|
Here some more complete logs:
$ cat mongod-INITSYNC-REPL.log | while read line; do echo "$line" | cut -c-200 ; done
|
{"t":{"$date":"2021-06-14T08:05:41.262+02:00"},"s":"I","c":"REPL","id":21311,"ctx":"initandlisten","msg":"Did not find local initialized voted for document at startup"}
|
{"t":{"$date":"2021-06-14T08:05:41.262+02:00"},"s":"I","c":"REPL","id":21312,"ctx":"initandlisten","msg":"Did not find local Rollback ID document at startup. Creating one"}
|
{"t":{"$date":"2021-06-14T08:05:41.266+02:00"},"s":"I","c":"REPL","id":21531,"ctx":"initandlisten","msg":"Initialized the rollback ID","attr":{"rbid":1}}
|
{"t":{"$date":"2021-06-14T08:05:41.266+02:00"},"s":"I","c":"REPL","id":21313,"ctx":"initandlisten","msg":"Did not find local replica set configuration document at startup","attr":{"error":{"code":47,"
|
{"t":{"$date":"2021-06-14T08:05:41.267+02:00"},"s":"I","c":"REPL","id":40440,"ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}
|
{"t":{"$date":"2021-06-14T08:05:41.267+02:00"},"s":"I","c":"REPL","id":40445,"ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}
|
{"t":{"$date":"2021-06-14T08:05:41.805+02:00"},"s":"I","c":"REPL","id":21400,"ctx":"conn14","msg":"Scheduling heartbeat to fetch a new config since we are not a member of our current config","attr":{"
|
{"t":{"$date":"2021-06-14T08:05:41.986+02:00"},"s":"I","c":"REPL","id":21392,"ctx":"ReplCoord-0","msg":"New replica set config in use","attr":{"config":{"_id":"shard_04","version":4,"term":3,"protocol
|
{"t":{"$date":"2021-06-14T08:05:41.986+02:00"},"s":"I","c":"REPL","id":21393,"ctx":"ReplCoord-0","msg":"Found self in config","attr":{"hostAndPort":"d-mipmdb-sh1-04.swi.srse.net:27018"}}
|
{"t":{"$date":"2021-06-14T08:05:41.986+02:00"},"s":"I","c":"REPL","id":21358,"ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"STARTUP2","oldState":"STARTUP"}}
|
{"t":{"$date":"2021-06-14T08:05:41.986+02:00"},"s":"I","c":"REPL","id":21306,"ctx":"ReplCoord-0","msg":"Starting replication storage threads"}
|
{"t":{"$date":"2021-06-14T08:05:41.987+02:00"},"s":"I","c":"REPL","id":21215,"ctx":"ReplCoord-3","msg":"Member is in new state","attr":{"hostAndPort":"d-mipmdb-sh2-04.swi.srse.net:27018","newState":"P
|
{"t":{"$date":"2021-06-14T08:05:41.995+02:00"},"s":"I","c":"INITSYNC","id":21164,"ctx":"ReplCoordExtern-0","msg":"Starting initial sync attempt","attr":{"initialSyncAttempt":1,"initialSyncMaxAttempts"
|
{"t":{"$date":"2021-06-14T08:05:42.000+02:00"},"s":"I","c":"REPL","id":21783,"ctx":"ReplCoordExtern-0","msg":"Waiting for pings from other members before syncing","attr":{"pingsNeeded":3}}
|
{"t":{"$date":"2021-06-14T08:05:42.060+02:00"},"s":"I","c":"REPL","id":21215,"ctx":"ReplCoord-2","msg":"Member is in new state","attr":{"hostAndPort":"d-mipmdb-arb-01.swi.srse.net:28004","newState":"A
|
{"t":{"$date":"2021-06-14T08:05:43.000+02:00"},"s":"I","c":"REPL","id":3873117,"ctx":"ReplCoordExtern-1","msg":"Choosing primary as sync source","attr":{"primary":"d-mipmdb-sh2-04.swi.srse.net:27018"}
|
{"t":{"$date":"2021-06-14T08:05:43.000+02:00"},"s":"I","c":"INITSYNC","id":21173,"ctx":"ReplCoordExtern-1","msg":"Initial syncer oplog truncation finished","attr":{"durationMillis":0}}
|
{"t":{"$date":"2021-06-14T08:05:43.000+02:00"},"s":"I","c":"REPL","id":21251,"ctx":"ReplCoordExtern-1","msg":"Creating replication oplog","attr":{"oplogSizeMB":51200}}
|
{"t":{"$date":"2021-06-14T08:05:43.052+02:00"},"s":"I","c":"REPL","id":21754,"ctx":"ReplCoordExtern-1","msg":"dropReplicatedDatabases - dropping databases","attr":{"numDatabases":1}}
|
{"t":{"$date":"2021-06-14T08:05:43.052+02:00"},"s":"I","c":"REPL","id":21756,"ctx":"ReplCoordExtern-1","msg":"dropReplicatedDatabases - dropped databases","attr":{"numDatabases":1}}
|
{"t":{"$date":"2021-06-14T08:05:43.303+02:00"},"s":"I","c":"REPL","id":4855903,"ctx":"ReplCoordExtern-1","msg":"Oplog fetcher retrying because FCV has changed"}
|
{"t":{"$date":"2021-06-14T11:54:23.518+02:00"},"s":"I","c":"INITSYNC","id":21183,"ctx":"ReplCoordExtern-0","msg":"Finished cloning data. Beginning oplog replay","attr":{"databaseClonerFinishStatus":"O
|
{"t":{"$date":"2021-06-14T11:54:23.615+02:00"},"s":"I","c":"INITSYNC","id":21195,"ctx":"ReplCoordExtern-3","msg":"Writing to the oplog and applying operations until stopTimestamp before initial sync c
|
{"t":{"$date":"2021-06-14T11:54:24.018+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-6","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:54:24.019+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-2","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:54:24.019+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-7","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:54:24.019+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-5","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:54:24.019+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-4","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:54:24.019+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-10","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIn
|
{"t":{"$date":"2021-06-14T11:54:24.020+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-3","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
// many more logs like this
|
{"t":{"$date":"2021-06-14T11:55:25.604+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-0","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.605+02:00"},"s":"I","c":"REPL","id":40447,"ctx":"TopologyVersionObserver","msg":"Stopped TopologyVersionObserver"}
|
{"t":{"$date":"2021-06-14T11:55:25.606+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-2","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.606+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-14","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIn
|
{"t":{"$date":"2021-06-14T11:55:25.610+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-4","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.611+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-8","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.612+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-5","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.613+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-15","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIn
|
{"t":{"$date":"2021-06-14T11:55:25.613+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-7","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.614+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-1","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.616+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-12","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIn
|
{"t":{"$date":"2021-06-14T11:55:25.616+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-2","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.617+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-14","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIn
|
{"t":{"$date":"2021-06-14T11:55:25.619+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-5","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.621+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-2","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.621+02:00"},"s":"E","c":"REPL","id":21204,"ctx":"ReplWriterWorker-6","msg":"Error applying inserts in bulk. Trying first insert as a lone insert","attr":{"groupedIns
|
{"t":{"$date":"2021-06-14T11:55:25.622+02:00"},"s":"I","c":"REPL","id":4784909,"ctx":"SignalHandler","msg":"Shutting down the ReplicationCoordinator"}
|
{"t":{"$date":"2021-06-14T11:55:25.622+02:00"},"s":"I","c":"REPL","id":21328,"ctx":"SignalHandler","msg":"Shutting down replication subsystems"}
|
{"t":{"$date":"2021-06-14T11:55:25.624+02:00"},"s":"E","c":"INITSYNC","id":21199,"ctx":"ReplCoordExtern-3","msg":"Failed to apply batch","attr":{"error":"CallbackCanceled: error applying batch: initia
|
{"t":{"$date":"2021-06-14T11:55:25.625+02:00"},"s":"I","c":"INITSYNC","id":21181,"ctx":"ReplCoordExtern-1","msg":"Finished fetching oplog during initial sync","attr":{"oplogFetcherFinishStatus":"Callb
|
{"t":{"$date":"2021-06-14T11:55:25.625+02:00"},"s":"I","c":"INITSYNC","id":21191,"ctx":"ReplCoordExtern-1","msg":"Initial sync attempt finishing up"}
|
{"t":{"$date":"2021-06-14T11:55:25.625+02:00"},"s":"I","c":"INITSYNC","id":21192,"ctx":"ReplCoordExtern-1","msg":"Initial Sync Attempt Statistics","attr":{"statistics":{"failedInitialSyncAttempts":0,"
|
{"t":{"$date":"2021-06-14T11:55:25.625+02:00"},"s":"E","c":"INITSYNC","id":21200,"ctx":"ReplCoordExtern-1","msg":"Initial sync attempt failed","attr":{"attemptsLeft":9,"error":"CallbackCanceled: error
|
{"t":{"$date":"2021-06-14T11:55:25.907+02:00"},"s":"I","c":"REPL","id":21324,"ctx":"ReplCoordExtern-1","msg":"Initial Sync has been cancelled","attr":{"error":{"code":90,"codeName":"CallbackCanceled",
|
{"t":{"$date":"2021-06-14T11:55:25.910+02:00"},"s":"I","c":"REPL","id":21307,"ctx":"SignalHandler","msg":"Stopping replication storage threads"}
|
{"t":{"$date":"2021-06-14T11:55:25.916+02:00"},"s":"I","c":"REPL","id":4784911,"ctx":"SignalHandler","msg":"Enqueuing the ReplicationStateTransitionLock for shutdown"}
|
{"t":{"$date":"2021-06-14T11:55:25.916+02:00"},"s":"I","c":"REPL","id":4784914,"ctx":"SignalHandler","msg":"Acquiring the ReplicationStateTransitionLock for shutdown"}
|
{"t":{"$date":"2021-06-14T11:55:25.916+02:00"},"s":"I","c":"REPL","id":4784916,"ctx":"SignalHandler","msg":"Reacquiring the ReplicationStateTransitionLock for shutdown"}
|
{"t":{"$date":"2021-06-14T11:55:25.916+02:00"},"s":"I","c":"REPL","id":4784917,"ctx":"SignalHandler","msg":"Attempting to mark clean shutdown"}
|
{"t":{"$date":"2021-06-14T11:55:25.919+02:00"},"s":"I","c":"REPL","id":4784920,"ctx":"SignalHandler","msg":"Shutting down the LogicalTimeValidator"}
|
|
It also confirms, this problem is reproducible.
[^mongod-INITSYNC-REPL.log]
|