[SERVER-47680] Properly quote BSON objects in logs so they can be parsed by standard json parsers Created: 21/Apr/20  Updated: 06/Dec/22  Resolved: 21/Apr/20

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

Type: Improvement Priority: Major - P3
Reporter: Judah Schvimer Assignee: Backlog - Server Tooling and Methods (STM) (Inactive)
Resolution: Won't Fix Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
Assigned Teams:
Server Tooling & Methods
Participants:

 Description   

Some BSON objects the server logs cannot be parsed by standard JSON parsers. This makes it so lobster cannot expand them, which makes debugging harder. Fixing this in lobster was deemed undesirable in EVG-7651. I'm not sure what the negative side affects are of this or the best way to accomplish this.

[js_test:sharded_last_stable_backup_restore_simple] 2020-03-25T16:10:21.870+0000 c20034| 2020-03-25T16:10:21.870+0000 I  INITSYNC [replication-1] Initial Sync Attempt Statistics: { failedInitialSyncAttempts: 0, maxFailedInitialSyncAttempts: 10, initialSyncStart: new Date(1585152621359), initialSyncAttempts: [], fetchedMissingDocs: 0, appliedOps: 0, initialSyncOplogStart: Timestamp(1585152621, 37), initialSyncOplogEnd: Timestamp(1585152621, 37), databases: { databasesCloned: 2, admin: { collections: 2, clonedCollections: 2, start: new Date(1585152621403), end: new Date(1585152621444), elapsedMillis: 41, admin.system.keys: { documentsToCopy: 2, documentsCopied: 2, indexes: 1, fetchedBatches: 1, start: new Date(1585152621404), end: new Date(1585152621432), elapsedMillis: 28, receivedBatches: 1 }, admin.system.version: { documentsToCopy: 1, documentsCopied: 1, indexes: 1, fetchedBatches: 1, start: new Date(1585152621432), end: new Date(1585152621444), elapsedMillis: 12, receivedBatches: 1 } }, config: { collections: 8, clonedCollections: 8, start: new Date(1585152621444), end: new Date(1585152621868), elapsedMillis: 424, config.shards: { documentsToCopy: 0, documentsCopied: 0, indexes: 2, fetchedBatches: 0, start: new Date(1585152621445), end: new Date(1585152621488), elapsedMillis: 43, receivedBatches: 0 }, config.lockpings: { documentsToCopy: 0, documentsCopied: 0, indexes: 2, fetchedBatches: 0, start: new Date(1585152621488), end: new Date(1585152621524), elapsedMillis: 36, receivedBatches: 0 }, config.chunks: { documentsToCopy: 0, documentsCopied: 0, indexes: 4, fetchedBatches: 0, start: new Date(1585152621524), end: new Date(1585152621631), elapsedMillis: 107, receivedBatches: 0 }, config.transactions: { documentsToCopy: 0, documentsCopied: 0, indexes: 1, fetchedBatches: 0, start: new Date(1585152621631), end: new Date(1585152621655), elapsedMillis: 24, receivedBatches: 0 }, config.tags: { documentsToCopy: 0, documentsCopied: 0, indexes: 3, fetchedBatches: 0, start: new Date(1585152621655), end: new Date(1585152621712), elapsedMillis: 57, receivedBatches: 0 }, config.migrations: { documentsToCopy: 0, documentsCopied: 0, indexes: 2, fetchedBatches: 0, start: new Date(1585152621712), end: new Date(1585152621759), elapsedMillis: 47, receivedBatches: 0 }, config.locks: { documentsToCopy: 0, documentsCopied: 0, indexes: 3, fetchedBatches: 0, start: new Date(1585152621759), end: new Date(1585152621844), elapsedMillis: 85, receivedBatches: 0 }, config.version: { documentsToCopy: 1, documentsCopied: 1, indexes: 1, fetchedBatches: 1, start: new Date(1585152621844), end: new Date(1585152621868), elapsedMillis: 24, receivedBatches: 1 } } } }



 Comments   
Comment by Judah Schvimer [ 21/Apr/20 ]

As max.hirschhorn pointed out, if an object goes in an "attr" field, then it uses strict JSON and the current lobster parser works. The above log line has since been converted to use LOGV2 properly and now looks like the following and parses fine:

[js_test:aggregation_write_concern] 2020-04-21T13:32:59.580+0000 d20521| 2020-04-21T13:32:59.580+00:00 I  INITSYNC 21192   [ReplCoordExtern-0] "Initial Sync Attempt Statistics","attr":{"statistics":{"failedInitialSyncAttempts":0,"maxFailedInitialSyncAttempts":10,"initialSyncStart":{"$date":"2020-04-21T13:32:59.402Z"},"initialSyncAttempts":[],"appliedOps":0,"initialSyncOplogStart":{"$timestamp":{"t":1587475979,"i":9}},"initialSyncOplogEnd":{"$timestamp":{"t":1587475979,"i":9}},"totalTimeUnreachableMillis":1,"databases":{"databasesCloned":2,"admin":{"collections":2,"clonedCollections":2,"start":{"$date":"2020-04-21T13:32:59.478Z"},"end":{"$date":"2020-04-21T13:32:59.529Z"},"elapsedMillis":51,"admin.system.version":{"documentsToCopy":1,"documentsCopied":1,"indexes":1,"fetchedBatches":1,"start":{"$date":"2020-04-21T13:32:59.478Z"},"end":{"$date":"2020-04-21T13:32:59.506Z"},"elapsedMillis":28,"receivedBatches":1},"admin.system.keys":{"documentsToCopy":2,"documentsCopied":2,"indexes":1,"fetchedBatches":1,"start":{"$date":"2020-04-21T13:32:59.506Z"},"end":{"$date":"2020-04-21T13:32:59.529Z"},"elapsedMillis":23,"receivedBatches":1}},"config":{"collections":2,"clonedCollections":2,"start":{"$date":"2020-04-21T13:32:59.529Z"},"end":{"$date":"2020-04-21T13:32:59.578Z"},"elapsedMillis":49,"config.system.indexBuilds":{"documentsToCopy":0,"documentsCopied":0,"indexes":1,"fetchedBatches":0,"start":{"$date":"2020-04-21T13:32:59.530Z"},"end":{"$date":"2020-04-21T13:32:59.554Z"},"elapsedMillis":24,"receivedBatches":0},"config.transactions":{"documentsToCopy":0,"documentsCopied":0,"indexes":1,"fetchedBatches":0,"start":{"$date":"2020-04-21T13:32:59.554Z"},"end":{"$date":"2020-04-21T13:32:59.578Z"},"elapsedMillis":24,"receivedBatches":0}}}}}

Closing Won't Fix.

Generated at Thu Feb 08 05:14:55 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.