start_cluster = True, cluster = <cluster.Cluster object at 0x7fe12c9cfcd0>
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 0x7fe12c9cfcd0>
name = '--time=2024-10-22T08:46:45'
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 0x7fe12cb83d50>, 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-10-22T08:48:47.436+00:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"main","msg":"Initialize...ckpointer","msg":"Frame","attr":{"frame":{"a":"7F9251D868D3","b":"7F9251D4D000","o":"398D3","s":"clone","s+":"43"}}}\n'
host = 'rscfg01', container = <Container: da1c92f31c81>

    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-10-22T08:48:08.246069778Z to point-in-time 2024-10-22T08:46:45 from '2024-10-22T08:43:04Z'..........................Started physical restore.
E               Waiting to finish..............Error: operation failed with: replay pitr oplog: reply oplog: replay chunk 1729586587.1729586650: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1729586621,"I":4},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"test.test","Object":[{"Key":"_id","Value":"671765bd8cb7972063aeb2bc"},{"Key":"doc","Value":3}],"Query":[{"Key":"_id","Value":"671765bd8cb7972063aeb2bc"}],"UI":{"Subtype":4,"Data":"/GEyuFTKSuCP47Rr5kEDhw=="},"LSID":"SAAAAAVpZAAQAAAABB+PjpREiUKYi+PbIejt9A4FdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA","TxnNumber":4,"PrevOpTime":"HAAAABF0cwAAAAAAAAAAABJ0AP//////////AA==","MultiOpType":null} | merr <nil>: applyOps: (NotWritablePrimary) not primary
E               
E               {"t":{"$date":"2024-10-22T08:48:47.436+00:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"main","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":21},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":21},"outgoing":{"minWireVersion":6,"maxWireVersion":21},"isInternalClient":true}}}
E               {"t":{"$date":"2024-10-22T08:48:47.439+00:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
E               {"t":{"$date":"2024-10-22T08:48:47.439+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-10-22T08:48:47.440+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","namespace":"config.tenantMigrationDonors"}}
E               {"t":{"$date":"2024-10-22T08:48:47.440+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","namespace":"config.tenantMigrationRecipients"}}
E               {"t":{"$date":"2024-10-22T08:48:47.440+00:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"main","msg":"Multi threading initialized"}
E               {"t":{"$date":"2024-10-22T08:48:47.440+00:00"},"s":"I",  "c":"TENANT_M", "id":7091600, "ctx":"main","msg":"Starting TenantMigrationAccessBlockerRegistry"}
E               {"t":{"$date":"2024-10-22T08:48:47.441+00:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":624,"port":27057,"dbPath":"/var/lib/mongo","architecture":"64-bit","host":"rs201"}}
E               {"t":{"$date":"2024-10-22T08:48:47.441+00:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"7.0.14-8","gitVersion":"4479fd75bea6bf98a934c29007352dd36f3e1db5","openSSLVersion":"OpenSSL 1.1.1k  FIPS 25 Mar 2021","modules":[],"proFeatures":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.441+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-10-22T08:48:47.441+00:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/tmp/pbmMongdTmpConf3761800724","net":{"bindIp":"localhost","port":27057},"replication":{"replSet":"rs2"},"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-10-22T08:48:47.442+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-10-22T08:48:47.442+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,remove=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),json_output=(error,message),verbose=[recovery_progress:1,checkpoint_progress:1,compact_progress:1,backup:0,checkpoint:0,compact:0,evict:0,history_store:0,recovery:0,rts:0,salvage:0,tiered:0,timestamp:0,transaction:0,verify:0,log:0],"}}
E               {"t":{"$date":"2024-10-22T08:48:47.578+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":578603,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Recovering log 5 through 6"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.605+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":605515,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Recovering log 6 through 6"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.659+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":659827,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Main recovery loop: starting at 5/196608 to 6/256"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.710+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":710878,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Recovering log 5 through 6"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.750+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":750214,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Recovering log 6 through 6"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.774+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":774502,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"recovery log replay has successfully finished and ran for 196 milliseconds"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.774+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":774598,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Set global recovery timestamp: (0, 0)"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.774+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":774618,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Set global oldest timestamp: (0, 0)"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.775+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":775863,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"recovery rollback to stable has successfully finished and ran for 1 milliseconds"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.778+00:00"},"s":"I",  "c":"WTCHKPT",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":778145,"thread":"624:0x7f92543fdc00","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":6,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 1, snapshot max: 1 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 57"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.780+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":780190,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"recovery checkpoint has successfully finished and ran for 4 milliseconds"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.780+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":780241,"thread":"624:0x7f92543fdc00","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":30,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"recovery was completed successfully and took 201ms, including 196ms for the log replay, 1ms for the rollback to stable, and 4ms for the checkpoint."}}}
E               {"t":{"$date":"2024-10-22T08:48:47.781+00:00"},"s":"I",  "c":"STORAGE",  "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":339}}
E               {"t":{"$date":"2024-10-22T08:48:47.781+00:00"},"s":"I",  "c":"RECOVERY", "id":23987,   "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.790+00:00"},"s":"I",  "c":"STORAGE",  "id":7393203, "ctx":"initandlisten","msg":"The size storer reports that the collection contains","attr":{"numRecords":73,"dataSize":20956}}
E               {"t":{"$date":"2024-10-22T08:48:47.790+00:00"},"s":"I",  "c":"STORAGE",  "id":7393212, "ctx":"initandlisten","msg":"Scanning collection to determine where to place markers for truncation","attr":{"namespace":"local.oplog.rs"}}
E               {"t":{"$date":"2024-10-22T08:48:47.791+00:00"},"s":"I",  "c":"STORAGE",  "id":22382,   "ctx":"initandlisten","msg":"WiredTiger record store oplog processing finished","attr":{"durationMillis":0}}
E               {"t":{"$date":"2024-10-22T08:48:47.821+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-10-22T08:48:47.821+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-10-22T08:48:47.821+00:00"},"s":"W",  "c":"CONTROL",  "id":5123300, "ctx":"initandlisten","msg":"vm.max_map_count is too low","attr":{"currentValue":262144,"recommendedMinimum":1677720,"maxConns":838860},"tags":["startupWarnings"]}
E               {"t":{"$date":"2024-10-22T08:48:47.830+00:00"},"s":"I",  "c":"NETWORK",  "id":4915702, "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":21},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":21},"outgoing":{"minWireVersion":6,"maxWireVersion":21},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":21},"incomingInternalClient":{"minWireVersion":21,"maxWireVersion":21},"outgoing":{"minWireVersion":21,"maxWireVersion":21},"isInternalClient":true}}}
E               {"t":{"$date":"2024-10-22T08:48:47.830+00:00"},"s":"I",  "c":"REPL",     "id":5853300, "ctx":"initandlisten","msg":"current featureCompatibilityVersion value","attr":{"featureCompatibilityVersion":"7.0","context":"startup"}}
E               {"t":{"$date":"2024-10-22T08:48:47.830+00:00"},"s":"I",  "c":"STORAGE",  "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}
E               {"t":{"$date":"2024-10-22T08:48:47.877+00:00"},"s":"I",  "c":"CONTROL",  "id":20536,   "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}
E               {"t":{"$date":"2024-10-22T08:48:47.877+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-10-22T08:48:47.878+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":"rs2","clusterId":{"$oid":"6717658645598c688415bd2d"},"configsvrConnectionString":"rscfg/rscfg01:27017"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.879+00:00"},"s":"I",  "c":"REPL",     "id":40440,   "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}
E               {"t":{"$date":"2024-10-22T08:48:47.879+00:00"},"s":"I",  "c":"REPL",     "id":40445,   "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}
E               {"t":{"$date":"2024-10-22T08:48:47.881+00:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigStartingUp","oldState":"ConfigPreStart"}}
E               {"t":{"$date":"2024-10-22T08:48:47.881+00:00"},"s":"I",  "c":"REPL",     "id":6005300, "ctx":"initandlisten","msg":"Starting up replica set aware services"}
E               {"t":{"$date":"2024-10-22T08:48:47.881+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-10-22T08:48:47.881+00:00"},"s":"I",  "c":"REPL",     "id":4280500, "ctx":"initandlisten","msg":"Attempting to create internal replication collections"}
E               {"t":{"$date":"2024-10-22T08:48:47.884+00:00"},"s":"I",  "c":"REPL",     "id":4280501, "ctx":"initandlisten","msg":"Attempting to load local voted for document"}
E               {"t":{"$date":"2024-10-22T08:48:47.884+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-10-22T08:48:47.884+00:00"},"s":"I",  "c":"REPL",     "id":4280502, "ctx":"initandlisten","msg":"Searching for local Rollback ID document"}
E               {"t":{"$date":"2024-10-22T08:48:47.885+00:00"},"s":"I",  "c":"REPL",     "id":21529,   "ctx":"initandlisten","msg":"Initializing rollback ID","attr":{"rbid":1}}
E               {"t":{"$date":"2024-10-22T08:48:47.885+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-10-22T08:48:47.886+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":"rs2","clusterId":{"$oid":"6717658645598c688415bd2d"},"configsvrConnectionString":"rscfg/rscfg01:27017"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.886+00:00"},"s":"I",  "c":"CONTROL",  "id":6608200, "ctx":"initandlisten","msg":"Initializing cluster server parameters from disk"}
E               {"t":{"$date":"2024-10-22T08:48:47.886+00:00"},"s":"I",  "c":"REPL",     "id":21546,   "ctx":"initandlisten","msg":"Recovering from an unstable checkpoint","attr":{"topOfOplog":{"ts":{"$timestamp":{"t":1729586584,"i":54}},"t":1},"appliedThrough":{"ts":{"$timestamp":{"t":0,"i":0}},"t":-1}}}
E               {"t":{"$date":"2024-10-22T08:48:47.886+00:00"},"s":"I",  "c":"REPL",     "id":21547,   "ctx":"initandlisten","msg":"No oplog entries to apply for recovery. appliedThrough is null"}
E               {"t":{"$date":"2024-10-22T08:48:47.888+00:00"},"s":"I",  "c":"WTCHKPT",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":888832,"thread":"624:0x7f92543fdc00","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":6,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 63, snapshot max: 63 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 57"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.892+00:00"},"s":"I",  "c":"REPL",     "id":4280505, "ctx":"initandlisten","msg":"Creating any necessary TenantMigrationAccessBlockers for unfinished migrations"}
E               {"t":{"$date":"2024-10-22T08:48:47.893+00:00"},"s":"I",  "c":"TENANT_M", "id":6531504, "ctx":"initandlisten","msg":"Clearing serverless operation lock registry on shutdown","attr":{"ns":null}}
E               {"t":{"$date":"2024-10-22T08:48:47.893+00:00"},"s":"I",  "c":"REPL",     "id":4280506, "ctx":"initandlisten","msg":"Reconstructing prepared transactions"}
E               {"t":{"$date":"2024-10-22T08:48:47.894+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-10-22T08:48:47.894+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-10-22T08:48:47.894+00:00"},"s":"I",  "c":"STORAGE",  "id":22262,   "ctx":"initandlisten","msg":"Timestamp monitor starting"}
E               {"t":{"$date":"2024-10-22T08:48:47.912+00:00"},"s":"I",  "c":"QUERY",    "id":7080100, "ctx":"ChangeStreamExpiredPreImagesRemover","msg":"Starting Change Stream Expired Pre-images Remover thread"}
E               {"t":{"$date":"2024-10-22T08:48:47.913+00:00"},"s":"I",  "c":"SHARDING", "id":7012500, "ctx":"QueryAnalysisConfigurationsRefresher","msg":"Failed to refresh query analysis configurations, will try again at the next interval","attr":{"error":"PrimarySteppedDown: No primary exists currently"}}
E               {"t":{"$date":"2024-10-22T08:48:47.913+00:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-27057.sock"}}
E               {"t":{"$date":"2024-10-22T08:48:47.913+00:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}
E               {"t":{"$date":"2024-10-22T08:48:47.913+00:00"},"s":"I",  "c":"NETWORK",  "id":23016,   "ctx":"listener","msg":"Waiting for connections","attr":{"port":27057,"ssl":"off"}}
E               {"t":{"$date":"2024-10-22T08:48:47.913+00:00"},"s":"I",  "c":"CONTROL",  "id":8423403, "ctx":"initandlisten","msg":"mongod startup complete","attr":{"Summary of time elapsed":{"Startup from clean shutdown?":true,"Statistics":{"Transport layer setup":"0 ms","Run initial syncer crash recovery":"0 ms","Create storage engine lock file in the data directory":"0 ms","Get metadata describing storage engine":"0 ms","Validate options in metadata against current startup options":"0 ms","Create storage engine":"369 ms","Write current PID to file":"10 ms","Initialize FCV before rebuilding indexes":"9 ms","Drop abandoned idents and get back indexes that need to be rebuilt or builds that need to be restarted":"0 ms","Rebuild indexes for collections":"0 ms","Build user and roles graph":"0 ms","Verify indexes for admin.system.users collection":"0 ms","Verify indexes for admin.system.roles collection":"0 ms","Set up the background thread pool responsible for waiting for opTimes to be majority committed":"0 ms","Initialize information needed to make a mongod instance shard aware":"0 ms","Start up cluster time keys manager with a local/direct keys client":"0 ms","Start up the replication coordinator":"13 ms","Create an oplog view for tenant migrations":"0 ms","Start transport layer":"0 ms","_initAndListen total elapsed time":"472 ms"}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.913+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:60272","uuid":{"uuid":{"$uuid":"43685fd4-5057-4ce5-bf85-b9d6472ca781"}},"connectionId":2,"connectionCount":1}}
E               {"t":{"$date":"2024-10-22T08:48:47.913+00:00"},"s":"I",  "c":"NETWORK",  "id":6788700, "ctx":"conn2","msg":"Received first command on ingress connection since session start or auth handshake","attr":{"elapsedMillis":0}}
E               {"t":{"$date":"2024-10-22T08:48:47.913+00:00"},"s":"I",  "c":"REPL",     "id":4280509, "ctx":"ReplCoord-0","msg":"Local configuration validated for startup"}
E               {"t":{"$date":"2024-10-22T08:48:47.914+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-10-22T08:48:47.914+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn2","msg":"Connection ended","attr":{"remote":"127.0.0.1:60272","uuid":{"uuid":{"$uuid":"43685fd4-5057-4ce5-bf85-b9d6472ca781"}},"connectionId":2,"connectionCount":0}}
E               {"t":{"$date":"2024-10-22T08:48:47.914+00:00"},"s":"I",  "c":"SHARDING", "id":7063400, "ctx":"ReplCoord-0","msg":"Updating implicit default writeConcern majority","attr":{"newImplicitDefaultWCMajority":true}}
E               {"t":{"$date":"2024-10-22T08:48:47.914+00:00"},"s":"I",  "c":"REPL",     "id":21392,   "ctx":"ReplCoord-0","msg":"New replica set config in use","attr":{"config":{"_id":"rs2","version":1,"members":[{"_id":0,"host":"localhost:27057","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-10-22T08:48:47.914+00:00"},"s":"I",  "c":"REPL",     "id":21393,   "ctx":"ReplCoord-0","msg":"Found self in config","attr":{"hostAndPort":"localhost:27057"}}
E               {"t":{"$date":"2024-10-22T08:48:47.914+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-10-22T08:48:47.914+00:00"},"s":"I",  "c":"REPL",     "id":21827,   "ctx":"ReplCoord-0","msg":"Updating term","attr":{"oldTerm":0,"newTerm":1}}
E               {"t":{"$date":"2024-10-22T08:48:47.914+00:00"},"s":"I",  "c":"REPL",     "id":21320,   "ctx":"ReplCoord-0","msg":"Updated term","attr":{"term":1}}
E               {"t":{"$date":"2024-10-22T08:48:47.914+00:00"},"s":"I",  "c":"REPL",     "id":21306,   "ctx":"ReplCoord-0","msg":"Starting replication storage threads"}
E               {"t":{"$date":"2024-10-22T08:48:47.914+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-10-22T08:48:47.914+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-10-22T08:48:47.914+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplCoord-0","msg":"createCollection","attr":{"namespace":"local.replset.initialSyncId","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"8b19698e-e658-4cc5-b214-dd92dcfa0189"}},"options":{}}}
E               {"t":{"$date":"2024-10-22T08:48:47.914+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:60286","uuid":{"uuid":{"$uuid":"4fdfce1e-53ab-46f6-88d4-7e8084175462"}},"connectionId":3,"connectionCount":1}}
E               {"t":{"$date":"2024-10-22T08:48:47.914+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn3","msg":"client metadata","attr":{"remote":"127.0.0.1:60286","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.2","env":{"container":{"runtime":"docker"}}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.915+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:60302","uuid":{"uuid":{"$uuid":"9d4479f7-99f1-4dd4-be28-b26affc0d63b"}},"connectionId":4,"connectionCount":2}}
E               {"t":{"$date":"2024-10-22T08:48:47.915+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:60298","uuid":{"uuid":{"$uuid":"bc51e87e-fe4a-4cbe-bc48-912affe71858"}},"connectionId":5,"connectionCount":3}}
E               {"t":{"$date":"2024-10-22T08:48:47.915+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn4","msg":"client metadata","attr":{"remote":"127.0.0.1:60302","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.2","env":{"container":{"runtime":"docker"}}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.915+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn5","msg":"client metadata","attr":{"remote":"127.0.0.1:60298","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.2","env":{"container":{"runtime":"docker"}}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.916+00:00"},"s":"I",  "c":"NETWORK",  "id":6788700, "ctx":"conn4","msg":"Received first command on ingress connection since session start or auth handshake","attr":{"elapsedMillis":0}}
E               {"t":{"$date":"2024-10-22T08:48:47.920+00:00"},"s":"I",  "c":"REPL",     "id":7360102, "ctx":"ReplCoord-0","msg":"Added oplog entry for create to transaction","attr":{"namespace":"local.$cmd","uuid":{"uuid":{"$uuid":"8b19698e-e658-4cc5-b214-dd92dcfa0189"}},"object":{"create":"replset.initialSyncId","idIndex":{"v":2,"key":{"_id":1},"name":"_id_"}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.920+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplCoord-0","msg":"Index build: done building","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"8b19698e-e658-4cc5-b214-dd92dcfa0189"}},"namespace":"local.replset.initialSyncId","index":"_id_","ident":"index-1--6996890584052868265","collectionIdent":"collection-0--6996890584052868265","commitTimestamp":null}}
E               {"t":{"$date":"2024-10-22T08:48:47.920+00:00"},"s":"I",  "c":"REPL",     "id":21299,   "ctx":"ReplCoord-0","msg":"Starting replication fetcher thread"}
E               {"t":{"$date":"2024-10-22T08:48:47.921+00:00"},"s":"I",  "c":"REPL",     "id":21300,   "ctx":"ReplCoord-0","msg":"Starting replication applier thread"}
E               {"t":{"$date":"2024-10-22T08:48:47.921+00:00"},"s":"I",  "c":"REPL",     "id":21301,   "ctx":"ReplCoord-0","msg":"Starting replication reporter thread"}
E               {"t":{"$date":"2024-10-22T08:48:47.921+00:00"},"s":"I",  "c":"REPL",     "id":21224,   "ctx":"OplogApplier-0","msg":"Starting oplog application"}
E               {"t":{"$date":"2024-10-22T08:48:47.921+00:00"},"s":"I",  "c":"REPL",     "id":4280511, "ctx":"ReplCoord-0","msg":"Set local replica set config"}
E               {"t":{"$date":"2024-10-22T08:48:47.921+00:00"},"s":"I",  "c":"REPL",     "id":8423402, "ctx":"BackgroundSync","msg":"Failed to select a sync source on the first attempt. Starting second attempt"}
E               {"t":{"$date":"2024-10-22T08:48:47.921+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-10-22T08:48:47.921+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-10-22T08:48:47.921+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-10-22T08:48:47.921+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-10-22T08:48:47.921+00:00"},"s":"I",  "c":"REPL",     "id":21827,   "ctx":"ReplCoord-0","msg":"Updating term","attr":{"oldTerm":1,"newTerm":2}}
E               {"t":{"$date":"2024-10-22T08:48:47.921+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-10-22T08:48:47.922+00:00"},"s":"I",  "c":"ELECTION", "id":21450,   "ctx":"ReplCoord-0","msg":"Election succeeded, assuming primary role","attr":{"term":2}}
E               {"t":{"$date":"2024-10-22T08:48:47.922+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-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":21106,   "ctx":"ReplCoord-0","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}}
E               {"t":{"$date":"2024-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":21359,   "ctx":"ReplCoord-0","msg":"Entering primary catch-up mode"}
E               {"t":{"$date":"2024-10-22T08:48:47.922+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-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":21363,   "ctx":"ReplCoord-0","msg":"Exited primary catch-up mode"}
E               {"t":{"$date":"2024-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":21107,   "ctx":"ReplCoord-0","msg":"Stopping replication producer"}
E               {"t":{"$date":"2024-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":21239,   "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":2}}
E               {"t":{"$date":"2024-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":21239,   "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":2}}
E               {"t":{"$date":"2024-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":21343,   "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}
E               {"t":{"$date":"2024-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":21344,   "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"}
E               {"t":{"$date":"2024-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":21340,   "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepUp","userOpsKilled":0,"userOpsRunning":2}}}
E               {"t":{"$date":"2024-10-22T08:48:47.922+00:00"},"s":"I",  "c":"REPL",     "id":6015310, "ctx":"OplogApplier-0","msg":"Starting to transition to primary."}
E               {"t":{"$date":"2024-10-22T08:48:47.923+00:00"},"s":"I",  "c":"REPL",     "id":6015309, "ctx":"OplogApplier-0","msg":"Logging transition to primary to oplog on stepup"}
E               {"t":{"$date":"2024-10-22T08:48:47.923+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-10-22T08:48:47.923+00:00"},"s":"I",  "c":"STORAGE",  "id":7508300, "ctx":"IndexBuildsCoordinator-StepUp","msg":"Finished performing asynchronous step-up checks on index builds"}
E               {"t":{"$date":"2024-10-22T08:48:47.924+00:00"},"s":"I",  "c":"REPL",     "id":21331,   "ctx":"OplogApplier-0","msg":"Transition to primary complete; database writes are now permitted","attr":{"term":2}}
E               {"t":{"$date":"2024-10-22T08:48:47.924+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":"60cf8474-f7af-4835-b7c2-4f17d9de4ae7"}},"options":{}}}
E               {"t":{"$date":"2024-10-22T08:48:47.924+00:00"},"s":"I",  "c":"REPL",     "id":6015306, "ctx":"OplogApplier-0","msg":"Applier already left draining state, exiting."}
E               {"t":{"$date":"2024-10-22T08:48:47.925+00:00"},"s":"I",  "c":"REPL",     "id":6795400, "ctx":"JournalFlusher","msg":"Advancing committed opTime to a new term","attr":{"newCommittedOpTime":{"ts":{"$timestamp":{"t":1729586927,"i":2}},"t":2},"newCommittedWallime":{"$date":"2024-10-22T08:48:47.923Z"},"oldTerm":-1}}
E               {"t":{"$date":"2024-10-22T08:48:47.925+00:00"},"s":"I",  "c":"STORAGE",  "id":22310,   "ctx":"JournalFlusher","msg":"Triggering the first stable checkpoint","attr":{"initialDataTimestamp":{"$timestamp":{"t":1729586584,"i":54}},"prevStableTimestamp":{"$timestamp":{"t":0,"i":0}},"currStableTimestamp":{"$timestamp":{"t":1729586927,"i":2}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.926+00:00"},"s":"I",  "c":"REPL",     "id":5123005, "ctx":"TenantMigrationRecipientService-0","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationRecipientService"}}
E               {"t":{"$date":"2024-10-22T08:48:47.926+00:00"},"s":"I",  "c":"REPL",     "id":5123005, "ctx":"TenantMigrationDonorService-1","msg":"Rebuilding PrimaryOnlyService due to stepUp","attr":{"service":"TenantMigrationDonorService"}}
E               {"t":{"$date":"2024-10-22T08:48:47.930+00:00"},"s":"I",  "c":"WTCHKPT",  "id":22430,   "ctx":"Checkpointer","msg":"WiredTiger message","attr":{"message":{"ts_sec":1729586927,"ts_usec":930868,"thread":"624:0x7f923bccc700","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":6,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 76, snapshot max: 81 snapshot count: 1, oldest timestamp: (1729586627, 2) , meta checkpoint timestamp: (1729586927, 2) base write gen: 57"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.934+00:00"},"s":"I",  "c":"REPL",     "id":7360103, "ctx":"monitoring-keys-for-HMAC","msg":"Wrote oplog entry for create","attr":{"namespace":"admin.$cmd","uuid":{"uuid":{"$uuid":"60cf8474-f7af-4835-b7c2-4f17d9de4ae7"}},"opTime":{"ts":{"$timestamp":{"t":1729586927,"i":3}},"t":2},"object":{"create":"system.keys","idIndex":{"v":2,"key":{"_id":1},"name":"_id_"}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.934+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"monitoring-keys-for-HMAC","msg":"Index build: done building","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"60cf8474-f7af-4835-b7c2-4f17d9de4ae7"}},"namespace":"admin.system.keys","index":"_id_","ident":"index-3--6996890584052868265","collectionIdent":"collection-2--6996890584052868265","commitTimestamp":{"$timestamp":{"t":1729586927,"i":3}}}}
E               {"t":{"$date":"2024-10-22T08:48:47.936+00:00"},"s":"E",  "c":"WT",       "id":22435,   "ctx":"Checkpointer","msg":"WiredTiger error message","attr":{"error":2,"message":{"ts_sec":1729586927,"ts_usec":936316,"thread":"624:0x7f923bccc700","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_DEFAULT","category_id":9,"verbose_level":"ERROR","verbose_level_id":-3,"msg":"__posix_fs_size:301:/var/lib/mongo/WiredTigerHS.wt: file-size: stat","error_str":"No such file or directory","error_code":2}}}
E               {"t":{"$date":"2024-10-22T08:48:47.936+00:00"},"s":"E",  "c":"WT",       "id":22435,   "ctx":"Checkpointer","msg":"WiredTiger error message","attr":{"error":22,"message":{"ts_sec":1729586927,"ts_usec":936384,"thread":"624:0x7f923bccc700","session_dhandle_name":"file:WiredTigerHS.wt","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_DEFAULT","category_id":9,"verbose_level":"ERROR","verbose_level_id":-3,"msg":"__wt_block_checkpoint_resolve:990:WiredTigerHS.wt: the checkpoint failed, the system must restart","error_str":"Invalid argument","error_code":22}}}
E               {"t":{"$date":"2024-10-22T08:48:47.936+00:00"},"s":"E",  "c":"WT",       "id":22435,   "ctx":"Checkpointer","msg":"WiredTiger error message","attr":{"error":-31804,"message":{"ts_sec":1729586927,"ts_usec":936420,"thread":"624:0x7f923bccc700","session_dhandle_name":"file:WiredTigerHS.wt","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_DEFAULT","category_id":9,"verbose_level":"ERROR","verbose_level_id":-3,"msg":"__wt_block_checkpoint_resolve:990:the process must exit and restart","error_str":"WT_PANIC: WiredTiger library panic","error_code":-31804}}}
E               {"t":{"$date":"2024-10-22T08:48:47.936+00:00"},"s":"F",  "c":"ASSERT",   "id":23089,   "ctx":"Checkpointer","msg":"Fatal assertion","attr":{"msgid":50853,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp","line":741}}
E               {"t":{"$date":"2024-10-22T08:48:47.936+00:00"},"s":"F",  "c":"ASSERT",   "id":23090,   "ctx":"Checkpointer","msg":"\n\n***aborting after fassert() failure\n\n"}
E               {"t":{"$date":"2024-10-22T08:48:47.936+00:00"},"s":"F",  "c":"CONTROL",  "id":6384300, "ctx":"Checkpointer","msg":"Writing fatal message","attr":{"message":"\n"}}
E               {"t":{"$date":"2024-10-22T08:48:47.936+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-10-22T08:48:47.946+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn4","msg":"Connection ended","attr":{"remote":"127.0.0.1:60302","uuid":{"uuid":{"$uuid":"9d4479f7-99f1-4dd4-be28-b26affc0d63b"}},"connectionId":4,"connectionCount":2}}
E               {"t":{"$date":"2024-10-22T08:48:47.946+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn5","msg":"Connection ended","attr":{"remote":"127.0.0.1:60298","uuid":{"uuid":{"$uuid":"bc51e87e-fe4a-4cbe-bc48-912affe71858"}},"connectionId":5,"connectionCount":1}}
E               {"t":{"$date":"2024-10-22T08:48:47.946+00:00"},"s":"I",  "c":"-",        "id":20883,   "ctx":"conn3","msg":"Interrupted operation as its client disconnected","attr":{"opId":49}}
E               {"t":{"$date":"2024-10-22T08:48:47.947+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn3","msg":"Connection ended","attr":{"remote":"127.0.0.1:60286","uuid":{"uuid":{"$uuid":"4fdfce1e-53ab-46f6-88d4-7e8084175462"}},"connectionId":3,"connectionCount":0}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31380,   "ctx":"Checkpointer","msg":"BACKTRACE","attr":{"bt":{"backtrace":[{"a":"56421D2B91B8","b":"564215302000","o":"7FB71B8","s":"_ZN5mongo15printStackTraceEv","C":"mongo::printStackTrace()","s+":"38"},{"a":"56421D2B3B37","b":"564215302000","o":"7FB1B37","s":"abruptQuit","s+":"77"},{"a":"7F9252135D80","b":"7F9252123000","o":"12D80","s":"funlockfile","s+":"50"},{"a":"7F9251D9B5EF","b":"7F9251D4D000","o":"4E5EF","s":"gsignal","s+":"10F"},{"a":"7F9251D6EE65","b":"7F9251D4D000","o":"21E65","s":"abort","s+":"127"},{"a":"56421D2A57E7","b":"564215302000","o":"7FA37E7","s":"_ZN5mongo11DBException13traceIfNeededERKS0_","C":"mongo::DBException::traceIfNeeded(mongo::DBException const&)","s+":"207"},{"a":"56421D2A625F","b":"564215302000","o":"7FA425F","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","C":"mongo::fassertFailedWithLocation(int, char const*, unsigned int)","s+":"15E"},{"a":"56421A619AF5","b":"564215302000","o":"5317AF5","s":"_ZN5mongo36TransactionTooLargeForCacheException41defineOnlyInFinalSubclassToPreventSlicingEv","C":"mongo::TransactionTooLargeForCacheException::defineOnlyInFinalSubclassToPreventSlicing()","s+":"1E45"},{"a":"56421A7DC857","b":"564215302000","o":"54DA857","s":"__wt_encrypt_size","s+":"1757"},{"a":"56421A7DD475","b":"564215302000","o":"54DB475","s":"__wt_panic_func","s+":"156"},{"a":"56421A64392F","b":"564215302000","o":"534192F","s":"__wt_block_checkpoint_resolve","s+":"55F"},{"a":"56421A728CBC","b":"564215302000","o":"5426CBC","s":"__wt_meta_track_off","s+":"5DC"},{"a":"56421A803915","b":"564215302000","o":"5501915","s":"__wt_checkpoint_sync","s+":"A75"},{"a":"56421A804F16","b":"564215302000","o":"5502F16","s":"__wt_txn_checkpoint","s+":"116"},{"a":"56421A7ADC88","b":"564215302000","o":"54ABC88","s":"__wt_session_notsup","s+":"2009"},{"a":"56421A5AED98","b":"564215302000","o":"52ACD98","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_sessionb","C":"mongo::WiredTigerKVEngine::_checkpoint(__wt_session*, bool)","s+":"48"},{"a":"56421A5B935B","b":"564215302000","o":"52B735B","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEPNS_16OperationContextEP12__wt_session","C":"mongo::WiredTigerKVEngine::_checkpoint(mongo::OperationContext*, __wt_session*)","s+":"3BB"},{"a":"56421A5BB8D9","b":"564215302000","o":"52B98D9","s":"_ZN5mongo18WiredTigerKVEngine10checkpointEPNS_16OperationContextE","C":"mongo::WiredTigerKVEngine::checkpoint(mongo::OperationContext*)","s+":"49"},{"a":"56421AE95839","b":"564215302000","o":"5B93839","s":"_ZN5mongo12Checkpointer3runEv","C":"mongo::Checkpointer::run()","s+":"529"},{"a":"56421CFA9C1A","b":"564215302000","o":"7CA7C1A","s":"_ZN5mongo13BackgroundJob7jobBodyEv","C":"mongo::BackgroundJob::jobBody()","s+":"31A"},{"a":"56421CFA9FFC","b":"564215302000","o":"7CA7FFC","s":"_ZN5mongo13BackgroundJob7jobBodyEv","C":"mongo::BackgroundJob::jobBody()","s+":"6FC"},{"a":"56421D7FDA34","b":"564215302000","o":"84FBA34","s":"_ZNKSt10error_code23default_error_conditionEv","C":"std::error_code::default_error_condition() const","s+":"84"},{"a":"7F925212B1DA","b":"7F9252123000","o":"81DA","s":"start_thread","s+":"EA"},{"a":"7F9251D868D3","b":"7F9251D4D000","o":"398D3","s":"clone","s+":"43"}],"processInfo":{"mongodbVersion":"7.0.14-8","gitVersion":"4479fd75bea6bf98a934c29007352dd36f3e1db5","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":"564215302000","elfType":3,"buildId":"66937C4A678C7DB1AF31CEF100440614C213F407"},{"b":"7F9252123000","path":"/lib64/libpthread.so.0","elfType":3,"buildId":"0B813C2AD185DCA27DDB58BA42ACC172679B1526"},{"b":"7F9251D4D000","path":"/lib64/libc.so.6","elfType":3,"buildId":"BF4C06A1D77241A2D30436873E56C348FCBB5D22"}]}}},"tags":[]}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421D2B91B8","b":"564215302000","o":"7FB71B8","s":"_ZN5mongo15printStackTraceEv","C":"mongo::printStackTrace()","s+":"38"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421D2B3B37","b":"564215302000","o":"7FB1B37","s":"abruptQuit","s+":"77"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F9252135D80","b":"7F9252123000","o":"12D80","s":"funlockfile","s+":"50"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F9251D9B5EF","b":"7F9251D4D000","o":"4E5EF","s":"gsignal","s+":"10F"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F9251D6EE65","b":"7F9251D4D000","o":"21E65","s":"abort","s+":"127"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421D2A57E7","b":"564215302000","o":"7FA37E7","s":"_ZN5mongo11DBException13traceIfNeededERKS0_","C":"mongo::DBException::traceIfNeeded(mongo::DBException const&)","s+":"207"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421D2A625F","b":"564215302000","o":"7FA425F","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","C":"mongo::fassertFailedWithLocation(int, char const*, unsigned int)","s+":"15E"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A619AF5","b":"564215302000","o":"5317AF5","s":"_ZN5mongo36TransactionTooLargeForCacheException41defineOnlyInFinalSubclassToPreventSlicingEv","C":"mongo::TransactionTooLargeForCacheException::defineOnlyInFinalSubclassToPreventSlicing()","s+":"1E45"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A7DC857","b":"564215302000","o":"54DA857","s":"__wt_encrypt_size","s+":"1757"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A7DD475","b":"564215302000","o":"54DB475","s":"__wt_panic_func","s+":"156"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A64392F","b":"564215302000","o":"534192F","s":"__wt_block_checkpoint_resolve","s+":"55F"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A728CBC","b":"564215302000","o":"5426CBC","s":"__wt_meta_track_off","s+":"5DC"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A803915","b":"564215302000","o":"5501915","s":"__wt_checkpoint_sync","s+":"A75"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A804F16","b":"564215302000","o":"5502F16","s":"__wt_txn_checkpoint","s+":"116"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A7ADC88","b":"564215302000","o":"54ABC88","s":"__wt_session_notsup","s+":"2009"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A5AED98","b":"564215302000","o":"52ACD98","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_sessionb","C":"mongo::WiredTigerKVEngine::_checkpoint(__wt_session*, bool)","s+":"48"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A5B935B","b":"564215302000","o":"52B735B","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEPNS_16OperationContextEP12__wt_session","C":"mongo::WiredTigerKVEngine::_checkpoint(mongo::OperationContext*, __wt_session*)","s+":"3BB"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421A5BB8D9","b":"564215302000","o":"52B98D9","s":"_ZN5mongo18WiredTigerKVEngine10checkpointEPNS_16OperationContextE","C":"mongo::WiredTigerKVEngine::checkpoint(mongo::OperationContext*)","s+":"49"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421AE95839","b":"564215302000","o":"5B93839","s":"_ZN5mongo12Checkpointer3runEv","C":"mongo::Checkpointer::run()","s+":"529"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421CFA9C1A","b":"564215302000","o":"7CA7C1A","s":"_ZN5mongo13BackgroundJob7jobBodyEv","C":"mongo::BackgroundJob::jobBody()","s+":"31A"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421CFA9FFC","b":"564215302000","o":"7CA7FFC","s":"_ZN5mongo13BackgroundJob7jobBodyEv","C":"mongo::BackgroundJob::jobBody()","s+":"6FC"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"56421D7FDA34","b":"564215302000","o":"84FBA34","s":"_ZNKSt10error_code23default_error_conditionEv","C":"std::error_code::default_error_condition() const","s+":"84"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F925212B1DA","b":"7F9252123000","o":"81DA","s":"start_thread","s+":"EA"}}}
E               {"t":{"$date":"2024-10-22T08:48:47.969+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"Checkpointer","msg":"Frame","attr":{"frame":{"a":"7F9251D868D3","b":"7F9251D4D000","o":"398D3","s":"clone","s+":"43"}}}

cluster.py:462: AssertionError