[SERVER-32462] Write command document payloads are not logged Created: 26/Dec/17  Updated: 27/Oct/23  Resolved: 29/Jan/18

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: 3.6.0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jeffrey Yemin Assignee: Mathias Stearn
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

In 3.4, a write command is logged like this:

2017-12-26T17:04:38.161-0500 D COMMAND  [conn4] run command JavaDriverTest.$cmd { insert: "com.mongodb.operation.MixedBulkWriteOperationSpecification", ordered: true, documents: [ { _id: 1 } ] }
2017-12-26T17:04:38.165-0500 I COMMAND  [conn4] command JavaDriverTest.com.mongodb.operation.MixedBulkWriteOperationSpecification command: insert { insert: "com.mongodb.operation.MixedBulkWriteOperationSpecification", ordered: true, documents: [ { _id: 1 } ] } ninserted:1 keysInserted:1 numYields:0 reslen:44 locks:{ Global: { acquireCount: { r: 3, w: 3 } }, Database: { acquireCount: { w: 2, W: 1 } }, Collection: { acquireCount: { w: 2 } } } protocol:op_query 3ms

In 3.6 the same write command sent via OP_MSG (using message payloads) is logged like this:

2017-12-26T17:03:54.205-0500 D COMMAND  [conn187] run command JavaDriverTest.$cmd { insert: "com.mongodb.operation.MixedBulkWriteOperationSpecification", ordered: true, $db: "JavaDriverTest", lsid: { id: UUID("a6d0bb55-ed4f-4643-8f21-75eb1ae00c91") } }
2017-12-26T17:03:54.206-0500 I COMMAND  [conn187] command JavaDriverTest.com.mongodb.operation.MixedBulkWriteOperationSpecification command: insert { insert: "com.mongodb.operation.MixedBulkWriteOperationSpecification", ordered: true, $db: "JavaDriverTest", lsid: { id: UUID("a6d0bb55-ed4f-4643-8f21-75eb1ae00c91") } } ninserted:1 keysInserted:1 numYields:0 reslen:29 locks:{ Global: { acquireCount: { r: 5, w: 3 } }, Database: { acquireCount: { r: 1, w: 2, W: 1 } }, Collection: { acquireCount: { r: 1, w: 2 } } } protocol:op_msg 1ms

Since the OP_MSG payload is not logged, the document sequence is not included in the log message.

This may be considered a regression from the perspective of some log analysis tools (human or otherwise).



 Comments   
Comment by Mathias Stearn [ 29/Jan/18 ]

jeff.yemin As discussed we made this change since we decided it wasn't worth the development effort and runtime overhead to maintain that log line. Since it sounded like it wasn't difficult to work around this, I'm going to close as WAD. If this becomes an issue later, feel free to reopen or file a new ticket.

Comment by Ian Whalen (Inactive) [ 12/Jan/18 ]

Hey Platforms, think we need Mathias' input to help triage. Once we've got that info we're OK if you leave it on your backlog or bounce it back to Query.

Comment by Ian Whalen (Inactive) [ 05/Jan/18 ]

redbeard0531 do you remember what the motivation was for this change?

Generated at Thu Feb 08 04:30:19 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.