[SERVER-27062] NetworkInterfaceASIO logging breaks our standard format Created: 16/Nov/16  Updated: 08/Jan/24  Resolved: 09/Oct/19

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

Type: Task Priority: Major - P3
Reporter: Samantha Ritter (Inactive) Assignee: Mira Carey
Resolution: Done Votes: 1
Labels: platforms-re-triaged
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Participants:

 Description   

NetworkInterfaceASIO::getDiagnosticString() returns a string that includes newlines, tabs, and other formatting decisions that go against our typical log structure. This makes it harder to automate parsing of mongodb logs.

2016-10-25T13:22:44.292+0000 W NETWORK  [ReplicaSetMonitor-TaskExecutor-0] Failed to connect to 10.120.3.49:27017, reason: Connection refused
2016-10-25T13:22:47.766+0000 I REPL     [replication-1] Restarting oplog query due to error: ExceededTimeLimit: Operation timed out, request was RemoteCommand 11504 -- target:logkeeperdb-31.10gen-mci.4085.mongodbdns.com:27017 db:local expDate:2016-10-25T13:22:47.765+0000 cmd:{ getMore: 19683593992, collection: "oplog.rs", maxTimeMS: 5000, term: 18, lastKnownCommittedOpTime: { ts: Timestamp 1477401742000|86, t: 18 } }. Last fetched optime (with hash): { ts: Timestamp 1477401733000|284, t: 18 }[-8518944276581541617]. Restarts remaining: 3
2016-10-25T13:22:47.766+0000 I ASIO     [NetworkInterfaceASIO-RS-0] Connecting to logkeeperdb-31.10gen-mci.4085.mongodbdns.com:27017
2016-10-25T13:22:47.766+0000 I REPL     [replication-1] Scheduled new oplog query Fetcher executor: { pool: { inProgressCount: 1 }, queues: { networkInProgress: 2, sleepers: 0 }, unsignaledEvents: 1, shuttingDown: false, networkInterface: "
NetworkInterfaceASIO Operations' Diagnostic:
Operation:    Count:   
Connecting    1        
In Progress   1        
Succeeded     5493     
Canceled..." } source: logkeeperdb-31.10gen-mci.4085.mongodbdns.com:27017 database: local query: { find: "oplog.rs", filter: { ts: { $gte: Timestamp 1477401733000|284 } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000, term: 18 } query metadata: { $replData: 1, $ssm: { $secondaryOk: true } } active: 1 timeout: 10000ms inShutdown: 0 first: 1 firstCommandScheduler: RemoteCommandRetryScheduler request: RemoteCommand 11530 -- target:logkeeperdb-31.10gen-mci.4085.mongodbdns.com:27017 db:local cmd:{ find: "oplog.rs", filter: { ts: { $gte: Timestamp 1477401733000|284 } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000, term: 18 } active: 1 callbackHandle.valid: 1 callbackHandle.cancelled: 0 attempt: 1 retryPolicy: RetryPolicyImpl maxAttempts: 1 maxTimeMillis: -1ms



 Comments   
Comment by Mira Carey [ 09/Oct/19 ]

This log line is no longer present in the code base

Comment by Ratika Gandhi [ 15/Jul/19 ]

Assigning to mira.carey@mongodb.com to investigate if it is still an issue.

Comment by Samantha Ritter (Inactive) [ 16/Nov/16 ]

The fetcher should be able to use NIA's logging string if it's useful information to have. Maybe we can add it back once we fix the formatting.

Comment by Eric Milkie [ 16/Nov/16 ]

Oh I see, that log snippit is from Oct 25.

Comment by Eric Milkie [ 16/Nov/16 ]

I thought we recently took out that diagnostic string from the fetcher log entries – for exactly this reason.

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