PSMDB-1482 add the test with unshardCollection #209
GitHub Actions / JUnit Test Report
failed
Nov 8, 2024 in 0s
21 tests run, 17 passed, 3 skipped, 1 failed.
Annotations
Check failure on line 79 in pbm-functional/pytest/test_PBM-1211.py
github-actions / JUnit Test Report
test_PBM-1211.test_pitr_PBM_T268[physical]
AssertionError: Starting restore 2024-11-08T14:04:41.732109464Z to point-in-time 2024-11-08T14:03:28 from '2024-11-08T13:59:49Z'..........................Started physical restore.
Waiting to finish..............Error: operation failed with: replay pitr oplog: reply oplog: replay chunk 1731074391.1731074455: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1731074425,"I":16},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"test.test","Object":[{"Key":"_id","Value":"672e19791d4e17153b9d7f15"},{"Key":"doc","Value":0}],"Query":null,"UI":{"Subtype":4,"Data":"WREJ02EhQTmu7uYeB77Oxw=="},"LSID":"SAAAAAVpZAAQAAAABMkDZwqkH0PIhBsuJFgDLqYFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA","TxnNumber":1,"PrevOpTime":"HAAAABF0cwAAAAAAAAAAABJ0AP//////////AA==","MultiOpType":null} | merr <nil>: applyOps: (NotWritablePrimary) not primary
{"t":{"$date":"2024-11-08T14:05:20.534+00:00"},"s":"I", "c":"CONTROL", "id":23285, "ctx":"-","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2024-11-08T14:05:20.534+00:00"},"s":"I", "c":"NETWORK", "id":4915701, "ctx":"-","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}
{"t":{"$date":"2024-11-08T14:05:20.534+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2024-11-08T14:05:20.534+00:00"},"s":"I", "c":"NETWORK", "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
{"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}
{"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}
{"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":5945603, "ctx":"main","msg":"Multi threading initialized"}
{"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":510,"port":27407,"dbPath":"/var/lib/mongo","architecture":"64-bit","host":"rs101"}}
{"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":23403, "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.29-25","gitVersion":"6ed5ea3065f1daafa7661d1c05d20c50b614a96a","openSSLVersion":"OpenSSL 1.1.1k FIPS 25 Mar 2021","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":51765, "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Oracle Linux Server release 8.10","version":"Kernel 6.5.0-1025-azure"}}}
{"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":21951, "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/tmp/pbmMongdTmpConf630898707","net":{"bindIp":"localhost","port":27407},"replication":{"replSet":"rs1"},"setParameter":{"disableLogicalSessionCacheRefresh":"true","takeUnstableCheckpointOnShutdown":"true"},"storage":{"dbPath":"/var/lib/mongo","directoryPerDB":false,"wiredTiger":{"collectionConfig":{"blockCompressor":"snappy"},"engineConfig":{"directoryForIndexes":false,"journalCompressor":"snappy"},"indexConfig":{"prefixCompression":true}}},"systemLog":{"destination":"file","path":"/var/lib/mongo/pbm.restore.log"}}}}
{"t":{"$date":"2024-11-08T14:05:20.536+00:00"},"s":"I", "c":"STORAGE", "id":22270, "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongo","storageEngine":"wiredTiger"}}
{"t":{"$date":"2024-11-08T14:05:20.536+00:00"},"s":"I", "c":"STORAGE", "id":22315, "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7478M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),builtin_extension_config=(zstd=(compression_level=6)),file_manager=(close_idle_time=600,close_scan_interval=10,close_handle_minimum=2000),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
{"t":{"$date":"2024-11-08T14:05:20.736+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:736592][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 5 through 6"}}
{"t":{"$date":"2024-11-08T14:05:20.761+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:761553][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 6 through 6"}}
{"t":{"$date":"2024-11-08T14:05:20.820+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:820585][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_ALL] Main recovery loop: starting at 5/47232 to 6/256"}}
{"t":{"$date":"2024-11-08T14:05:20.867+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:867528][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 5 through 6"}}
{"t":{"$date":"2024-11-08T14:05:20.902+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:902413][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 6 through 6"}}
{"t":{"$date":"2024-11-08T14:05:20.925+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:925207][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery log replay has successfully finished and ran for 188 milliseconds"}}
{"t":{"$date":"2024-11-08T14:05:20.925+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:925243][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (0, 0)"}}
{"t":{"$date":"2024-11-08T14:05:20.925+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:925254][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (0, 0)"}}
{"t":{"$date":"2024-11-08T14:05:20.926+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:926093][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery rollback to stable has successfully finished and ran for 0 milliseconds"}}
{"t":{"$date":"2024-11-08T14:05:20.927+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:927675][510:0x7fc914af1c00], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 1, snapshot max: 1 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 42"}}
{"t":{"$date":"2024-11-08T14:05:20.929+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:929886][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery checkpoint has successfully finished and ran for 3 milliseconds"}}
{"t":{"$date":"2024-11-08T14:05:20.929+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:929922][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery was completed successfully and took 193ms, including 188ms for the log replay, 0ms for the rollback to stable, and 3ms for the checkpoint."}}
{"t":{"$date":"2024-11-08T14:05:20.930+00:00"},"s":"I", "c":"STORAGE", "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":394}}
{"t":{"$date":"2024-11-08T14:05:20.930+00:00"},"s":"I", "c":"RECOVERY", "id":23987, "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}
{"t":{"$date":"2024-11-08T14:05:20.939+00:00"},"s":"I", "c":"STORAGE", "id":22383, "ctx":"initandlisten","msg":"The size storer reports that the oplog contains","attr":{"numRecords":47,"dataSize":13138}}
{"t":{"$date":"2024-11-08T14:05:20.939+00:00"},"s":"I", "c":"STORAGE", "id":22384, "ctx":"initandlisten","msg":"Scanning the oplog to determine where to place markers for truncation"}
{"t":{"$date":"2024-11-08T14:05:20.940+00:00"},"s":"I", "c":"STORAGE", "id":22382, "ctx":"initandlisten","msg":"WiredTiger record store oplog processing finished","attr":{"durationMillis":0}}
{"t":{"$date":"2024-11-08T14:05:20.952+00:00"},"s":"I", "c":"STORAGE", "id":22262, "ctx":"initandlisten","msg":"Timestamp monitor starting"}
{"t":{"$date":"2024-11-08T14:05:20.953+00:00"},"s":"W", "c":"CONTROL", "id":22120, "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted. You can use percona-server-mongodb-enable-auth.sh to fix it","tags":["startupWarnings"]}
{"t":{"$date":"2024-11-08T14:05:20.953+00:00"},"s":"W", "c":"CONTROL", "id":22178, "ctx":"initandlisten","msg":"/sys/kernel/mm/transparent_hugepage/enabled is 'always'. We suggest setting it to 'never' in this binary version","tags":["startupWarnings"]}
{"t":{"$date":"2024-11-08T14:05:20.960+00:00"},"s":"I", "c":"NETWORK", "id":4915702, "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":13,"maxWireVersion":13},"outgoing":{"minWireVersion":13,"maxWireVersion":13},"isInternalClient":true}}}
{"t":{"$date":"2024-11-08T14:05:20.960+00:00"},"s":"I", "c":"STORAGE", "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}
{"t":{"$date":"2024-11-08T14:05:20.978+00:00"},"s":"I", "c":"CONTROL", "id":20536, "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}
{"t":{"$date":"2024-11-08T14:05:20.979+00:00"},"s":"W", "c":"SHARDING", "id":22075, "ctx":"initandlisten","msg":"Not started with --shardsvr, but a shardIdentity document was found on disk","attr":{"namespace":"admin.system.version","shardIdentityDocument":{"_id":"shardIdentity","shardName":"rs1","clusterId":{"$oid":"672e1942fb7cde5b9f386568"},"configsvrConnectionString":"rscfg/rscfg01:27017"}}}
{"t":{"$date":"2024-11-08T14:05:20.979+00:00"},"s":"I", "c":"FTDC", "id":20625, "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/var/lib/mongo/diagnostic.data"}}
{"t":{"$date":"2024-11-08T14:05:20.981+00:00"},"s":"I", "c":"-", "id":4939300, "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"ReadConcernMajorityNotAvailableYet: Read concern majority reads are currently not possible.","nextWakeupMillis":200}}
{"t":{"$date":"2024-11-08T14:05:20.981+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigStartingUp","oldState":"ConfigPreStart"}}
{"t":{"$date":"2024-11-08T14:05:20.981+00:00"},"s":"I", "c":"REPL", "id":4280500, "ctx":"initandlisten","msg":"Attempting to create internal replication collections"}
{"t":{"$date":"2024-11-08T14:05:20.984+00:00"},"s":"I", "c":"REPL", "id":4280501, "ctx":"initandlisten","msg":"Attempting to load local voted for document"}
{"t":{"$date":"2024-11-08T14:05:20.984+00:00"},"s":"I", "c":"REPL", "id":21311, "ctx":"initandlisten","msg":"Did not find local initialized voted for document at startup"}
{"t":{"$date":"2024-11-08T14:05:20.984+00:00"},"s":"I", "c":"REPL", "id":4280502, "ctx":"initandlisten","msg":"Searching for local Rollback ID document"}
{"t":{"$date":"2024-11-08T14:05:20.985+00:00"},"s":"I", "c":"REPL", "id":21529, "ctx":"initandlisten","msg":"Initializing rollback ID","attr":{"rbid":1}}
{"t":{"$date":"2024-11-08T14:05:20.985+00:00"},"s":"I", "c":"REPL", "id":4280504, "ctx":"initandlisten","msg":"Cleaning up any partially applied oplog batches & reading last op from oplog"}
{"t":{"$date":"2024-11-08T14:05:20.985+00:00"},"s":"I", "c":"REPL", "id":21546, "ctx":"initandlisten","msg":"Recovering from an unstable checkpoint","attr":{"topOfOplog":{"ts":{"$timestamp":{"t":1731074389,"i":44}},"t":1},"appliedThrough":{"ts":{"$timestamp":{"t":1731074389,"i":44}},"t":1}}}
{"t":{"$date":"2024-11-08T14:05:20.986+00:00"},"s":"I", "c":"REPL", "id":21548, "ctx":"initandlisten","msg":"Starting recovery oplog application at the appliedThrough through the top of the oplog","attr":{"appliedThrough":{"ts":{"$timestamp":{"t":1731074389,"i":44}},"t":1},"topOfOplog":{"ts":{"$timestamp":{"t":1731074389,"i":44}},"t":1}}}
{"t":{"$date":"2024-11-08T14:05:20.986+00:00"},"s":"I", "c":"REPL", "id":21549, "ctx":"initandlisten","msg":"No oplog entries to apply for recovery. Start point is at the top of the oplog"}
{"t":{"$date":"2024-11-08T14:05:20.987+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:987663][510:0x7fc914af1c00], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 37, snapshot max: 37 snapshot count: 0, oldest timestamp: (1731074389, 44) , meta checkpoint timestamp: (0, 0) base write gen: 42"}}
{"t":{"$date":"2024-11-08T14:05:20.991+00:00"},"s":"I", "c":"REPL", "id":4280505, "ctx":"initandlisten","msg":"Creating any necessary TenantMigrationAccessBlockers for unfinished migrations"}
{"t":{"$date":"2024-11-08T14:05:20.991+00:00"},"s":"I", "c":"REPL", "id":4280506, "ctx":"initandlisten","msg":"Reconstructing prepared transactions"}
{"t":{"$date":"2024-11-08T14:05:20.992+00:00"},"s":"I", "c":"REPL", "id":4280507, "ctx":"initandlisten","msg":"Loaded replica set config, scheduled callback to set local config"}
{"t":{"$date":"2024-11-08T14:05:20.992+00:00"},"s":"I", "c":"REPL", "id":4280508, "ctx":"ReplCoord-0","msg":"Attempting to set local replica set config; validating config for startup"}
{"t":{"$date":"2024-11-08T14:05:20.992+00:00"},"s":"I", "c":"REPL", "id":40440, "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}
{"t":{"$date":"2024-11-08T14:05:20.993+00:00"},"s":"I", "c":"REPL", "id":40445, "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}
{"t":{"$date":"2024-11-08T14:05:20.993+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-27407.sock"}}
{"t":{"$date":"2024-11-08T14:05:20.993+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}
{"t":{"$date":"2024-11-08T14:05:20.993+00:00"},"s":"I", "c":"NETWORK", "id":23016, "ctx":"listener","msg":"Waiting for connections","attr":{"port":27407,"ssl":"off"}}
{"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44604","uuid":"c534b521-b10f-4af2-aa29-d07ab0485af2","connectionId":1,"connectionCount":1}}
{"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44610","uuid":"29fb6d75-c6a9-4c22-8a3a-505aa1ccfbd2","connectionId":3,"connectionCount":2}}
{"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn1","msg":"client metadata","attr":{"remote":"127.0.0.1:44604","client":"conn1","negotiatedCompressors":[],"doc":{"application":{"name":"pbm-physical-restore"},"driver":{"name":"mongo-go-driver","version":"1.16.0"},"os":{"type":"linux","architecture":"amd64"},"platform":"go1.23.3","env":{"container":{"runtime":"docker"}}}}}
{"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"W", "c":"COMMAND", "id":5578800, "ctx":"conn3","msg":"Deprecated operation requested. The client driver may require an upgrade in order to ensure compatibility with future server versions. For more details see https://dochub.mongodb.org/core/legacy-opcode-compatibility","attr":{"op":"query","clientInfo":{"address":"127.0.0.1:44610"}}}
{"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"REPL", "id":4280509, "ctx":"ReplCoord-0","msg":"Local configuration validated for startup"}
{"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"ReplCoord-0","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigStartingUp"}}
{"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44620","uuid":"021d5572-bb8b-437a-ac4f-5ca867ca73b6","connectionId":4,"connectionCount":3}}
{"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21392, "ctx":"ReplCoord-0","msg":"New replica set config in use","attr":{"config":{"_id":"rs1","version":1,"members":[{"_id":0,"host":"localhost:27407","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1,"tags":{},"secondaryDelaySecs":0,"votes":1}],"protocolVersion":1,"writeConcernMajorityJournalDefault":true,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":10000,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0}}}}}
{"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21393, "ctx":"ReplCoord-0","msg":"Found self in config","attr":{"hostAndPort":"localhost:27407"}}
{"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"STARTUP2","oldState":"STARTUP"}}
{"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn3","msg":"Connection ended","attr":{"remote":"127.0.0.1:44610","uuid":"29fb6d75-c6a9-4c22-8a3a-505aa1ccfbd2","connectionId":3,"connectionCount":2}}
{"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21320, "ctx":"ReplCoord-0","msg":"Updated term","attr":{"term":1}}
{"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21306, "ctx":"ReplCoord-0","msg":"Starting replication storage threads"}
{"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44636","uuid":"03ee4e9d-91db-4e89-b167-e28271854d79","connectionId":5,"connectionCount":3}}
{"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn5","msg":"client metadata","attr":{"remote":"127.0.0.1:44636","client":"conn5","negotiatedCompressors":[],"doc":{"application":{"name":"pbm-physical-restore"},"driver":{"name":"mongo-go-driver","version":"1.16.0"},"os":{"type":"linux","architecture":"amd64"},"platform":"go1.23.3","env":{"container":{"runtime":"docker"}}}}}
{"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn4","msg":"client metadata","attr":{"remote":"127.0.0.1:44620","client":"conn4","negotiatedCompressors":[],"doc":{"application":{"name":"pbm-physical-restore"},"driver":{"name":"mongo-go-driver","version":"1.16.0"},"os":{"type":"linux","architecture":"amd64"},"platform":"go1.23.3","env":{"container":{"runtime":"docker"}}}}}
{"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"REPL", "id":4280512, "ctx":"ReplCoord-0","msg":"No initial sync required. Attempting to begin steady replication"}
{"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"RECOVERING","oldState":"STARTUP2"}}
{"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"ReplCoord-0","msg":"createCollection","attr":{"namespace":"local.replset.initialSyncId","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"287444f4-8af8-404f-a606-826b191f7a4e"}},"options":{}}}
{"t":{"$date":"2024-11-08T14:05:21.031+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"ReplCoord-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.replset.initialSyncId","index":"_id_","commitTimestamp":null}}
{"t":{"$date":"2024-11-08T14:05:21.031+00:00"},"s":"I", "c":"REPL", "id":21299, "ctx":"ReplCoord-0","msg":"Starting replication fetcher thread"}
{"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":21300, "ctx":"ReplCoord-0","msg":"Starting replication applier thread"}
{"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":21301, "ctx":"ReplCoord-0","msg":"Starting replication reporter thread"}
{"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":4280511, "ctx":"ReplCoord-0","msg":"Set local replica set config"}
{"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":21224, "ctx":"OplogApplier-0","msg":"Starting oplog application"}
{"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"OplogApplier-0","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"RECOVERING"}}
{"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"ELECTION", "id":4615652, "ctx":"OplogApplier-0","msg":"Starting an election, since we've seen no PRIMARY in election timeout period","attr":{"electionTimeoutPeriodMillis":10000}}
{"t":{"$date":"2024-11-08T14:05:21.033+00:00"},"s":"I", "c":"ELECTION", "id":21438, "ctx":"OplogApplier-0","msg":"Conducting a dry run election to see if we could be elected","attr":{"currentTerm":1}}
{"t":{"$date":"2024-11-08T14:05:21.033+00:00"},"s":"I", "c":"ELECTION", "id":21444, "ctx":"ReplCoord-0","msg":"Dry election run succeeded, running for election","attr":{"newTerm":2}}
{"t":{"$date":"2024-11-08T14:05:21.033+00:00"},"s":"I", "c":"ELECTION", "id":6015300, "ctx":"ReplCoord-0","msg":"Storing last vote document in local storage for my election","attr":{"lastVote":{"term":2,"candidateIndex":0}}}
{"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"ELECTION", "id":21450, "ctx":"ReplCoord-0","msg":"Election succeeded, assuming primary role","attr":{"term":2}}
{"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}}
{"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21106, "ctx":"ReplCoord-0","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}}
{"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21359, "ctx":"ReplCoord-0","msg":"Entering primary catch-up mode"}
{"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":6015304, "ctx":"ReplCoord-0","msg":"Skipping primary catchup since we are the only node in the replica set."}
{"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21363, "ctx":"ReplCoord-0","msg":"Exited primary catch-up mode"}
{"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21107, "ctx":"ReplCoord-0","msg":"Stopping replication producer"}
{"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21239, "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":2}}
{"t":{"$date":"2024-11-08T14:05:21.035+00:00"},"s":"I", "c":"REPL", "id":21343, "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}
{"t":{"$date":"2024-11-08T14:05:21.035+00:00"},"s":"I", "c":"REPL", "id":21344, "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"}
{"t":{"$date":"2024-11-08T14:05:21.035+00:00"},"s":"I", "c":"REPL", "id":21340, "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepUp","userOpsKilled":0,"userOpsRunning":1}}}
{"t":{"$date":"2024-11-08T14:05:21.035+00:00"},"s":"I", "c":"REPL", "id":6015310, "ctx":"OplogApplier-0","msg":"Starting to transition to primary."}
{"t":{"$date":"2024-11-08T14:05:21.036+00:00"},"s":"I", "c":"REPL", "id":6015309, "ctx":"OplogApplier-0","msg":"Logging transition to primary to oplog on stepup"}
{"t":{"$date":"2024-11-08T14:05:21.036+00:00"},"s":"I", "c":"STORAGE", "id":20657, "ctx":"OplogApplier-0","msg":"IndexBuildsCoordinator::onStepUp - this node is stepping up to primary"}
{"t":{"$date":"2024-11-08T14:05:21.036+00:00"},"s":"I", "c":"REPL", "id":21331, "ctx":"OplogApplier-0","msg":"Transition to primary complete; database writes are now permitted"}
{"t":{"$date":"2024-11-08T14:05:21.037+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"monitoring-keys-for-HMAC","msg":"createCollection","attr":{"namespace":"admin.system.keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"3c469c6a-6e28-469c-8292-8a2441ad2def"}},"options":{}}}
{"t":{"$date":"2024-11-08T14:05:21.039+00:00"},"s":"I", "c":"STORAGE", "id":22310, "ctx":"JournalFlusher","msg":"Triggering the first stable checkpoint","attr":{"initialDataTimestamp":{"$timestamp":{"t":1731074389,"i":44}},"prevStableTimestamp":{"$timestamp":{"t":0,"i":0}},"currStableTimestamp":{"$timestamp":{"t":1731074721,"i":2}}}}
{"t":{"$date":"2024-11-08T14:05:21.040+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationDonors","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"c61daba4-6fa8-459f-bb5c-e7c47b9f3b43"}},"options":{}}}
{"t":{"$date":"2024-11-08T14:05:21.040+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationRecipientService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationRecipients","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"2fc4736d-c484-434d-ab38-eb76367dd5ac"}},"options":{}}}
{"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"Checkpointer","msg":"WiredTiger error","attr":{"error":2,"message":"[1731074721:41541][510:0x7fc8fc9fc700], file:collection-2-4794091703575719002.wt, WT_SESSION.checkpoint: __posix_fs_size, 296: /var/lib/mongo/WiredTigerHS.wt: file-size: stat: No such file or directory"}}
{"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"Checkpointer","msg":"WiredTiger error","attr":{"error":2,"message":"[1731074721:41591][510:0x7fc8fc9fc700], file:collection-2-4794091703575719002.wt, WT_SESSION.checkpoint: __reconcile, 351: reconciliation failed after building the disk image: No such file or directory"}}
{"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"Checkpointer","msg":"WiredTiger error","attr":{"error":-31804,"message":"[1731074721:41651][510:0x7fc8fc9fc700], file:collection-2-4794091703575719002.wt, WT_SESSION.checkpoint: __reconcile, 351: the process must exit and restart: WT_PANIC: WiredTiger library panic"}}
{"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"F", "c":"-", "id":23089, "ctx":"Checkpointer","msg":"Fatal assertion","attr":{"msgid":50853,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp","line":574}}
{"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"F", "c":"-", "id":23090, "ctx":"Checkpointer","msg":"\n\n***aborting after fassert() failure\n\n"}
{"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"F", "c":"CONTROL", "id":6384300, "ctx":"Checkpointer","msg":"Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}}
{"t":{"$date":"2024-11-08T14:05:21.049+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn4","msg":"Connection ended","attr":{"remote":"127.0.0.1:44620","uuid":"021d5572-bb8b-437a-ac4f-5ca867ca73b6","connectionId":4,"connectionCount":2}}
{"t":{"$date":"2024-11-08T14:05:21.049+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn5","msg":"Connection ended","attr":{"remote":"127.0.0.1:44636","uuid":"03ee4e9d-91db-4e89-b167-e28271854d79","connectionId":5,"connectionCount":1}}
{"t":{"$date":"2024-11-08T14:05:21.050+00:00"},"s":"I", "c":"-", "id":20883, "ctx":"conn1","msg":"Interrupted operation as its client disconnected","attr":{"opId":45}}
{"t":{"$date":"2024-11-08T14:05:21.050+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn1","msg":"Connection ended","attr":{"remote":"127.0.0.1:44604","uuid":"c534b521-b10f-4af2-aa29-d07ab0485af2","connectionId":1,"connectionCount":0}}
{"t":{"$date":"2024-11-08T14:05:21.054+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"_id_","commitTimestamp":{"$timestamp":{"t":1731074721,"i":6}}}}
{"t":{"$date":"2024-11-08T14:05:21.054+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"TenantMigrationRecipientTTLIndex","commitTimestamp":{"$timestamp":{"t":1731074721,"i":6}}}}
{"t":{"$date":"2024-11-08T14:05:21.054+00:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationRecipientService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationRecipientService"}}
{"t":{"$date":"2024-11-08T14:05:21.059+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"monitoring-keys-for-HMAC","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"admin.system.keys","index":"_id_","commitTimestamp":{"$timestamp":{"t":1731074721,"i":3}}}}
{"t":{"$date":"2024-11-08T14:05:21.065+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"_id_","commitTimestamp":{"$timestamp":{"t":1731074721,"i":8}}}}
{"t":{"$date":"2024-11-08T14:05:21.065+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"TenantMigrationDonorTTLIndex","commitTimestamp":{"$timestamp":{"t":1731074721,"i":8}}}}
{"t":{"$date":"2024-11-08T14:05:21.065+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.external_validation_keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"7bed0cc6-3081-4174-8db2-4027f7517813"}},"options":{}}}
{"t":{"$date":"2024-11-08T14:05:21.073+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"_id_","commitTimestamp":{"$timestamp":{"t":1731074721,"i":11}}}}
{"t":{"$date":"2024-11-08T14:05:21.073+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"ExternalKeysTTLIndex","commitTimestamp":{"$timestamp":{"t":1731074721,"i":11}}}}
{"t":{"$date":"2024-11-08T14:05:21.073+00:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationDonorService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationDonorService"}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31380, "ctx":"Checkpointer","msg":"BACKTRACE","attr":{"bt":{"backtrace":[{"a":"560D5EAB69C3","b":"560D5A899000","o":"421D9C3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"},{"a":"560D5EAB9417","b":"560D5A899000","o":"4220417","s":"_ZN5mongo15printStackTraceEv","s+":"37"},{"a":"560D5EAB15B6","b":"560D5A899000","o":"42185B6","s":"abruptQuit","s+":"66"},{"a":"7FC91226FD80","b":"7FC91225D000","o":"12D80","s":"funlockfile","s+":"50"},{"a":"7FC911ED55EF","b":"7FC911E87000","o":"4E5EF","s":"gsignal","s+":"10F"},{"a":"7FC911EA8E65","b":"7FC911E87000","o":"21E65","s":"abort","s+":"127"},{"a":"560D5BE17D6D","b":"560D5A899000","o":"157ED6D","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"},{"a":"560D5B8D3CF4","b":"560D5A899000","o":"103ACF4","s":"_ZZN5mongo8RecordIdC4EPKciENKUlvE0_clEv","s+":"30B8"},{"a":"560D5C17C9F3","b":"560D5A899000","o":"18E39F3","s":"__wt_event_handler_set","s+":"4A3"},{"a":"560D5B8E63E3","b":"560D5A899000","o":"104D3E3","s":"__wt_panic_func","s+":"114"},{"a":"560D5B8E2A8D","b":"560D5A899000","o":"1049A8D","s":"__wt_ext_map_windows_error","s+":"25CA"},{"a":"560D5C211DFA","b":"560D5A899000","o":"1978DFA","s":"__wt_sync_file","s+":"6AA"},{"a":"560D5C19B13B","b":"560D5A899000","o":"190213B","s":"__wt_checkpoint_tree_reconcile_update","s+":"1CB"},{"a":"560D5C19C23F","b":"560D5A899000","o":"190323F","s":"__wt_checkpoint_sync","s+":"99F"},{"a":"560D5C19DB76","b":"560D5A899000","o":"1904B76","s":"__wt_txn_checkpoint","s+":"246"},{"a":"560D5B8E56EF","b":"560D5A899000","o":"104C6EF","s":"__wt_session_notsup","s+":"FCC"},{"a":"560D5C082586","b":"560D5A899000","o":"17E9586","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_sessionb","s+":"46"},{"a":"560D5C08F988","b":"560D5A899000","o":"17F6988","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_session","s+":"2B8"},{"a":"560D5C090050","b":"560D5A899000","o":"17F7050","s":"_ZN5mongo18WiredTigerKVEngine10checkpointEv","s+":"40"},{"a":"560D5D035459","b":"560D5A899000","o":"279C459","s":"_ZN5mongo12Checkpointer3runEv","s+":"E59"},{"a":"560D5E871E32","b":"560D5A899000","o":"3FD8E32","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"E2"},{"a":"560D5E87254C","b":"560D5A899000","o":"3FD954C","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"7FC"},{"a":"7FC912ADAB23","b":"7FC912A18000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"},{"a":"7FC9122651DA","b":"7FC91225D000","o":"81DA","s":"start_thread","s+":"EA"},{"a":"7FC911EC08D3","b":"7FC911E87000","o":"398D3","s":"clone","s+":"43"}],"processInfo":{"mongodbVersion":"5.0.29-25","gitVersion":"6ed5ea3065f1daafa7661d1c05d20c50b614a96a","compiledModules":[],"uname":{"sysname":"Linux","release":"6.5.0-1025-azure","version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","machine":"x86_64"},"somap":[{"b":"560D5A899000","elfType":3,"buildId":"539E2C825673723B04D19874D3C9DF6EB9A69E4F"},{"b":"7FC912A18000","path":"/lib64/libstdc++.so.6","elfType":3,"buildId":"41809D0B18272BC525772714DA54108BF1C59253"},{"b":"7FC91225D000","path":"/lib64/libpthread.so.0","elfType":3,"buildId":"0B813C2AD185DCA27DDB58BA42ACC172679B1526"},{"b":"7FC911E87000","path":"/lib64/libc.so.6","elfType":3,"buildId":"BF4C06A1D77241A2D30436873E56C348FCBB5D22"}]}}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5EAB69C3","b":"560D5A899000","o":"421D9C3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5EAB9417","b":"560D5A899000","o":"4220417","s":"_ZN5mongo15printStackTraceEv","s+":"37"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5EAB15B6","b":"560D5A899000","o":"42185B6","s":"abruptQuit","s+":"66"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC91226FD80","b":"7FC91225D000","o":"12D80","s":"funlockfile","s+":"50"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC911ED55EF","b":"7FC911E87000","o":"4E5EF","s":"gsignal","s+":"10F"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC911EA8E65","b":"7FC911E87000","o":"21E65","s":"abort","s+":"127"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5BE17D6D","b":"560D5A899000","o":"157ED6D","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5B8D3CF4","b":"560D5A899000","o":"103ACF4","s":"_ZZN5mongo8RecordIdC4EPKciENKUlvE0_clEv","s+":"30B8"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C17C9F3","b":"560D5A899000","o":"18E39F3","s":"__wt_event_handler_set","s+":"4A3"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5B8E63E3","b":"560D5A899000","o":"104D3E3","s":"__wt_panic_func","s+":"114"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5B8E2A8D","b":"560D5A899000","o":"1049A8D","s":"__wt_ext_map_windows_error","s+":"25CA"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C211DFA","b":"560D5A899000","o":"1978DFA","s":"__wt_sync_file","s+":"6AA"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C19B13B","b":"560D5A899000","o":"190213B","s":"__wt_checkpoint_tree_reconcile_update","s+":"1CB"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C19C23F","b":"560D5A899000","o":"190323F","s":"__wt_checkpoint_sync","s+":"99F"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C19DB76","b":"560D5A899000","o":"1904B76","s":"__wt_txn_checkpoint","s+":"246"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5B8E56EF","b":"560D5A899000","o":"104C6EF","s":"__wt_session_notsup","s+":"FCC"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C082586","b":"560D5A899000","o":"17E9586","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_sessionb","s+":"46"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C08F988","b":"560D5A899000","o":"17F6988","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_session","s+":"2B8"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C090050","b":"560D5A899000","o":"17F7050","s":"_ZN5mongo18WiredTigerKVEngine10checkpointEv","s+":"40"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5D035459","b":"560D5A899000","o":"279C459","s":"_ZN5mongo12Checkpointer3runEv","s+":"E59"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5E871E32","b":"560D5A899000","o":"3FD8E32","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"E2"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5E87254C","b":"560D5A899000","o":"3FD954C","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"7FC"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC912ADAB23","b":"7FC912A18000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC9122651DA","b":"7FC91225D000","o":"81DA","s":"start_thread","s+":"EA"}}}
{"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC911EC08D3","b":"7FC911E87000","o":"398D3","s":"clone","s+":"43"}}}Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f986ba85a50>
backup_type = 'physical'
@pytest.mark.timeout(900,func_only=True)
@pytest.mark.parametrize('backup_type',['logical','physical'])
def test_pitr_PBM_T268(start_cluster,cluster,backup_type):
def insert_docs():
client=pymongo.MongoClient(cluster.connection)
for i in range(1500):
client['test']['test'].insert_one({"doc":i})
time.sleep(0.1)
cluster.check_pbm_status()
base_backup=cluster.make_backup(backup_type)
cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=0.5")
Cluster.log("Start inserting docs in the background")
background_insert = threading.Thread(target=insert_docs)
background_insert.start()
time.sleep(60)
Cluster.log("Check if PITR is running")
if not cluster.check_pitr():
logs=cluster.exec_pbm_cli("logs -sD -t0")
assert False, logs.stdout
time.sleep(60)
background_insert.join()
time.sleep(30)
assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == 1500
pitr = datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%S")
Cluster.log("Time for PITR is " + pitr)
time.sleep(60)
cluster.disable_pitr()
pymongo.MongoClient(cluster.connection).drop_database('test')
backup="--time=" + pitr
if backup_type == 'logical':
cluster.make_restore(backup, check_pbm_status=True)
else:
> cluster.make_restore(backup, restart_cluster=True, check_pbm_status=True)
test_PBM-1211.py:79:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self = <cluster.Cluster object at 0x7f986ba85a50>
name = '--time=2024-11-08T14:03:28'
kwargs = {'check_pbm_status': True, 'restart_cluster': True}
client = MongoClient(host=['mongos:27017'], document_class=dict, tz_aware=False, connect=True)
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f986baa1ad0>, exit_status=1, command=b'time...AAAAABJ0AP//////////AA==","MultiOpType":null} | merr <nil>: applyOps: (NotWritablePrimary) not primary\n', _stderr=b'')
n = <testinfra.host.Host docker://rscfg01>, timeout = 240
error = '{"t":{"$date":"2024-11-08T14:05:20.534+00:00"},"s":"I", "c":"CONTROL", "id":23285, "ctx":"-","msg":"Automatically...ckpointer","msg":"Frame","attr":{"frame":{"a":"7FC911EC08D3","b":"7FC911E87000","o":"398D3","s":"clone","s+":"43"}}}\n'
host = 'rscfg01', container = <Container: b16b187b86c2>
def make_restore(self, name, **kwargs):
if self.layout == "sharded":
client = pymongo.MongoClient(self.connection)
result = client.admin.command("balancerStop")
client.close()
Cluster.log("Stopping balancer: " + str(result))
self.stop_mongos()
self.stop_arbiters()
n = testinfra.get_host("docker://" + self.pbm_cli)
timeout = time.time() + 60
while True:
if not self.get_status()['running']:
break
if time.time() > timeout:
assert False, "Cannot start restore, another operation running"
time.sleep(1)
Cluster.log("Restore started")
timeout=kwargs.get('timeout', 240)
result = n.run('timeout ' + str(timeout) + ' pbm restore ' + name + ' --wait')
if result.rc == 0:
Cluster.log(result.stdout)
else:
# try to catch possible failures if timeout exceeded
error=''
for host in self.mongod_hosts:
try:
container = docker.from_env().containers.get(host)
get_logs = container.exec_run(
'cat /var/lib/mongo/pbm.restore.log', stderr=False)
if get_logs.exit_code == 0:
Cluster.log(
"!!!!Possible failure on {}, file pbm.restore.log was found:".format(host))
logs = get_logs.output.decode('utf-8')
Cluster.log(logs)
if '"s":"F"' in logs:
error = logs
except docker.errors.APIError:
pass
if error:
> assert False, result.stdout + result.stderr + "\n" + error
E AssertionError: Starting restore 2024-11-08T14:04:41.732109464Z to point-in-time 2024-11-08T14:03:28 from '2024-11-08T13:59:49Z'..........................Started physical restore.
E Waiting to finish..............Error: operation failed with: replay pitr oplog: reply oplog: replay chunk 1731074391.1731074455: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1731074425,"I":16},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"test.test","Object":[{"Key":"_id","Value":"672e19791d4e17153b9d7f15"},{"Key":"doc","Value":0}],"Query":null,"UI":{"Subtype":4,"Data":"WREJ02EhQTmu7uYeB77Oxw=="},"LSID":"SAAAAAVpZAAQAAAABMkDZwqkH0PIhBsuJFgDLqYFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA","TxnNumber":1,"PrevOpTime":"HAAAABF0cwAAAAAAAAAAABJ0AP//////////AA==","MultiOpType":null} | merr <nil>: applyOps: (NotWritablePrimary) not primary
E
E {"t":{"$date":"2024-11-08T14:05:20.534+00:00"},"s":"I", "c":"CONTROL", "id":23285, "ctx":"-","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
E {"t":{"$date":"2024-11-08T14:05:20.534+00:00"},"s":"I", "c":"NETWORK", "id":4915701, "ctx":"-","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}
E {"t":{"$date":"2024-11-08T14:05:20.534+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
E {"t":{"$date":"2024-11-08T14:05:20.534+00:00"},"s":"I", "c":"NETWORK", "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
E {"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
E {"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
E {"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}
E {"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}
E {"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":5945603, "ctx":"main","msg":"Multi threading initialized"}
E {"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":510,"port":27407,"dbPath":"/var/lib/mongo","architecture":"64-bit","host":"rs101"}}
E {"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":23403, "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.29-25","gitVersion":"6ed5ea3065f1daafa7661d1c05d20c50b614a96a","openSSLVersion":"OpenSSL 1.1.1k FIPS 25 Mar 2021","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
E {"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":51765, "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Oracle Linux Server release 8.10","version":"Kernel 6.5.0-1025-azure"}}}
E {"t":{"$date":"2024-11-08T14:05:20.535+00:00"},"s":"I", "c":"CONTROL", "id":21951, "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/tmp/pbmMongdTmpConf630898707","net":{"bindIp":"localhost","port":27407},"replication":{"replSet":"rs1"},"setParameter":{"disableLogicalSessionCacheRefresh":"true","takeUnstableCheckpointOnShutdown":"true"},"storage":{"dbPath":"/var/lib/mongo","directoryPerDB":false,"wiredTiger":{"collectionConfig":{"blockCompressor":"snappy"},"engineConfig":{"directoryForIndexes":false,"journalCompressor":"snappy"},"indexConfig":{"prefixCompression":true}}},"systemLog":{"destination":"file","path":"/var/lib/mongo/pbm.restore.log"}}}}
E {"t":{"$date":"2024-11-08T14:05:20.536+00:00"},"s":"I", "c":"STORAGE", "id":22270, "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongo","storageEngine":"wiredTiger"}}
E {"t":{"$date":"2024-11-08T14:05:20.536+00:00"},"s":"I", "c":"STORAGE", "id":22315, "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7478M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),builtin_extension_config=(zstd=(compression_level=6)),file_manager=(close_idle_time=600,close_scan_interval=10,close_handle_minimum=2000),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
E {"t":{"$date":"2024-11-08T14:05:20.736+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:736592][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 5 through 6"}}
E {"t":{"$date":"2024-11-08T14:05:20.761+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:761553][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 6 through 6"}}
E {"t":{"$date":"2024-11-08T14:05:20.820+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:820585][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_ALL] Main recovery loop: starting at 5/47232 to 6/256"}}
E {"t":{"$date":"2024-11-08T14:05:20.867+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:867528][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 5 through 6"}}
E {"t":{"$date":"2024-11-08T14:05:20.902+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:902413][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 6 through 6"}}
E {"t":{"$date":"2024-11-08T14:05:20.925+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:925207][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery log replay has successfully finished and ran for 188 milliseconds"}}
E {"t":{"$date":"2024-11-08T14:05:20.925+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:925243][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (0, 0)"}}
E {"t":{"$date":"2024-11-08T14:05:20.925+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:925254][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (0, 0)"}}
E {"t":{"$date":"2024-11-08T14:05:20.926+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:926093][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery rollback to stable has successfully finished and ran for 0 milliseconds"}}
E {"t":{"$date":"2024-11-08T14:05:20.927+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:927675][510:0x7fc914af1c00], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 1, snapshot max: 1 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 42"}}
E {"t":{"$date":"2024-11-08T14:05:20.929+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:929886][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery checkpoint has successfully finished and ran for 3 milliseconds"}}
E {"t":{"$date":"2024-11-08T14:05:20.929+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:929922][510:0x7fc914af1c00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery was completed successfully and took 193ms, including 188ms for the log replay, 0ms for the rollback to stable, and 3ms for the checkpoint."}}
E {"t":{"$date":"2024-11-08T14:05:20.930+00:00"},"s":"I", "c":"STORAGE", "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":394}}
E {"t":{"$date":"2024-11-08T14:05:20.930+00:00"},"s":"I", "c":"RECOVERY", "id":23987, "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}
E {"t":{"$date":"2024-11-08T14:05:20.939+00:00"},"s":"I", "c":"STORAGE", "id":22383, "ctx":"initandlisten","msg":"The size storer reports that the oplog contains","attr":{"numRecords":47,"dataSize":13138}}
E {"t":{"$date":"2024-11-08T14:05:20.939+00:00"},"s":"I", "c":"STORAGE", "id":22384, "ctx":"initandlisten","msg":"Scanning the oplog to determine where to place markers for truncation"}
E {"t":{"$date":"2024-11-08T14:05:20.940+00:00"},"s":"I", "c":"STORAGE", "id":22382, "ctx":"initandlisten","msg":"WiredTiger record store oplog processing finished","attr":{"durationMillis":0}}
E {"t":{"$date":"2024-11-08T14:05:20.952+00:00"},"s":"I", "c":"STORAGE", "id":22262, "ctx":"initandlisten","msg":"Timestamp monitor starting"}
E {"t":{"$date":"2024-11-08T14:05:20.953+00:00"},"s":"W", "c":"CONTROL", "id":22120, "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted. You can use percona-server-mongodb-enable-auth.sh to fix it","tags":["startupWarnings"]}
E {"t":{"$date":"2024-11-08T14:05:20.953+00:00"},"s":"W", "c":"CONTROL", "id":22178, "ctx":"initandlisten","msg":"/sys/kernel/mm/transparent_hugepage/enabled is 'always'. We suggest setting it to 'never' in this binary version","tags":["startupWarnings"]}
E {"t":{"$date":"2024-11-08T14:05:20.960+00:00"},"s":"I", "c":"NETWORK", "id":4915702, "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":13,"maxWireVersion":13},"outgoing":{"minWireVersion":13,"maxWireVersion":13},"isInternalClient":true}}}
E {"t":{"$date":"2024-11-08T14:05:20.960+00:00"},"s":"I", "c":"STORAGE", "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}
E {"t":{"$date":"2024-11-08T14:05:20.978+00:00"},"s":"I", "c":"CONTROL", "id":20536, "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}
E {"t":{"$date":"2024-11-08T14:05:20.979+00:00"},"s":"W", "c":"SHARDING", "id":22075, "ctx":"initandlisten","msg":"Not started with --shardsvr, but a shardIdentity document was found on disk","attr":{"namespace":"admin.system.version","shardIdentityDocument":{"_id":"shardIdentity","shardName":"rs1","clusterId":{"$oid":"672e1942fb7cde5b9f386568"},"configsvrConnectionString":"rscfg/rscfg01:27017"}}}
E {"t":{"$date":"2024-11-08T14:05:20.979+00:00"},"s":"I", "c":"FTDC", "id":20625, "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/var/lib/mongo/diagnostic.data"}}
E {"t":{"$date":"2024-11-08T14:05:20.981+00:00"},"s":"I", "c":"-", "id":4939300, "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"ReadConcernMajorityNotAvailableYet: Read concern majority reads are currently not possible.","nextWakeupMillis":200}}
E {"t":{"$date":"2024-11-08T14:05:20.981+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigStartingUp","oldState":"ConfigPreStart"}}
E {"t":{"$date":"2024-11-08T14:05:20.981+00:00"},"s":"I", "c":"REPL", "id":4280500, "ctx":"initandlisten","msg":"Attempting to create internal replication collections"}
E {"t":{"$date":"2024-11-08T14:05:20.984+00:00"},"s":"I", "c":"REPL", "id":4280501, "ctx":"initandlisten","msg":"Attempting to load local voted for document"}
E {"t":{"$date":"2024-11-08T14:05:20.984+00:00"},"s":"I", "c":"REPL", "id":21311, "ctx":"initandlisten","msg":"Did not find local initialized voted for document at startup"}
E {"t":{"$date":"2024-11-08T14:05:20.984+00:00"},"s":"I", "c":"REPL", "id":4280502, "ctx":"initandlisten","msg":"Searching for local Rollback ID document"}
E {"t":{"$date":"2024-11-08T14:05:20.985+00:00"},"s":"I", "c":"REPL", "id":21529, "ctx":"initandlisten","msg":"Initializing rollback ID","attr":{"rbid":1}}
E {"t":{"$date":"2024-11-08T14:05:20.985+00:00"},"s":"I", "c":"REPL", "id":4280504, "ctx":"initandlisten","msg":"Cleaning up any partially applied oplog batches & reading last op from oplog"}
E {"t":{"$date":"2024-11-08T14:05:20.985+00:00"},"s":"I", "c":"REPL", "id":21546, "ctx":"initandlisten","msg":"Recovering from an unstable checkpoint","attr":{"topOfOplog":{"ts":{"$timestamp":{"t":1731074389,"i":44}},"t":1},"appliedThrough":{"ts":{"$timestamp":{"t":1731074389,"i":44}},"t":1}}}
E {"t":{"$date":"2024-11-08T14:05:20.986+00:00"},"s":"I", "c":"REPL", "id":21548, "ctx":"initandlisten","msg":"Starting recovery oplog application at the appliedThrough through the top of the oplog","attr":{"appliedThrough":{"ts":{"$timestamp":{"t":1731074389,"i":44}},"t":1},"topOfOplog":{"ts":{"$timestamp":{"t":1731074389,"i":44}},"t":1}}}
E {"t":{"$date":"2024-11-08T14:05:20.986+00:00"},"s":"I", "c":"REPL", "id":21549, "ctx":"initandlisten","msg":"No oplog entries to apply for recovery. Start point is at the top of the oplog"}
E {"t":{"$date":"2024-11-08T14:05:20.987+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1731074720:987663][510:0x7fc914af1c00], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 37, snapshot max: 37 snapshot count: 0, oldest timestamp: (1731074389, 44) , meta checkpoint timestamp: (0, 0) base write gen: 42"}}
E {"t":{"$date":"2024-11-08T14:05:20.991+00:00"},"s":"I", "c":"REPL", "id":4280505, "ctx":"initandlisten","msg":"Creating any necessary TenantMigrationAccessBlockers for unfinished migrations"}
E {"t":{"$date":"2024-11-08T14:05:20.991+00:00"},"s":"I", "c":"REPL", "id":4280506, "ctx":"initandlisten","msg":"Reconstructing prepared transactions"}
E {"t":{"$date":"2024-11-08T14:05:20.992+00:00"},"s":"I", "c":"REPL", "id":4280507, "ctx":"initandlisten","msg":"Loaded replica set config, scheduled callback to set local config"}
E {"t":{"$date":"2024-11-08T14:05:20.992+00:00"},"s":"I", "c":"REPL", "id":4280508, "ctx":"ReplCoord-0","msg":"Attempting to set local replica set config; validating config for startup"}
E {"t":{"$date":"2024-11-08T14:05:20.992+00:00"},"s":"I", "c":"REPL", "id":40440, "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}
E {"t":{"$date":"2024-11-08T14:05:20.993+00:00"},"s":"I", "c":"REPL", "id":40445, "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}
E {"t":{"$date":"2024-11-08T14:05:20.993+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-27407.sock"}}
E {"t":{"$date":"2024-11-08T14:05:20.993+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}
E {"t":{"$date":"2024-11-08T14:05:20.993+00:00"},"s":"I", "c":"NETWORK", "id":23016, "ctx":"listener","msg":"Waiting for connections","attr":{"port":27407,"ssl":"off"}}
E {"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44604","uuid":"c534b521-b10f-4af2-aa29-d07ab0485af2","connectionId":1,"connectionCount":1}}
E {"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44610","uuid":"29fb6d75-c6a9-4c22-8a3a-505aa1ccfbd2","connectionId":3,"connectionCount":2}}
E {"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn1","msg":"client metadata","attr":{"remote":"127.0.0.1:44604","client":"conn1","negotiatedCompressors":[],"doc":{"application":{"name":"pbm-physical-restore"},"driver":{"name":"mongo-go-driver","version":"1.16.0"},"os":{"type":"linux","architecture":"amd64"},"platform":"go1.23.3","env":{"container":{"runtime":"docker"}}}}}
E {"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"W", "c":"COMMAND", "id":5578800, "ctx":"conn3","msg":"Deprecated operation requested. The client driver may require an upgrade in order to ensure compatibility with future server versions. For more details see https://dochub.mongodb.org/core/legacy-opcode-compatibility","attr":{"op":"query","clientInfo":{"address":"127.0.0.1:44610"}}}
E {"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"REPL", "id":4280509, "ctx":"ReplCoord-0","msg":"Local configuration validated for startup"}
E {"t":{"$date":"2024-11-08T14:05:21.021+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"ReplCoord-0","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigStartingUp"}}
E {"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44620","uuid":"021d5572-bb8b-437a-ac4f-5ca867ca73b6","connectionId":4,"connectionCount":3}}
E {"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21392, "ctx":"ReplCoord-0","msg":"New replica set config in use","attr":{"config":{"_id":"rs1","version":1,"members":[{"_id":0,"host":"localhost:27407","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1,"tags":{},"secondaryDelaySecs":0,"votes":1}],"protocolVersion":1,"writeConcernMajorityJournalDefault":true,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":10000,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0}}}}}
E {"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21393, "ctx":"ReplCoord-0","msg":"Found self in config","attr":{"hostAndPort":"localhost:27407"}}
E {"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"STARTUP2","oldState":"STARTUP"}}
E {"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn3","msg":"Connection ended","attr":{"remote":"127.0.0.1:44610","uuid":"29fb6d75-c6a9-4c22-8a3a-505aa1ccfbd2","connectionId":3,"connectionCount":2}}
E {"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21320, "ctx":"ReplCoord-0","msg":"Updated term","attr":{"term":1}}
E {"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"REPL", "id":21306, "ctx":"ReplCoord-0","msg":"Starting replication storage threads"}
E {"t":{"$date":"2024-11-08T14:05:21.022+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44636","uuid":"03ee4e9d-91db-4e89-b167-e28271854d79","connectionId":5,"connectionCount":3}}
E {"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn5","msg":"client metadata","attr":{"remote":"127.0.0.1:44636","client":"conn5","negotiatedCompressors":[],"doc":{"application":{"name":"pbm-physical-restore"},"driver":{"name":"mongo-go-driver","version":"1.16.0"},"os":{"type":"linux","architecture":"amd64"},"platform":"go1.23.3","env":{"container":{"runtime":"docker"}}}}}
E {"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn4","msg":"client metadata","attr":{"remote":"127.0.0.1:44620","client":"conn4","negotiatedCompressors":[],"doc":{"application":{"name":"pbm-physical-restore"},"driver":{"name":"mongo-go-driver","version":"1.16.0"},"os":{"type":"linux","architecture":"amd64"},"platform":"go1.23.3","env":{"container":{"runtime":"docker"}}}}}
E {"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"REPL", "id":4280512, "ctx":"ReplCoord-0","msg":"No initial sync required. Attempting to begin steady replication"}
E {"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"RECOVERING","oldState":"STARTUP2"}}
E {"t":{"$date":"2024-11-08T14:05:21.023+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"ReplCoord-0","msg":"createCollection","attr":{"namespace":"local.replset.initialSyncId","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"287444f4-8af8-404f-a606-826b191f7a4e"}},"options":{}}}
E {"t":{"$date":"2024-11-08T14:05:21.031+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"ReplCoord-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.replset.initialSyncId","index":"_id_","commitTimestamp":null}}
E {"t":{"$date":"2024-11-08T14:05:21.031+00:00"},"s":"I", "c":"REPL", "id":21299, "ctx":"ReplCoord-0","msg":"Starting replication fetcher thread"}
E {"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":21300, "ctx":"ReplCoord-0","msg":"Starting replication applier thread"}
E {"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":21301, "ctx":"ReplCoord-0","msg":"Starting replication reporter thread"}
E {"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":4280511, "ctx":"ReplCoord-0","msg":"Set local replica set config"}
E {"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":21224, "ctx":"OplogApplier-0","msg":"Starting oplog application"}
E {"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"OplogApplier-0","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"RECOVERING"}}
E {"t":{"$date":"2024-11-08T14:05:21.032+00:00"},"s":"I", "c":"ELECTION", "id":4615652, "ctx":"OplogApplier-0","msg":"Starting an election, since we've seen no PRIMARY in election timeout period","attr":{"electionTimeoutPeriodMillis":10000}}
E {"t":{"$date":"2024-11-08T14:05:21.033+00:00"},"s":"I", "c":"ELECTION", "id":21438, "ctx":"OplogApplier-0","msg":"Conducting a dry run election to see if we could be elected","attr":{"currentTerm":1}}
E {"t":{"$date":"2024-11-08T14:05:21.033+00:00"},"s":"I", "c":"ELECTION", "id":21444, "ctx":"ReplCoord-0","msg":"Dry election run succeeded, running for election","attr":{"newTerm":2}}
E {"t":{"$date":"2024-11-08T14:05:21.033+00:00"},"s":"I", "c":"ELECTION", "id":6015300, "ctx":"ReplCoord-0","msg":"Storing last vote document in local storage for my election","attr":{"lastVote":{"term":2,"candidateIndex":0}}}
E {"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"ELECTION", "id":21450, "ctx":"ReplCoord-0","msg":"Election succeeded, assuming primary role","attr":{"term":2}}
E {"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}}
E {"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21106, "ctx":"ReplCoord-0","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}}
E {"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21359, "ctx":"ReplCoord-0","msg":"Entering primary catch-up mode"}
E {"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":6015304, "ctx":"ReplCoord-0","msg":"Skipping primary catchup since we are the only node in the replica set."}
E {"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21363, "ctx":"ReplCoord-0","msg":"Exited primary catch-up mode"}
E {"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21107, "ctx":"ReplCoord-0","msg":"Stopping replication producer"}
E {"t":{"$date":"2024-11-08T14:05:21.034+00:00"},"s":"I", "c":"REPL", "id":21239, "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":2}}
E {"t":{"$date":"2024-11-08T14:05:21.035+00:00"},"s":"I", "c":"REPL", "id":21343, "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}
E {"t":{"$date":"2024-11-08T14:05:21.035+00:00"},"s":"I", "c":"REPL", "id":21344, "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"}
E {"t":{"$date":"2024-11-08T14:05:21.035+00:00"},"s":"I", "c":"REPL", "id":21340, "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepUp","userOpsKilled":0,"userOpsRunning":1}}}
E {"t":{"$date":"2024-11-08T14:05:21.035+00:00"},"s":"I", "c":"REPL", "id":6015310, "ctx":"OplogApplier-0","msg":"Starting to transition to primary."}
E {"t":{"$date":"2024-11-08T14:05:21.036+00:00"},"s":"I", "c":"REPL", "id":6015309, "ctx":"OplogApplier-0","msg":"Logging transition to primary to oplog on stepup"}
E {"t":{"$date":"2024-11-08T14:05:21.036+00:00"},"s":"I", "c":"STORAGE", "id":20657, "ctx":"OplogApplier-0","msg":"IndexBuildsCoordinator::onStepUp - this node is stepping up to primary"}
E {"t":{"$date":"2024-11-08T14:05:21.036+00:00"},"s":"I", "c":"REPL", "id":21331, "ctx":"OplogApplier-0","msg":"Transition to primary complete; database writes are now permitted"}
E {"t":{"$date":"2024-11-08T14:05:21.037+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"monitoring-keys-for-HMAC","msg":"createCollection","attr":{"namespace":"admin.system.keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"3c469c6a-6e28-469c-8292-8a2441ad2def"}},"options":{}}}
E {"t":{"$date":"2024-11-08T14:05:21.039+00:00"},"s":"I", "c":"STORAGE", "id":22310, "ctx":"JournalFlusher","msg":"Triggering the first stable checkpoint","attr":{"initialDataTimestamp":{"$timestamp":{"t":1731074389,"i":44}},"prevStableTimestamp":{"$timestamp":{"t":0,"i":0}},"currStableTimestamp":{"$timestamp":{"t":1731074721,"i":2}}}}
E {"t":{"$date":"2024-11-08T14:05:21.040+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationDonors","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"c61daba4-6fa8-459f-bb5c-e7c47b9f3b43"}},"options":{}}}
E {"t":{"$date":"2024-11-08T14:05:21.040+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationRecipientService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationRecipients","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"2fc4736d-c484-434d-ab38-eb76367dd5ac"}},"options":{}}}
E {"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"Checkpointer","msg":"WiredTiger error","attr":{"error":2,"message":"[1731074721:41541][510:0x7fc8fc9fc700], file:collection-2-4794091703575719002.wt, WT_SESSION.checkpoint: __posix_fs_size, 296: /var/lib/mongo/WiredTigerHS.wt: file-size: stat: No such file or directory"}}
E {"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"Checkpointer","msg":"WiredTiger error","attr":{"error":2,"message":"[1731074721:41591][510:0x7fc8fc9fc700], file:collection-2-4794091703575719002.wt, WT_SESSION.checkpoint: __reconcile, 351: reconciliation failed after building the disk image: No such file or directory"}}
E {"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"Checkpointer","msg":"WiredTiger error","attr":{"error":-31804,"message":"[1731074721:41651][510:0x7fc8fc9fc700], file:collection-2-4794091703575719002.wt, WT_SESSION.checkpoint: __reconcile, 351: the process must exit and restart: WT_PANIC: WiredTiger library panic"}}
E {"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"F", "c":"-", "id":23089, "ctx":"Checkpointer","msg":"Fatal assertion","attr":{"msgid":50853,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp","line":574}}
E {"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"F", "c":"-", "id":23090, "ctx":"Checkpointer","msg":"\n\n***aborting after fassert() failure\n\n"}
E {"t":{"$date":"2024-11-08T14:05:21.041+00:00"},"s":"F", "c":"CONTROL", "id":6384300, "ctx":"Checkpointer","msg":"Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}}
E {"t":{"$date":"2024-11-08T14:05:21.049+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn4","msg":"Connection ended","attr":{"remote":"127.0.0.1:44620","uuid":"021d5572-bb8b-437a-ac4f-5ca867ca73b6","connectionId":4,"connectionCount":2}}
E {"t":{"$date":"2024-11-08T14:05:21.049+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn5","msg":"Connection ended","attr":{"remote":"127.0.0.1:44636","uuid":"03ee4e9d-91db-4e89-b167-e28271854d79","connectionId":5,"connectionCount":1}}
E {"t":{"$date":"2024-11-08T14:05:21.050+00:00"},"s":"I", "c":"-", "id":20883, "ctx":"conn1","msg":"Interrupted operation as its client disconnected","attr":{"opId":45}}
E {"t":{"$date":"2024-11-08T14:05:21.050+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn1","msg":"Connection ended","attr":{"remote":"127.0.0.1:44604","uuid":"c534b521-b10f-4af2-aa29-d07ab0485af2","connectionId":1,"connectionCount":0}}
E {"t":{"$date":"2024-11-08T14:05:21.054+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"_id_","commitTimestamp":{"$timestamp":{"t":1731074721,"i":6}}}}
E {"t":{"$date":"2024-11-08T14:05:21.054+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationRecipientService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationRecipients","index":"TenantMigrationRecipientTTLIndex","commitTimestamp":{"$timestamp":{"t":1731074721,"i":6}}}}
E {"t":{"$date":"2024-11-08T14:05:21.054+00:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationRecipientService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationRecipientService"}}
E {"t":{"$date":"2024-11-08T14:05:21.059+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"monitoring-keys-for-HMAC","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"admin.system.keys","index":"_id_","commitTimestamp":{"$timestamp":{"t":1731074721,"i":3}}}}
E {"t":{"$date":"2024-11-08T14:05:21.065+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"_id_","commitTimestamp":{"$timestamp":{"t":1731074721,"i":8}}}}
E {"t":{"$date":"2024-11-08T14:05:21.065+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.tenantMigrationDonors","index":"TenantMigrationDonorTTLIndex","commitTimestamp":{"$timestamp":{"t":1731074721,"i":8}}}}
E {"t":{"$date":"2024-11-08T14:05:21.065+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.external_validation_keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"7bed0cc6-3081-4174-8db2-4027f7517813"}},"options":{}}}
E {"t":{"$date":"2024-11-08T14:05:21.073+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"_id_","commitTimestamp":{"$timestamp":{"t":1731074721,"i":11}}}}
E {"t":{"$date":"2024-11-08T14:05:21.073+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"ExternalKeysTTLIndex","commitTimestamp":{"$timestamp":{"t":1731074721,"i":11}}}}
E {"t":{"$date":"2024-11-08T14:05:21.073+00:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationDonorService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationDonorService"}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31380, "ctx":"Checkpointer","msg":"BACKTRACE","attr":{"bt":{"backtrace":[{"a":"560D5EAB69C3","b":"560D5A899000","o":"421D9C3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"},{"a":"560D5EAB9417","b":"560D5A899000","o":"4220417","s":"_ZN5mongo15printStackTraceEv","s+":"37"},{"a":"560D5EAB15B6","b":"560D5A899000","o":"42185B6","s":"abruptQuit","s+":"66"},{"a":"7FC91226FD80","b":"7FC91225D000","o":"12D80","s":"funlockfile","s+":"50"},{"a":"7FC911ED55EF","b":"7FC911E87000","o":"4E5EF","s":"gsignal","s+":"10F"},{"a":"7FC911EA8E65","b":"7FC911E87000","o":"21E65","s":"abort","s+":"127"},{"a":"560D5BE17D6D","b":"560D5A899000","o":"157ED6D","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"},{"a":"560D5B8D3CF4","b":"560D5A899000","o":"103ACF4","s":"_ZZN5mongo8RecordIdC4EPKciENKUlvE0_clEv","s+":"30B8"},{"a":"560D5C17C9F3","b":"560D5A899000","o":"18E39F3","s":"__wt_event_handler_set","s+":"4A3"},{"a":"560D5B8E63E3","b":"560D5A899000","o":"104D3E3","s":"__wt_panic_func","s+":"114"},{"a":"560D5B8E2A8D","b":"560D5A899000","o":"1049A8D","s":"__wt_ext_map_windows_error","s+":"25CA"},{"a":"560D5C211DFA","b":"560D5A899000","o":"1978DFA","s":"__wt_sync_file","s+":"6AA"},{"a":"560D5C19B13B","b":"560D5A899000","o":"190213B","s":"__wt_checkpoint_tree_reconcile_update","s+":"1CB"},{"a":"560D5C19C23F","b":"560D5A899000","o":"190323F","s":"__wt_checkpoint_sync","s+":"99F"},{"a":"560D5C19DB76","b":"560D5A899000","o":"1904B76","s":"__wt_txn_checkpoint","s+":"246"},{"a":"560D5B8E56EF","b":"560D5A899000","o":"104C6EF","s":"__wt_session_notsup","s+":"FCC"},{"a":"560D5C082586","b":"560D5A899000","o":"17E9586","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_sessionb","s+":"46"},{"a":"560D5C08F988","b":"560D5A899000","o":"17F6988","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_session","s+":"2B8"},{"a":"560D5C090050","b":"560D5A899000","o":"17F7050","s":"_ZN5mongo18WiredTigerKVEngine10checkpointEv","s+":"40"},{"a":"560D5D035459","b":"560D5A899000","o":"279C459","s":"_ZN5mongo12Checkpointer3runEv","s+":"E59"},{"a":"560D5E871E32","b":"560D5A899000","o":"3FD8E32","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"E2"},{"a":"560D5E87254C","b":"560D5A899000","o":"3FD954C","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"7FC"},{"a":"7FC912ADAB23","b":"7FC912A18000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"},{"a":"7FC9122651DA","b":"7FC91225D000","o":"81DA","s":"start_thread","s+":"EA"},{"a":"7FC911EC08D3","b":"7FC911E87000","o":"398D3","s":"clone","s+":"43"}],"processInfo":{"mongodbVersion":"5.0.29-25","gitVersion":"6ed5ea3065f1daafa7661d1c05d20c50b614a96a","compiledModules":[],"uname":{"sysname":"Linux","release":"6.5.0-1025-azure","version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","machine":"x86_64"},"somap":[{"b":"560D5A899000","elfType":3,"buildId":"539E2C825673723B04D19874D3C9DF6EB9A69E4F"},{"b":"7FC912A18000","path":"/lib64/libstdc++.so.6","elfType":3,"buildId":"41809D0B18272BC525772714DA54108BF1C59253"},{"b":"7FC91225D000","path":"/lib64/libpthread.so.0","elfType":3,"buildId":"0B813C2AD185DCA27DDB58BA42ACC172679B1526"},{"b":"7FC911E87000","path":"/lib64/libc.so.6","elfType":3,"buildId":"BF4C06A1D77241A2D30436873E56C348FCBB5D22"}]}}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5EAB69C3","b":"560D5A899000","o":"421D9C3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5EAB9417","b":"560D5A899000","o":"4220417","s":"_ZN5mongo15printStackTraceEv","s+":"37"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5EAB15B6","b":"560D5A899000","o":"42185B6","s":"abruptQuit","s+":"66"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC91226FD80","b":"7FC91225D000","o":"12D80","s":"funlockfile","s+":"50"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC911ED55EF","b":"7FC911E87000","o":"4E5EF","s":"gsignal","s+":"10F"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC911EA8E65","b":"7FC911E87000","o":"21E65","s":"abort","s+":"127"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5BE17D6D","b":"560D5A899000","o":"157ED6D","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5B8D3CF4","b":"560D5A899000","o":"103ACF4","s":"_ZZN5mongo8RecordIdC4EPKciENKUlvE0_clEv","s+":"30B8"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C17C9F3","b":"560D5A899000","o":"18E39F3","s":"__wt_event_handler_set","s+":"4A3"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5B8E63E3","b":"560D5A899000","o":"104D3E3","s":"__wt_panic_func","s+":"114"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5B8E2A8D","b":"560D5A899000","o":"1049A8D","s":"__wt_ext_map_windows_error","s+":"25CA"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C211DFA","b":"560D5A899000","o":"1978DFA","s":"__wt_sync_file","s+":"6AA"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C19B13B","b":"560D5A899000","o":"190213B","s":"__wt_checkpoint_tree_reconcile_update","s+":"1CB"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C19C23F","b":"560D5A899000","o":"190323F","s":"__wt_checkpoint_sync","s+":"99F"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C19DB76","b":"560D5A899000","o":"1904B76","s":"__wt_txn_checkpoint","s+":"246"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5B8E56EF","b":"560D5A899000","o":"104C6EF","s":"__wt_session_notsup","s+":"FCC"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C082586","b":"560D5A899000","o":"17E9586","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_sessionb","s+":"46"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C08F988","b":"560D5A899000","o":"17F6988","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_session","s+":"2B8"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5C090050","b":"560D5A899000","o":"17F7050","s":"_ZN5mongo18WiredTigerKVEngine10checkpointEv","s+":"40"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5D035459","b":"560D5A899000","o":"279C459","s":"_ZN5mongo12Checkpointer3runEv","s+":"E59"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5E871E32","b":"560D5A899000","o":"3FD8E32","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"E2"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"560D5E87254C","b":"560D5A899000","o":"3FD954C","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"7FC"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC912ADAB23","b":"7FC912A18000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC9122651DA","b":"7FC91225D000","o":"81DA","s":"start_thread","s+":"EA"}}}
E {"t":{"$date":"2024-11-08T14:05:21.106+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7FC911EC08D3","b":"7FC911E87000","o":"398D3","s":"clone","s+":"43"}}}
cluster.py:462: AssertionError
Loading