AssertionError: Starting restore 2024-12-02T11:35:31.196042205Z to point-in-time 2024-12-02T11:34:18 from '2024-12-02T11:30:38Z'..........................Started physical restore. Waiting to finish.........Error: operation failed with: replay pitr oplog: reply oplog: replay chunk 1733139040.1733139104: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1733139074,"I":16},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"test.test","Object":[{"Key":"_id","Value":"674d9a8224106a1ada66ed44"},{"Key":"doc","Value":0}],"Query":null,"UI":{"Subtype":4,"Data":"ljMJ/FDJQg+Bieb3uFQd7w=="},"LSID":"SAAAAAVpZAAQAAAABAwoe4QDKU59nkrRk5dQHkkFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA","TxnNumber":1,"PrevOpTime":"HAAAABF0cwAAAAAAAAAAABJ0AP//////////AA==","MultiOpType":null} | merr <nil>: applyOps: (NotWritablePrimary) not primary {"t":{"$date":"2024-12-02T11:36:05.585+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-12-02T11:36:05.585+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-12-02T11:36:05.588+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"} {"t":{"$date":"2024-12-02T11:36:05.588+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-12-02T11:36:05.589+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"} {"t":{"$date":"2024-12-02T11:36:05.589+00:00"},"s":"W", "c":"ASIO", "id":22601, "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"} {"t":{"$date":"2024-12-02T11:36:05.589+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}} {"t":{"$date":"2024-12-02T11:36:05.589+00:00"},"s":"I", "c":"REPL", "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}} {"t":{"$date":"2024-12-02T11:36:05.589+00:00"},"s":"I", "c":"CONTROL", "id":5945603, "ctx":"main","msg":"Multi threading initialized"} {"t":{"$date":"2024-12-02T11:36:05.589+00:00"},"s":"I", "c":"CONTROL", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":512,"port":27653,"dbPath":"/var/lib/mongo","architecture":"64-bit","host":"rs101"}} {"t":{"$date":"2024-12-02T11:36:05.589+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-12-02T11:36:05.589+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-12-02T11:36:05.589+00:00"},"s":"I", "c":"CONTROL", "id":21951, "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/tmp/pbmMongdTmpConf39861279","net":{"bindIp":"localhost","port":27653},"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-12-02T11:36:05.590+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-12-02T11:36:05.590+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-12-02T11:36:05.791+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:791064][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 5 through 6"}} {"t":{"$date":"2024-12-02T11:36:05.816+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:816962][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 6 through 6"}} {"t":{"$date":"2024-12-02T11:36:05.870+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:870273][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_ALL] Main recovery loop: starting at 5/47232 to 6/256"}} {"t":{"$date":"2024-12-02T11:36:05.917+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:917579][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 5 through 6"}} {"t":{"$date":"2024-12-02T11:36:05.951+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:951874][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 6 through 6"}} {"t":{"$date":"2024-12-02T11:36:05.974+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:974210][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery log replay has successfully finished and ran for 183 milliseconds"}} {"t":{"$date":"2024-12-02T11:36:05.974+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:974252][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (0, 0)"}} {"t":{"$date":"2024-12-02T11:36:05.974+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:974263][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (0, 0)"}} {"t":{"$date":"2024-12-02T11:36:05.975+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:975097][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery rollback to stable has successfully finished and ran for 0 milliseconds"}} {"t":{"$date":"2024-12-02T11:36:05.976+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:976723][512:0x7f463a27ac00], 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-12-02T11:36:05.979+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:979308][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery checkpoint has successfully finished and ran for 4 milliseconds"}} {"t":{"$date":"2024-12-02T11:36:05.979+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139365:979342][512:0x7f463a27ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] recovery was completed successfully and took 188ms, including 183ms for the log replay, 0ms for the rollback to stable, and 4ms for the checkpoint."}} {"t":{"$date":"2024-12-02T11:36:05.979+00:00"},"s":"I", "c":"STORAGE", "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":389}} {"t":{"$date":"2024-12-02T11:36:05.980+00:00"},"s":"I", "c":"RECOVERY", "id":23987, "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}} {"t":{"$date":"2024-12-02T11:36:05.987+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-12-02T11:36:05.987+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-12-02T11:36:05.987+00:00"},"s":"I", "c":"STORAGE", "id":22382, "ctx":"initandlisten","msg":"WiredTiger record store oplog processing finished","attr":{"durationMillis":0}} {"t":{"$date":"2024-12-02T11:36:06.002+00:00"},"s":"I", "c":"STORAGE", "id":22262, "ctx":"initandlisten","msg":"Timestamp monitor starting"} {"t":{"$date":"2024-12-02T11:36:06.003+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-12-02T11:36:06.003+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-12-02T11:36:06.011+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-12-02T11:36:06.011+00:00"},"s":"I", "c":"STORAGE", "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"} {"t":{"$date":"2024-12-02T11:36:06.030+00:00"},"s":"I", "c":"CONTROL", "id":20536, "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"} {"t":{"$date":"2024-12-02T11:36:06.030+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":"674d9a4bf5d9397a6743b436"},"configsvrConnectionString":"rscfg/rscfg01:27017"}}} {"t":{"$date":"2024-12-02T11:36:06.031+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-12-02T11:36:06.033+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-12-02T11:36:06.033+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigStartingUp","oldState":"ConfigPreStart"}} {"t":{"$date":"2024-12-02T11:36:06.033+00:00"},"s":"I", "c":"REPL", "id":4280500, "ctx":"initandlisten","msg":"Attempting to create internal replication collections"} {"t":{"$date":"2024-12-02T11:36:06.035+00:00"},"s":"I", "c":"REPL", "id":4280501, "ctx":"initandlisten","msg":"Attempting to load local voted for document"} {"t":{"$date":"2024-12-02T11:36:06.035+00:00"},"s":"I", "c":"REPL", "id":21311, "ctx":"initandlisten","msg":"Did not find local initialized voted for document at startup"} {"t":{"$date":"2024-12-02T11:36:06.035+00:00"},"s":"I", "c":"REPL", "id":4280502, "ctx":"initandlisten","msg":"Searching for local Rollback ID document"} {"t":{"$date":"2024-12-02T11:36:06.037+00:00"},"s":"I", "c":"REPL", "id":21529, "ctx":"initandlisten","msg":"Initializing rollback ID","attr":{"rbid":1}} {"t":{"$date":"2024-12-02T11:36:06.037+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-12-02T11:36:06.037+00:00"},"s":"I", "c":"REPL", "id":21546, "ctx":"initandlisten","msg":"Recovering from an unstable checkpoint","attr":{"topOfOplog":{"ts":{"$timestamp":{"t":1733139038,"i":44}},"t":1},"appliedThrough":{"ts":{"$timestamp":{"t":1733139038,"i":44}},"t":1}}} {"t":{"$date":"2024-12-02T11:36:06.037+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":1733139038,"i":44}},"t":1},"topOfOplog":{"ts":{"$timestamp":{"t":1733139038,"i":44}},"t":1}}} {"t":{"$date":"2024-12-02T11:36:06.037+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-12-02T11:36:06.039+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1733139366:39377][512:0x7f463a27ac00], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 37, snapshot max: 37 snapshot count: 0, oldest timestamp: (1733139038, 44) , meta checkpoint timestamp: (0, 0) base write gen: 42"}} {"t":{"$date":"2024-12-02T11:36:06.043+00:00"},"s":"I", "c":"REPL", "id":4280505, "ctx":"initandlisten","msg":"Creating any necessary TenantMigrationAccessBlockers for unfinished migrations"} {"t":{"$date":"2024-12-02T11:36:06.043+00:00"},"s":"I", "c":"REPL", "id":4280506, "ctx":"initandlisten","msg":"Reconstructing prepared transactions"} {"t":{"$date":"2024-12-02T11:36:06.043+00:00"},"s":"I", "c":"REPL", "id":4280507, "ctx":"initandlisten","msg":"Loaded replica set config, scheduled callback to set local config"} {"t":{"$date":"2024-12-02T11:36:06.043+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-12-02T11:36:06.044+00:00"},"s":"I", "c":"REPL", "id":40440, "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"} {"t":{"$date":"2024-12-02T11:36:06.044+00:00"},"s":"I", "c":"REPL", "id":40445, "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"} {"t":{"$date":"2024-12-02T11:36:06.045+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-27653.sock"}} {"t":{"$date":"2024-12-02T11:36:06.045+00:00"},"s":"I", "c":"NETWORK", "id":23015, "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}} {"t":{"$date":"2024-12-02T11:36:06.045+00:00"},"s":"I", "c":"NETWORK", "id":23016, "ctx":"listener","msg":"Waiting for connections","attr":{"port":27653,"ssl":"off"}} {"t":{"$date":"2024-12-02T11:36:06.068+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44158","uuid":"d109e5d5-f981-48f6-9d03-3181f454d1f1","connectionId":2,"connectionCount":1}} {"t":{"$date":"2024-12-02T11:36:06.069+00:00"},"s":"W", "c":"COMMAND", "id":5578800, "ctx":"conn2","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:44158"}}} {"t":{"$date":"2024-12-02T11:36:06.069+00:00"},"s":"I", "c":"REPL", "id":4280509, "ctx":"ReplCoord-0","msg":"Local configuration validated for startup"} {"t":{"$date":"2024-12-02T11:36:06.069+00:00"},"s":"I", "c":"REPL", "id":6015317, "ctx":"ReplCoord-0","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigStartingUp"}} {"t":{"$date":"2024-12-02T11:36:06.069+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn2","msg":"Connection ended","attr":{"remote":"127.0.0.1:44158","uuid":"d109e5d5-f981-48f6-9d03-3181f454d1f1","connectionId":2,"connectionCount":0}} {"t":{"$date":"2024-12-02T11:36:06.069+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:27653","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-12-02T11:36:06.069+00:00"},"s":"I", "c":"REPL", "id":21393, "ctx":"ReplCoord-0","msg":"Found self in config","attr":{"hostAndPort":"localhost:27653"}} {"t":{"$date":"2024-12-02T11:36:06.069+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"STARTUP2","oldState":"STARTUP"}} {"t":{"$date":"2024-12-02T11:36:06.069+00:00"},"s":"I", "c":"REPL", "id":21320, "ctx":"ReplCoord-0","msg":"Updated term","attr":{"term":1}} {"t":{"$date":"2024-12-02T11:36:06.069+00:00"},"s":"I", "c":"REPL", "id":21306, "ctx":"ReplCoord-0","msg":"Starting replication storage threads"} {"t":{"$date":"2024-12-02T11:36:06.069+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44162","uuid":"804405f1-152e-4700-ab3e-53bed6eda000","connectionId":3,"connectionCount":1}} {"t":{"$date":"2024-12-02T11:36:06.069+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn3","msg":"client metadata","attr":{"remote":"127.0.0.1:44162","client":"conn3","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-12-02T11:36:06.070+00:00"},"s":"I", "c":"REPL", "id":4280512, "ctx":"ReplCoord-0","msg":"No initial sync required. Attempting to begin steady replication"} {"t":{"$date":"2024-12-02T11:36:06.070+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"RECOVERING","oldState":"STARTUP2"}} {"t":{"$date":"2024-12-02T11:36:06.070+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"ReplCoord-0","msg":"createCollection","attr":{"namespace":"local.replset.initialSyncId","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"c31238dc-d52c-4a3d-9d80-3526df5c1882"}},"options":{}}} {"t":{"$date":"2024-12-02T11:36:06.070+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44178","uuid":"2ad4045d-16b9-4435-b814-f08ad739f294","connectionId":4,"connectionCount":2}} {"t":{"$date":"2024-12-02T11:36:06.070+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:44180","uuid":"a9ae3d3e-90c2-4343-bf91-32f6727290a9","connectionId":5,"connectionCount":3}} {"t":{"$date":"2024-12-02T11:36:06.070+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn4","msg":"client metadata","attr":{"remote":"127.0.0.1:44178","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-12-02T11:36:06.070+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn5","msg":"client metadata","attr":{"remote":"127.0.0.1:44180","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-12-02T11:36:06.076+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-12-02T11:36:06.076+00:00"},"s":"I", "c":"REPL", "id":21299, "ctx":"ReplCoord-0","msg":"Starting replication fetcher thread"} {"t":{"$date":"2024-12-02T11:36:06.076+00:00"},"s":"I", "c":"REPL", "id":21300, "ctx":"ReplCoord-0","msg":"Starting replication applier thread"} {"t":{"$date":"2024-12-02T11:36:06.076+00:00"},"s":"I", "c":"REPL", "id":21301, "ctx":"ReplCoord-0","msg":"Starting replication reporter thread"} {"t":{"$date":"2024-12-02T11:36:06.076+00:00"},"s":"I", "c":"REPL", "id":21224, "ctx":"OplogApplier-0","msg":"Starting oplog application"} {"t":{"$date":"2024-12-02T11:36:06.076+00:00"},"s":"I", "c":"REPL", "id":4280511, "ctx":"ReplCoord-0","msg":"Set local replica set config"} {"t":{"$date":"2024-12-02T11:36:06.077+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"OplogApplier-0","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"RECOVERING"}} {"t":{"$date":"2024-12-02T11:36:06.077+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-12-02T11:36:06.077+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-12-02T11:36:06.077+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-12-02T11:36:06.077+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-12-02T11:36:06.078+00:00"},"s":"I", "c":"ELECTION", "id":21450, "ctx":"ReplCoord-0","msg":"Election succeeded, assuming primary role","attr":{"term":2}} {"t":{"$date":"2024-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}} {"t":{"$date":"2024-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":21106, "ctx":"ReplCoord-0","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}} {"t":{"$date":"2024-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":21359, "ctx":"ReplCoord-0","msg":"Entering primary catch-up mode"} {"t":{"$date":"2024-12-02T11:36:06.078+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-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":21363, "ctx":"ReplCoord-0","msg":"Exited primary catch-up mode"} {"t":{"$date":"2024-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":21107, "ctx":"ReplCoord-0","msg":"Stopping replication producer"} {"t":{"$date":"2024-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":21239, "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":2}} {"t":{"$date":"2024-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":21239, "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":2}} {"t":{"$date":"2024-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":21343, "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"} {"t":{"$date":"2024-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":21344, "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"} {"t":{"$date":"2024-12-02T11:36:06.078+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-12-02T11:36:06.078+00:00"},"s":"I", "c":"REPL", "id":6015310, "ctx":"OplogApplier-0","msg":"Starting to transition to primary."} {"t":{"$date":"2024-12-02T11:36:06.079+00:00"},"s":"I", "c":"REPL", "id":6015309, "ctx":"OplogApplier-0","msg":"Logging transition to primary to oplog on stepup"} {"t":{"$date":"2024-12-02T11:36:06.079+00:00"},"s":"I", "c":"STORAGE", "id":20657, "ctx":"OplogApplier-0","msg":"IndexBuildsCoordinator::onStepUp - this node is stepping up to primary"} {"t":{"$date":"2024-12-02T11:36:06.079+00:00"},"s":"I", "c":"REPL", "id":21331, "ctx":"OplogApplier-0","msg":"Transition to primary complete; database writes are now permitted"} {"t":{"$date":"2024-12-02T11:36:06.079+00:00"},"s":"I", "c":"REPL", "id":6015306, "ctx":"OplogApplier-0","msg":"Applier already left draining state, exiting."} {"t":{"$date":"2024-12-02T11:36:06.079+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":"3aa1f9df-5ce3-4853-b409-13595a1fa1e0"}},"options":{}}} {"t":{"$date":"2024-12-02T11:36:06.081+00:00"},"s":"I", "c":"STORAGE", "id":22310, "ctx":"JournalFlusher","msg":"Triggering the first stable checkpoint","attr":{"initialDataTimestamp":{"$timestamp":{"t":1733139038,"i":44}},"prevStableTimestamp":{"$timestamp":{"t":0,"i":0}},"currStableTimestamp":{"$timestamp":{"t":1733139366,"i":2}}}} {"t":{"$date":"2024-12-02T11:36:06.081+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationDonors","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"7b99108e-61c9-4323-8b35-42f909138fe8"}},"options":{}}} {"t":{"$date":"2024-12-02T11:36:06.082+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationRecipientService-0","msg":"createCollection","attr":{"namespace":"config.tenantMigrationRecipients","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"e5bc1464-474e-4b59-ad11-901edd0c28de"}},"options":{}}} {"t":{"$date":"2024-12-02T11:36:06.085+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"Checkpointer","msg":"WiredTiger error","attr":{"error":2,"message":"[1733139366:85475][512:0x7f4622185700], file:collection-2--139037963103975097.wt, WT_SESSION.checkpoint: __posix_fs_size, 296: /var/lib/mongo/WiredTigerHS.wt: file-size: stat: No such file or directory"}} {"t":{"$date":"2024-12-02T11:36:06.085+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"Checkpointer","msg":"WiredTiger error","attr":{"error":2,"message":"[1733139366:85522][512:0x7f4622185700], file:collection-2--139037963103975097.wt, WT_SESSION.checkpoint: __reconcile, 351: reconciliation failed after building the disk image: No such file or directory"}} {"t":{"$date":"2024-12-02T11:36:06.085+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"Checkpointer","msg":"WiredTiger error","attr":{"error":-31804,"message":"[1733139366:85541][512:0x7f4622185700], file:collection-2--139037963103975097.wt, WT_SESSION.checkpoint: __reconcile, 351: the process must exit and restart: WT_PANIC: WiredTiger library panic"}} {"t":{"$date":"2024-12-02T11:36:06.085+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-12-02T11:36:06.085+00:00"},"s":"F", "c":"-", "id":23090, "ctx":"Checkpointer","msg":"\n\n***aborting after fassert() failure\n\n"} {"t":{"$date":"2024-12-02T11:36:06.085+00:00"},"s":"F", "c":"CONTROL", "id":6384300, "ctx":"Checkpointer","msg":"Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}} {"t":{"$date":"2024-12-02T11:36:06.093+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn4","msg":"Connection ended","attr":{"remote":"127.0.0.1:44178","uuid":"2ad4045d-16b9-4435-b814-f08ad739f294","connectionId":4,"connectionCount":1}} {"t":{"$date":"2024-12-02T11:36:06.093+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn5","msg":"Connection ended","attr":{"remote":"127.0.0.1:44180","uuid":"a9ae3d3e-90c2-4343-bf91-32f6727290a9","connectionId":5,"connectionCount":2}} {"t":{"$date":"2024-12-02T11:36:06.094+00:00"},"s":"I", "c":"-", "id":20883, "ctx":"conn3","msg":"Interrupted operation as its client disconnected","attr":{"opId":44}} {"t":{"$date":"2024-12-02T11:36:06.095+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn3","msg":"Connection ended","attr":{"remote":"127.0.0.1:44162","uuid":"804405f1-152e-4700-ab3e-53bed6eda000","connectionId":3,"connectionCount":0}} {"t":{"$date":"2024-12-02T11:36:06.099+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":1733139366,"i":3}}}} {"t":{"$date":"2024-12-02T11:36:06.101+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":1733139366,"i":6}}}} {"t":{"$date":"2024-12-02T11:36:06.101+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":1733139366,"i":6}}}} {"t":{"$date":"2024-12-02T11:36:06.101+00:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationRecipientService-1","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationRecipientService"}} {"t":{"$date":"2024-12-02T11:36:06.103+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":1733139366,"i":7}}}} {"t":{"$date":"2024-12-02T11:36:06.103+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":1733139366,"i":7}}}} {"t":{"$date":"2024-12-02T11:36:06.104+00:00"},"s":"I", "c":"STORAGE", "id":20320, "ctx":"TenantMigrationDonorService-1","msg":"createCollection","attr":{"namespace":"config.external_validation_keys","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"94a66bf3-3db3-4c8d-beea-503c2f048c6d"}},"options":{}}} {"t":{"$date":"2024-12-02T11:36:06.111+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-1","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"_id_","commitTimestamp":{"$timestamp":{"t":1733139366,"i":11}}}} {"t":{"$date":"2024-12-02T11:36:06.111+00:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"TenantMigrationDonorService-1","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.external_validation_keys","index":"ExternalKeysTTLIndex","commitTimestamp":{"$timestamp":{"t":1733139366,"i":11}}}} {"t":{"$date":"2024-12-02T11:36:06.111+00:00"},"s":"I", "c":"REPL", "id":5123005, "ctx":"TenantMigrationDonorService-1","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationDonorService"}} {"t":{"$date":"2024-12-02T11:36:06.142+00:00"},"s":"I", "c":"CONTROL", "id":31380, "ctx":"Checkpointer","msg":"BACKTRACE","attr":{"bt":{"backtrace":[{"a":"55EC34EEC9C3","b":"55EC30CCF000","o":"421D9C3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"},{"a":"55EC34EEF417","b":"55EC30CCF000","o":"4220417","s":"_ZN5mongo15printStackTraceEv","s+":"37"},{"a":"55EC34EE75B6","b":"55EC30CCF000","o":"42185B6","s":"abruptQuit","s+":"66"},{"a":"7F46379F8D80","b":"7F46379E6000","o":"12D80","s":"funlockfile","s+":"50"},{"a":"7F463765E5EF","b":"7F4637610000","o":"4E5EF","s":"gsignal","s+":"10F"},{"a":"7F4637631E65","b":"7F4637610000","o":"21E65","s":"abort","s+":"127"},{"a":"55EC3224DD6D","b":"55EC30CCF000","o":"157ED6D","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"},{"a":"55EC31D09CF4","b":"55EC30CCF000","o":"103ACF4","s":"_ZZN5mongo8RecordIdC4EPKciENKUlvE0_clEv","s+":"30B8"},{"a":"55EC325B29F3","b":"55EC30CCF000","o":"18E39F3","s":"__wt_event_handler_set","s+":"4A3"},{"a":"55EC31D1C3E3","b":"55EC30CCF000","o":"104D3E3","s":"__wt_panic_func","s+":"114"},{"a":"55EC31D18A8D","b":"55EC30CCF000","o":"1049A8D","s":"__wt_ext_map_windows_error","s+":"25CA"},{"a":"55EC32647DFA","b":"55EC30CCF000","o":"1978DFA","s":"__wt_sync_file","s+":"6AA"},{"a":"55EC325D113B","b":"55EC30CCF000","o":"190213B","s":"__wt_checkpoint_tree_reconcile_update","s+":"1CB"},{"a":"55EC325D223F","b":"55EC30CCF000","o":"190323F","s":"__wt_checkpoint_sync","s+":"99F"},{"a":"55EC325D3B76","b":"55EC30CCF000","o":"1904B76","s":"__wt_txn_checkpoint","s+":"246"},{"a":"55EC31D1B6EF","b":"55EC30CCF000","o":"104C6EF","s":"__wt_session_notsup","s+":"FCC"},{"a":"55EC324B8586","b":"55EC30CCF000","o":"17E9586","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_sessionb","s+":"46"},{"a":"55EC324C5988","b":"55EC30CCF000","o":"17F6988","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_session","s+":"2B8"},{"a":"55EC324C6050","b":"55EC30CCF000","o":"17F7050","s":"_ZN5mongo18WiredTigerKVEngine10checkpointEv","s+":"40"},{"a":"55EC3346B459","b":"55EC30CCF000","o":"279C459","s":"_ZN5mongo12Checkpointer3runEv","s+":"E59"},{"a":"55EC34CA7E32","b":"55EC30CCF000","o":"3FD8E32","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"E2"},{"a":"55EC34CA854C","b":"55EC30CCF000","o":"3FD954C","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"7FC"},{"a":"7F4638263B23","b":"7F46381A1000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"},{"a":"7F46379EE1DA","b":"7F46379E6000","o":"81DA","s":"start_thread","s+":"EA"},{"a":"7F46376498D3","b":"7F4637610000","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":"55EC30CCF000","elfType":3,"buildId":"539E2C825673723B04D19874D3C9DF6EB9A69E4F"},{"b":"7F46381A1000","path":"/lib64/libstdc++.so.6","elfType":3,"buildId":"41809D0B18272BC525772714DA54108BF1C59253"},{"b":"7F46379E6000","path":"/lib64/libpthread.so.0","elfType":3,"buildId":"0B813C2AD185DCA27DDB58BA42ACC172679B1526"},{"b":"7F4637610000","path":"/lib64/libc.so.6","elfType":3,"buildId":"BF4C06A1D77241A2D30436873E56C348FCBB5D22"}]}}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC34EEC9C3","b":"55EC30CCF000","o":"421D9C3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC34EEF417","b":"55EC30CCF000","o":"4220417","s":"_ZN5mongo15printStackTraceEv","s+":"37"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC34EE75B6","b":"55EC30CCF000","o":"42185B6","s":"abruptQuit","s+":"66"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F46379F8D80","b":"7F46379E6000","o":"12D80","s":"funlockfile","s+":"50"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F463765E5EF","b":"7F4637610000","o":"4E5EF","s":"gsignal","s+":"10F"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F4637631E65","b":"7F4637610000","o":"21E65","s":"abort","s+":"127"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC3224DD6D","b":"55EC30CCF000","o":"157ED6D","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC31D09CF4","b":"55EC30CCF000","o":"103ACF4","s":"_ZZN5mongo8RecordIdC4EPKciENKUlvE0_clEv","s+":"30B8"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC325B29F3","b":"55EC30CCF000","o":"18E39F3","s":"__wt_event_handler_set","s+":"4A3"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC31D1C3E3","b":"55EC30CCF000","o":"104D3E3","s":"__wt_panic_func","s+":"114"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC31D18A8D","b":"55EC30CCF000","o":"1049A8D","s":"__wt_ext_map_windows_error","s+":"25CA"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC32647DFA","b":"55EC30CCF000","o":"1978DFA","s":"__wt_sync_file","s+":"6AA"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC325D113B","b":"55EC30CCF000","o":"190213B","s":"__wt_checkpoint_tree_reconcile_update","s+":"1CB"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC325D223F","b":"55EC30CCF000","o":"190323F","s":"__wt_checkpoint_sync","s+":"99F"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC325D3B76","b":"55EC30CCF000","o":"1904B76","s":"__wt_txn_checkpoint","s+":"246"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC31D1B6EF","b":"55EC30CCF000","o":"104C6EF","s":"__wt_session_notsup","s+":"FCC"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC324B8586","b":"55EC30CCF000","o":"17E9586","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_sessionb","s+":"46"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC324C5988","b":"55EC30CCF000","o":"17F6988","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_session","s+":"2B8"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC324C6050","b":"55EC30CCF000","o":"17F7050","s":"_ZN5mongo18WiredTigerKVEngine10checkpointEv","s+":"40"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC3346B459","b":"55EC30CCF000","o":"279C459","s":"_ZN5mongo12Checkpointer3runEv","s+":"E59"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC34CA7E32","b":"55EC30CCF000","o":"3FD8E32","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"E2"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"55EC34CA854C","b":"55EC30CCF000","o":"3FD954C","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"7FC"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F4638263B23","b":"7F46381A1000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F46379EE1DA","b":"7F46379E6000","o":"81DA","s":"start_thread","s+":"EA"}}} {"t":{"$date":"2024-12-02T11:36:06.143+00:00"},"s":"I", "c":"CONTROL", "id":31445, "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F46376498D3","b":"7F4637610000","o":"398D3","s":"clone","s+":"43"}}}

Process completed with exit code 1.

AssertionError: assert 'old_index' not in {'_id_': {'key': [('_id', 1)], 'v': 2}, 'new_index': {'key': [('data', 1)], 'v': 2}, 'old_index': {'key': [('key', 1)], 'v': 2}} + where {'_id_': {'key': [('_id', 1)], 'v': 2}, 'new_index': {'key': [('data', 1)], 'v': 2}, 'old_index': {'key': [('key', 1)], 'v': 2}} = index_information() + where index_information = Collection(Database(MongoClient(host=['rs101:27017'], document_class=dict, tz_aware=False, connect=True), 'restored'), 'indexes').index_information

AssertionError: Backup failed{"Error":"get backup metadata: get: context deadline exceeded"} 2024-12-02T12:03:59Z I [rs2/rs201:27017] % _____ %%% | __ \ ###%%%%%%%%%%%%* | |__) |__ _ __ ___ ___ _ __ __ _ ### ##%% %%%% | ___/ _ \ '__/ __/ _ \| '_ \ / _` | #### ##% %%%% | | | __/ | | (_| (_) | | | | (_| | ### #### %%% |_| \___|_| \___\___/|_| |_|\__,_| ,((### ### %%% _____ _ (((( (### #### %%%% / ____| | | ((( ((# ###### | (___ __ _ _ _ __ _ __| | (((( (((# #### \___ \ / _` | | | |/ _` |/ _` | /(( ,((( *### ____) | (_| | |_| | (_| | (_| | //// ((( #### |_____/ \__, |\__,_|\__,_|\__,_| /// (((( #### | | /////////////(((((((((((((((((######## |_| Join @ squad.percona.com/mongodb ** Join Percona Squad! ** Participate in monthly SWAG raffles, get early access to new product features, invite-only ”ask me anything” sessions with database performance experts. Interested? Fill in the form at squad.percona.com/mongodb 2024-12-02T12:03:59Z I [rs2/rs201:27017] log options: log-path=/dev/stderr, log-level:D, log-json:false 2024-12-02T12:03:59Z I [rs1/rs101:27017] % _____ %%% | __ \ ###%%%%%%%%%%%%* | |__) |__ _ __ ___ ___ _ __ __ _ ### ##%% %%%% | ___/ _ \ '__/ __/ _ \| '_ \ / _` | #### ##% %%%% | | | __/ | | (_| (_) | | | | (_| | ### #### %%% |_| \___|_| \___\___/|_| |_|\__,_| ,((### ### %%% _____ _ (((( (### #### %%%% / ____| | | ((( ((# ###### | (___ __ _ _ _ __ _ __| | (((( (((# #### \___ \ / _` | | | |/ _` |/ _` | /(( ,((( *### ____) | (_| | |_| | (_| | (_| | //// ((( #### |_____/ \__, |\__,_|\__,_|\__,_| /// (((( #### | | /////////////(((((((((((((((((######## |_| Join @ squad.percona.com/mongodb ** Join Percona Squad! ** Participate in monthly SWAG raffles, get early access to new product features, invite-only ”ask me anything” sessions with database performance experts. Interested? Fill in the form at squad.percona.com/mongodb 2024-12-02T12:03:59Z I [rs2/rs201:27017] pbm-agent: Version: 2.7.0 Platform: linux/amd64 GitCommit: 44b7141b76d5e4a1c87ecf4878102eaceb7e8c0f GitBranch: dev BuildTime: 2024-12-02_11:18_UTC GoVersion: go1.23.3 2024-12-02T12:03:59Z I [rs2/rs201:27017] starting PITR routine 2024-12-02T12:03:59Z I [rs1/rs101:27017] log options: log-path=/dev/stderr, log-level:D, log-json:false 2024-12-02T12:03:59Z I [rs1/rs103:27017] % _____ %%% | __ \ ###%%%%%%%%%%%%* | |__) |__ _ __ ___ ___ _ __ __ _ ### ##%% %%%% | ___/ _ \ '__/ __/ _ \| '_ \ / _` | #### ##% %%%% | | | __/ | | (_| (_) | | | | (_| | ### #### %%% |_| \___|_| \___\___/|_| |_|\__,_| ,((### ### %%% _____ _ (((( (### #### %%%% / ____| | | ((( ((# ###### | (___ __ _ _ _ __ _ __| | (((( (((# #### \___ \ / _` | | | |/ _` |/ _` | /(( ,((( *### ____) | (_| | |_| | (_| | (_| | //// ((( #### |_____/ \__, |\__,_|\__,_|\__,_| /// (((( #### | | /////////////(((((((((((((((((######## |_| Join @ squad.percona.com/mongodb ** Join Percona Squad! ** Participate in monthly SWAG raffles, get early access to new product features, invite-only ”ask me anything” sessions with database performance experts. Interested? Fill in the form at squad.percona.com/mongodb 2024-12-02T12:03:59Z E [rs2/rs201:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:03:59Z I [rs2/rs201:27017] node: rs2/rs201:27017 2024-12-02T12:03:59Z I [rs1/rs102:27017] % _____ %%% | __ \ ###%%%%%%%%%%%%* | |__) |__ _ __ ___ ___ _ __ __ _ ### ##%% %%%% | ___/ _ \ '__/ __/ _ \| '_ \ / _` | #### ##% %%%% | | | __/ | | (_| (_) | | | | (_| | ### #### %%% |_| \___|_| \___\___/|_| |_|\__,_| ,((### ### %%% _____ _ (((( (### #### %%%% / ____| | | ((( ((# ###### | (___ __ _ _ _ __ _ __| | (((( (((# #### \___ \ / _` | | | |/ _` |/ _` | /(( ,((( *### ____) | (_| | |_| | (_| | (_| | //// ((( #### |_____/ \__, |\__,_|\__,_|\__,_| /// (((( #### | | /////////////(((((((((((((((((######## |_| Join @ squad.percona.com/mongodb ** Join Percona Squad! ** Participate in monthly SWAG raffles, get early access to new product features, invite-only ”ask me anything” sessions with database performance experts. Interested? Fill in the form at squad.percona.com/mongodb 2024-12-02T12:03:59Z I [rs1/rs101:27017] pbm-agent: Version: 2.7.0 Platform: linux/amd64 GitCommit: 44b7141b76d5e4a1c87ecf4878102eaceb7e8c0f GitBranch: dev BuildTime: 2024-12-02_11:18_UTC GoVersion: go1.23.3 2024-12-02T12:03:59Z I [rs1/rs101:27017] starting PITR routine 2024-12-02T12:03:59Z I [rs1/rs103:27017] log options: log-path=/dev/stderr, log-level:D, log-json:false 2024-12-02T12:03:59Z I [rs1/rs102:27017] log options: log-path=/dev/stderr, log-level:D, log-json:false 2024-12-02T12:03:59Z I [rs1/rs101:27017] node: rs1/rs101:27017 2024-12-02T12:03:59Z I [rs2/rs201:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-12-02T12:03:59Z I [rs1/rs103:27017] pbm-agent: Version: 2.7.0 Platform: linux/amd64 GitCommit: 44b7141b76d5e4a1c87ecf4878102eaceb7e8c0f GitBranch: dev BuildTime: 2024-12-02_11:18_UTC GoVersion: go1.23.3 2024-12-02T12:03:59Z I [rs1/rs103:27017] starting PITR routine 2024-12-02T12:03:59Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:03:59Z I [rs2/rs201:27017] listening for the commands 2024-12-02T12:03:59Z I [rs1/rs102:27017] pbm-agent: Version: 2.7.0 Platform: linux/amd64 GitCommit: 44b7141b76d5e4a1c87ecf4878102eaceb7e8c0f GitBranch: dev BuildTime: 2024-12-02_11:18_UTC GoVersion: go1.23.3 2024-12-02T12:03:59Z I [rs1/rs102:27017] starting PITR routine 2024-12-02T12:03:59Z I [rs1/rs103:27017] node: rs1/rs103:27017 2024-12-02T12:03:59Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-12-02T12:03:59Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:03:59Z I [rs1/rs102:27017] node: rs1/rs102:27017 2024-12-02T12:03:59Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-12-02T12:03:59Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:03:59Z I [rs1/rs101:27017] listening for the commands 2024-12-02T12:03:59Z I [rs1/rs103:27017] listening for the commands 2024-12-02T12:03:59Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-12-02T12:03:59Z I [rs1/rs102:27017] listening for the commands 2024-12-02T12:04:00Z I [rscfg/rscfg01:27017] % _____ %%% | __ \ ###%%%%%%%%%%%%* | |__) |__ _ __ ___ ___ _ __ __ _ ### ##%% %%%% | ___/ _ \ '__/ __/ _ \| '_ \ / _` | #### ##% %%%% | | | __/ | | (_| (_) | | | | (_| | ### #### %%% |_| \___|_| \___\___/|_| |_|\__,_| ,((### ### %%% _____ _ (((( (### #### %%%% / ____| | | ((( ((# ###### | (___ __ _ _ _ __ _ __| | (((( (((# #### \___ \ / _` | | | |/ _` |/ _` | /(( ,((( *### ____) | (_| | |_| | (_| | (_| | //// ((( #### |_____/ \__, |\__,_|\__,_|\__,_| /// (((( #### | | /////////////(((((((((((((((((######## |_| Join @ squad.percona.com/mongodb ** Join Percona Squad! ** Participate in monthly SWAG raffles, get early access to new product features, invite-only ”ask me anything” sessions with database performance experts. Interested? Fill in the form at squad.percona.com/mongodb 2024-12-02T12:04:00Z I [rscfg/rscfg02:27017] % _____ %%% | __ \ ###%%%%%%%%%%%%* | |__) |__ _ __ ___ ___ _ __ __ _ ### ##%% %%%% | ___/ _ \ '__/ __/ _ \| '_ \ / _` | #### ##% %%%% | | | __/ | | (_| (_) | | | | (_| | ### #### %%% |_| \___|_| \___\___/|_| |_|\__,_| ,((### ### %%% _____ _ (((( (### #### %%%% / ____| | | ((( ((# ###### | (___ __ _ _ _ __ _ __| | (((( (((# #### \___ \ / _` | | | |/ _` |/ _` | /(( ,((( *### ____) | (_| | |_| | (_| | (_| | //// ((( #### |_____/ \__, |\__,_|\__,_|\__,_| /// (((( #### | | /////////////(((((((((((((((((######## |_| Join @ squad.percona.com/mongodb ** Join Percona Squad! ** Participate in monthly SWAG raffles, get early access to new product features, invite-only ”ask me anything” sessions with database performance experts. Interested? Fill in the form at squad.percona.com/mongodb 2024-12-02T12:04:00Z I [rscfg/rscfg01:27017] log options: log-path=/dev/stderr, log-level:D, log-json:false 2024-12-02T12:04:00Z I [rscfg/rscfg02:27017] log options: log-path=/dev/stderr, log-level:D, log-json:false 2024-12-02T12:04:00Z I [rscfg/rscfg01:27017] pbm-agent: Version: 2.7.0 Platform: linux/amd64 GitCommit: 44b7141b76d5e4a1c87ecf4878102eaceb7e8c0f GitBranch: dev BuildTime: 2024-12-02_11:18_UTC GoVersion: go1.23.3 2024-12-02T12:04:00Z I [rscfg/rscfg01:27017] starting PITR routine 2024-12-02T12:04:00Z I [rs2/rs203:27017] % _____ %%% | __ \ ###%%%%%%%%%%%%* | |__) |__ _ __ ___ ___ _ __ __ _ ### ##%% %%%% | ___/ _ \ '__/ __/ _ \| '_ \ / _` | #### ##% %%%% | | | __/ | | (_| (_) | | | | (_| | ### #### %%% |_| \___|_| \___\___/|_| |_|\__,_| ,((### ### %%% _____ _ (((( (### #### %%%% / ____| | | ((( ((# ###### | (___ __ _ _ _ __ _ __| | (((( (((# #### \___ \ / _` | | | |/ _` |/ _` | /(( ,((( *### ____) | (_| | |_| | (_| | (_| | //// ((( #### |_____/ \__, |\__,_|\__,_|\__,_| /// (((( #### | | /////////////(((((((((((((((((######## |_| Join @ squad.percona.com/mongodb ** Join Percona Squad! ** Participate in monthly SWAG raffles, get early access to new product features, invite-only ”ask me anything” sessions with database performance experts. Interested? Fill in the form at squad.percona.com/mongodb 2024-12-02T12:04:00Z I [rs2/rs202:27017] % _____ %%% | __ \ ###%%%%%%%%%%%%* | |__) |__ _ __ ___ ___ _ __ __ _ ### ##%% %%%% | ___/ _ \ '__/ __/ _ \| '_ \ / _` | #### ##% %%%% | | | __/ | | (_| (_) | | | | (_| | ### #### %%% |_| \___|_| \___\___/|_| |_|\__,_| ,((### ### %%% _____ _ (((( (### #### %%%% / ____| | | ((( ((# ###### | (___ __ _ _ _ __ _ __| | (((( (((# #### \___ \ / _` | | | |/ _` |/ _` | /(( ,((( *### ____) | (_| | |_| | (_| | (_| | //// ((( #### |_____/ \__, |\__,_|\__,_|\__,_| /// (((( #### | | /////////////(((((((((((((((((######## |_| Join @ squad.percona.com/mongodb ** Join Percona Squad! ** Participate in monthly SWAG raffles, get early access to new product features, invite-only ”ask me anything” sessions with database performance experts. Interested? Fill in the form at squad.percona.com/mongodb 2024-12-02T12:04:00Z I [rscfg/rscfg02:27017] pbm-agent: Version: 2.7.0 Platform: linux/amd64 GitCommit: 44b7141b76d5e4a1c87ecf4878102eaceb7e8c0f GitBranch: dev BuildTime: 2024-12-02_11:18_UTC GoVersion: go1.23.3 2024-12-02T12:04:00Z I [rscfg/rscfg02:27017] starting PITR routine 2024-12-02T12:04:00Z E [rscfg/rscfg01:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:00Z I [rscfg/rscfg01:27017] node: rscfg/rscfg01:27017 2024-12-02T12:04:00Z I [rs2/rs202:27017] log options: log-path=/dev/stderr, log-level:D, log-json:false 2024-12-02T12:04:00Z I [rscfg/rscfg02:27017] node: rscfg/rscfg02:27017 2024-12-02T12:04:00Z I [rscfg/rscfg01:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-12-02T12:04:00Z I [rs2/rs203:27017] log options: log-path=/dev/stderr, log-level:D, log-json:false 2024-12-02T12:04:00Z E [rscfg/rscfg02:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:00Z I [rs2/rs202:27017] pbm-agent: Version: 2.7.0 Platform: linux/amd64 GitCommit: 44b7141b76d5e4a1c87ecf4878102eaceb7e8c0f GitBranch: dev BuildTime: 2024-12-02_11:18_UTC GoVersion: go1.23.3 2024-12-02T12:04:00Z I [rs2/rs202:27017] starting PITR routine 2024-12-02T12:04:00Z I [rscfg/rscfg02:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-12-02T12:04:00Z I [rscfg/rscfg01:27017] listening for the commands 2024-12-02T12:04:00Z I [rs2/rs203:27017] pbm-agent: Version: 2.7.0 Platform: linux/amd64 GitCommit: 44b7141b76d5e4a1c87ecf4878102eaceb7e8c0f GitBranch: dev BuildTime: 2024-12-02_11:18_UTC GoVersion: go1.23.3 2024-12-02T12:04:00Z I [rs2/rs203:27017] starting PITR routine 2024-12-02T12:04:00Z I [rs2/rs202:27017] node: rs2/rs202:27017 2024-12-02T12:04:00Z E [rs2/rs202:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:00Z I [rscfg/rscfg02:27017] listening for the commands 2024-12-02T12:04:00Z I [rs2/rs202:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-12-02T12:04:00Z I [rs2/rs203:27017] node: rs2/rs203:27017 2024-12-02T12:04:00Z I [rs2/rs202:27017] listening for the commands 2024-12-02T12:04:00Z E [rs2/rs203:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:01Z I [rs2/rs203:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-12-02T12:04:01Z I [rs2/rs203:27017] listening for the commands 2024-12-02T12:04:02Z I [rscfg/rscfg03:27017] % _____ %%% | __ \ ###%%%%%%%%%%%%* | |__) |__ _ __ ___ ___ _ __ __ _ ### ##%% %%%% | ___/ _ \ '__/ __/ _ \| '_ \ / _` | #### ##% %%%% | | | __/ | | (_| (_) | | | | (_| | ### #### %%% |_| \___|_| \___\___/|_| |_|\__,_| ,((### ### %%% _____ _ (((( (### #### %%%% / ____| | | ((( ((# ###### | (___ __ _ _ _ __ _ __| | (((( (((# #### \___ \ / _` | | | |/ _` |/ _` | /(( ,((( *### ____) | (_| | |_| | (_| | (_| | //// ((( #### |_____/ \__, |\__,_|\__,_|\__,_| /// (((( #### | | /////////////(((((((((((((((((######## |_| Join @ squad.percona.com/mongodb ** Join Percona Squad! ** Participate in monthly SWAG raffles, get early access to new product features, invite-only ”ask me anything” sessions with database performance experts. Interested? Fill in the form at squad.percona.com/mongodb 2024-12-02T12:04:02Z I [rscfg/rscfg03:27017] log options: log-path=/dev/stderr, log-level:D, log-json:false 2024-12-02T12:04:02Z I [rscfg/rscfg03:27017] pbm-agent: Version: 2.7.0 Platform: linux/amd64 GitCommit: 44b7141b76d5e4a1c87ecf4878102eaceb7e8c0f GitBranch: dev BuildTime: 2024-12-02_11:18_UTC GoVersion: go1.23.3 2024-12-02T12:04:02Z I [rscfg/rscfg03:27017] starting PITR routine 2024-12-02T12:04:02Z I [rscfg/rscfg03:27017] node: rscfg/rscfg03:27017 2024-12-02T12:04:02Z E [rscfg/rscfg03:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:02Z I [rscfg/rscfg03:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-12-02T12:04:02Z I [rscfg/rscfg03:27017] listening for the commands 2024-12-02T12:04:04Z E [rs2/rs201:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:04Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:04Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:04Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:05Z E [rscfg/rscfg01:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:05Z E [rscfg/rscfg02:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:06Z E [rs2/rs202:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:06Z E [rs2/rs203:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:07Z E [rscfg/rscfg03:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-12-02T12:04:08Z I [rscfg/rscfg01:27017] got command resync <ts: 1733141048>, opid: 674da238b59b69e927b15c90 2024-12-02T12:04:08Z I [rscfg/rscfg01:27017] got epoch {1733141047 3} 2024-12-02T12:04:08Z I [rscfg/rscfg02:27017] got command resync <ts: 1733141048>, opid: 674da238b59b69e927b15c90 2024-12-02T12:04:09Z I [rs2/rs202:27017] got command resync <ts: 1733141048>, opid: 674da238b59b69e927b15c90 2024-12-02T12:04:09Z I [rscfg/rscfg02:27017] got epoch {1733141047 3} 2024-12-02T12:04:09Z I [rs2/rs203:27017] got command resync <ts: 1733141048>, opid: 674da238b59b69e927b15c90 2024-12-02T12:04:09Z I [rs2/rs202:27017] got epoch {1733141047 3} 2024-12-02T12:04:09Z I [rscfg/rscfg01:27017] [resync] started 2024-12-02T12:04:09Z I [rs2/rs202:27017] [resync] not a member of the leader rs 2024-12-02T12:04:09Z I [rs2/rs203:27017] got epoch {1733141047 3} 2024-12-02T12:04:09Z I [rs2/rs203:27017] [resync] not a member of the leader rs 2024-12-02T12:04:09Z D [rscfg/rscfg02:27017] [resync] lock not acquired 2024-12-02T12:04:09Z D [rscfg/rscfg01:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)] 2024-12-02T12:04:09Z D [rscfg/rscfg01:27017] [resync] got backups list: 0 2024-12-02T12:04:09Z D [rscfg/rscfg01:27017] [resync] got physical restores list: 0 2024-12-02T12:04:09Z D [rscfg/rscfg01:27017] [resync] epoch set to {1733141049 15} 2024-12-02T12:04:09Z I [rscfg/rscfg01:27017] [resync] succeed 2024-12-02T12:04:09Z I [rs2/rs201:27017] got command resync <ts: 1733141048>, opid: 674da238b59b69e927b15c90 2024-12-02T12:04:09Z I [rs2/rs201:27017] got epoch {1733141049 15} 2024-12-02T12:04:09Z I [rs2/rs201:27017] [resync] not a member of the leader rs 2024-12-02T12:04:09Z I [rs1/rs101:27017] got command resync <ts: 1733141048>, opid: 674da238b59b69e927b15c90 2024-12-02T12:04:09Z I [rs1/rs101:27017] got epoch {1733141049 15} 2024-12-02T12:04:09Z I [rs1/rs103:27017] got command resync <ts: 1733141048>, opid: 674da238b59b69e927b15c90 2024-12-02T12:04:09Z I [rs1/rs101:27017] [resync] not a member of the leader rs 2024-12-02T12:04:09Z I [rs1/rs102:27017] got command resync <ts: 1733141048>, opid: 674da238b59b69e927b15c90 2024-12-02T12:04:09Z I [rs1/rs103:27017] got epoch {1733141049 15} 2024-12-02T12:04:09Z I [rs1/rs102:27017] got epoch {1733141049 15} 2024-12-02T12:04:09Z I [rs1/rs103:27017] [resync] not a member of the leader rs 2024-12-02T12:04:09Z I [rs1/rs102:27017] [resync] not a member of the leader rs 2024-12-02T12:04:09Z I [rscfg/rscfg03:27017] got command resync <ts: 1733141048>, opid: 674da238b59b69e927b15c90 2024-12-02T12:04:09Z I [rscfg/rscfg03:27017] got epoch {1733141049 15} 2024-12-02T12:04:09Z D [rscfg/rscfg03:27017] [resync] get lock: duplicate operation: 674da238b59b69e927b15c90 [Resync storage] 2024-12-02T12:04:09Z D [rscfg/rscfg03:27017] [resync] lock not acquired 2024-12-02T12:04:14Z I [rs2/rs201:27017] got command resync <ts: 1733141054>, opid: 674da23e44e0b8d071d84a72 2024-12-02T12:04:14Z I [rs2/rs201:27017] got epoch {1733141049 15} 2024-12-02T12:04:14Z I [rs1/rs101:27017] got command resync <ts: 1733141054>, opid: 674da23e44e0b8d071d84a72 2024-12-02T12:04:14Z I [rs1/rs101:27017] got epoch {1733141049 15} 2024-12-02T12:04:14Z I [rs1/rs103:27017] got command resync <ts: 1733141054>, opid: 674da23e44e0b8d071d84a72 2024-12-02T12:04:14Z I [rs1/rs101:27017] [resync] not a member of the leader rs 2024-12-02T12:04:14Z I [rs2/rs201:27017] [resync] not a member of the leader rs 2024-12-02T12:04:14Z I [rs1/rs102:27017] got command resync <ts: 1733141054>, opid: 674da23e44e0b8d071d84a72 2024-12-02T12:04:14Z I [rs1/rs103:27017] got epoch {1733141049 15} 2024-12-02T12:04:14Z I [rs1/rs102:27017] got epoch {1733141049 15} 2024-12-02T12:04:14Z I [rs1/rs103:27017] [resync] not a member of the leader rs 2024-12-02T12:04:14Z I [rs1/rs102:27017] [resync] not a member of the leader rs 2024-12-02T12:04:14Z W [rs2/rs201:27017] [agentCheckup] storage is not initialized 2024-12-02T12:04:14Z W [rs1/rs101:27017] [agentCheckup] storage is not initialized 2024-12-02T12:04:14Z W [rs1/rs103:27017] [agentCheckup] storage is not initialized 2024-12-02T12:04:14Z W [rs1/rs102:27017] [agentCheckup] storage is not initialized 2024-12-02T12:04:14Z I [rscfg/rscfg03:27017] got command resync <ts: 1733141054>, opid: 674da23e44e0b8d071d84a72 2024-12-02T12:04:14Z I [rscfg/rscfg03:27017] got epoch {1733141049 15} 2024-12-02T12:04:14Z I [rscfg/rscfg03:27017] [resync] started 2024-12-02T12:04:14Z D [rscfg/rscfg03:27017] [resync] BufferSize is set to 10485760 (~10Mb) | 5 2024-12-02T12:04:14Z D [rscfg/rscfg03:27017] [resync] got backups list: 0 2024-12-02T12:04:14Z D [rscfg/rscfg03:27017] [resync] got physical restores list: 0 2024-12-02T12:04:14Z D [rscfg/rscfg03:27017] [resync] epoch set to {1733141054 157} 2024-12-02T12:04:14Z I [rscfg/rscfg03:27017] [resync] succeed 2024-12-02T12:04:15Z I [rscfg/rscfg01:27017] got command resync <ts: 1733141054>, opid: 674da23e44e0b8d071d84a72 2024-12-02T12:04:15Z I [rscfg/rscfg02:27017] got command resync <ts: 1733141054>, opid: 674da23e44e0b8d071d84a72 2024-12-02T12:04:15Z I [rscfg/rscfg01:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z I [rscfg/rscfg02:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z D [rscfg/rscfg02:27017] [resync] lock not acquired 2024-12-02T12:04:15Z D [rscfg/rscfg01:27017] [resync] get lock: duplicate operation: 674da23e44e0b8d071d84a72 [Resync storage] 2024-12-02T12:04:15Z I [rs2/rs202:27017] got command resync <ts: 1733141054>, opid: 674da23e44e0b8d071d84a72 2024-12-02T12:04:15Z I [rscfg/rscfg02:27017] got command backup [name: 2024-12-02T12:04:14Z, compression: s2 (level: default)] <ts: 1733141054>, opid: 674da23e3be4e88f45cdd8cf 2024-12-02T12:04:15Z I [rs2/rs203:27017] got command resync <ts: 1733141054>, opid: 674da23e44e0b8d071d84a72 2024-12-02T12:04:15Z I [rs2/rs202:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z D [rscfg/rscfg01:27017] [resync] lock not acquired 2024-12-02T12:04:15Z I [rs2/rs203:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z I [rscfg/rscfg02:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z I [rs2/rs202:27017] [resync] not a member of the leader rs 2024-12-02T12:04:15Z I [rs2/rs203:27017] [resync] not a member of the leader rs 2024-12-02T12:04:15Z I [rs2/rs202:27017] got command backup [name: 2024-12-02T12:04:14Z, compression: s2 (level: default)] <ts: 1733141054>, opid: 674da23e3be4e88f45cdd8cf 2024-12-02T12:04:15Z I [rs2/rs203:27017] got command backup [name: 2024-12-02T12:04:14Z, compression: s2 (level: default)] <ts: 1733141054>, opid: 674da23e3be4e88f45cdd8cf 2024-12-02T12:04:15Z I [rs2/rs203:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z I [rs2/rs202:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z I [rs2/rs201:27017] got command backup [name: 2024-12-02T12:04:14Z, compression: s2 (level: default)] <ts: 1733141054>, opid: 674da23e3be4e88f45cdd8cf 2024-12-02T12:04:15Z I [rs2/rs201:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z I [rs1/rs101:27017] got command backup [name: 2024-12-02T12:04:14Z, compression: s2 (level: default)] <ts: 1733141054>, opid: 674da23e3be4e88f45cdd8cf 2024-12-02T12:04:15Z I [rs1/rs101:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z I [rs1/rs103:27017] got command backup [name: 2024-12-02T12:04:14Z, compression: s2 (level: default)] <ts: 1733141054>, opid: 674da23e3be4e88f45cdd8cf 2024-12-02T12:04:15Z I [rs1/rs103:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z I [rs1/rs102:27017] got command backup [name: 2024-12-02T12:04:14Z, compression: s2 (level: default)] <ts: 1733141054>, opid: 674da23e3be4e88f45cdd8cf 2024-12-02T12:04:15Z I [rs1/rs102:27017] got epoch {1733141054 157} 2024-12-02T12:04:15Z I [rscfg/rscfg03:27017] got command backup [name: 2024-12-02T12:04:14Z, compression: s2 (level: default)] <ts: 1733141054>, opid: 674da23e3be4e88f45cdd8cf 2024-12-02T12:04:15Z I [rscfg/rscfg03:27017] got epoch {1733141054 157} 2024-12-02T12:04:30Z D [rscfg/rscfg02:27017] [backup/2024-12-02T12:04:14Z] nomination timeout 2024-12-02T12:04:30Z D [rscfg/rscfg02:27017] [backup/2024-12-02T12:04:14Z] skip after nomination, probably started by another node 2024-12-02T12:04:30Z D [rs2/rs202:27017] [backup/2024-12-02T12:04:14Z] nomination timeout 2024-12-02T12:04:30Z D [rs2/rs203:27017] [backup/2024-12-02T12:04:14Z] nomination timeout 2024-12-02T12:04:30Z D [rs2/rs202:27017] [backup/2024-12-02T12:04:14Z] skip after nomination, probably started by another node 2024-12-02T12:04:30Z D [rs2/rs203:27017] [backup/2024-12-02T12:04:14Z] skip after nomination, probably started by another node 2024-12-02T12:04:30Z D [rs2/rs201:27017] [backup/2024-12-02T12:04:14Z] nomination timeout 2024-12-02T12:04:30Z D [rs2/rs201:27017] [backup/2024-12-02T12:04:14Z] skip after nomination, probably started by another node 2024-12-02T12:04:30Z D [rs1/rs101:27017] [backup/2024-12-02T12:04:14Z] nomination timeout 2024-12-02T12:04:30Z D [rs1/rs101:27017] [backup/2024-12-02T12:04:14Z] skip after nomination, probably started by another node 2024-12-02T12:04:30Z D [rs1/rs103:27017] [backup/2024-12-02T12:04:14Z] nomination timeout 2024-12-02T12:04:30Z D [rs1/rs103:27017] [backup/2024-12-02T12:04:14Z] skip after nomination, probably started by another node 2024-12-02T12:04:30Z D [rs1/rs102:27017] [backup/2024-12-02T12:04:14Z] nomination timeout 2024-12-02T12:04:30Z D [rs1/rs102:27017] [backup/2024-12-02T12:04:14Z] skip after nomination, probably started by another node 2024-12-02T12:04:30Z D [rscfg/rscfg03:27017] [backup/2024-12-02T12:04:14Z] nomination timeout 2024-12-02T12:04:30Z D [rscfg/rscfg03:27017] [backup/2024-12-02T12:04:14Z] skip after nomination, probably started by another node

AssertionError: assert 'old_index' not in {'_id_': {'key': [('_id', 1)], 'v': 2}, 'new_index': {'key': [('data', 1)], 'v': 2}, 'old_index': {'key': [('key', 1)], 'v': 2}} + where {'_id_': {'key': [('_id', 1)], 'v': 2}, 'new_index': {'key': [('data', 1)], 'v': 2}, 'old_index': {'key': [('key', 1)], 'v': 2}} = index_information() + where index_information = Collection(Database(MongoClient(host=['rs101:27017'], document_class=dict, tz_aware=False, connect=True), 'restored'), 'indexes').index_information

Process completed with exit code 1.

Process completed with exit code 1.

AssertionError: assert 'old_index' not in {'_id_': {'key': [('_id', 1)], 'v': 2}, 'new_index': {'key': [('data', 1)], 'v': 2}, 'old_index': {'key': [('key', 1)], 'v': 2}} + where {'_id_': {'key': [('_id', 1)], 'v': 2}, 'new_index': {'key': [('data', 1)], 'v': 2}, 'old_index': {'key': [('key', 1)], 'v': 2}} = index_information() + where index_information = Collection(Database(MongoClient(host=['rs101:27017'], document_class=dict, tz_aware=False, connect=True), 'restored'), 'indexes').index_information

Process completed with exit code 1.

AssertionError: assert 'old_index' not in {'_id_': {'key': [('_id', 1)], 'v': 2}, 'new_index': {'key': [('data', 1)], 'v': 2}, 'old_index': {'key': [('key', 1)], 'v': 2}} + where {'_id_': {'key': [('_id', 1)], 'v': 2}, 'new_index': {'key': [('data', 1)], 'v': 2}, 'old_index': {'key': [('key', 1)], 'v': 2}} = index_information() + where index_information = Collection(Database(MongoClient(host=['rs101:27017'], document_class=dict, tz_aware=False, connect=True), 'restored'), 'indexes').index_information

Process completed with exit code 1.

The job running on runner GitHub Actions 8 has exceeded the maximum execution time of 120 minutes.