start_cluster = True, cluster = <cluster.Cluster object at 0x7fbe7bc49510>

    @pytest.mark.timeout(1200, func_only=True)
    def test_physical_pitr_PBM_T251(start_cluster,cluster):
        cluster.check_pbm_status()
        for i in range(30):
             pymongo.MongoClient(cluster.connection)["test"]["test"].insert_one({"a": i})
        cluster.make_backup("logical")
        cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=3")
        backup=cluster.make_backup("physical")
        for i in range(30):
             pymongo.MongoClient(cluster.connection)["test"]["test"].insert_one({"b": i})
        timeout = time.time() + 360
        while True:
            status = cluster.get_status()
            for snapshot in status['backups']['snapshot']:
                if snapshot['name'] == backup:
                    backup_epoch = snapshot['restoreTo']
            if 'pitrChunks' in status['backups']:
                if 'pitrChunks' in status['backups']['pitrChunks']:
                    pitr_epoch = status['backups']['pitrChunks']['pitrChunks'][-1]['range']['end']
                    if pitr_epoch > backup_epoch:
                        pitr = datetime.utcfromtimestamp(pitr_epoch).strftime("%Y-%m-%dT%H:%M:%S")
                        Cluster.log("Time for PITR is: " + pitr)
                        break
            if time.time() > timeout:
                assert False
            time.sleep(1)
        time.sleep(30)
        backup="--time=" + pitr + " --base-snapshot=" + backup
        cluster.disable_pitr()
        cluster.make_restore(backup,restart_cluster=True,check_pbm_status=True)
        assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == 60
    
    
        backup=cluster.make_backup("physical")
>       cluster.make_restore(backup,restart_cluster=True,check_pbm_status=True)

test_PBM-1265.py:89: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7fbe7bc49510>, name = '2024-04-04T10:20:23Z'
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 0x7fbe7bbf2a90>, exit_status=124, command=b'ti...........................................................................................................", _stderr=b'')
n = <testinfra.host.Host docker://rscfg01>, timeout = 240
error = '{"t":{"$date":"2024-04-04T10:21:30.223+00:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatica...rMongod-0","msg":"Frame","attr":{"frame":{"a":"7EFEF17FBE73","b":"7EFEF17C2000","o":"39E73","s":"clone","s+":"43"}}}\n'
host = 'rscfg03', container = <Container: 406d0bebee82>

    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-04-04T10:20:39.642954033Z from '2024-04-04T10:20:23Z'..........................Started physical restore.
E               Waiting to finish.....................................................................................................................................................................................................................
E               {"t":{"$date":"2024-04-04T10:21:30.223+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-04-04T10:21:30.223+00:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"main","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}
E               {"t":{"$date":"2024-04-04T10:21:30.224+00:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
E               {"t":{"$date":"2024-04-04T10:21:30.224+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-04-04T10:21:30.225+00:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
E               {"t":{"$date":"2024-04-04T10:21:30.225+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}
E               {"t":{"$date":"2024-04-04T10:21:30.225+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}
E               {"t":{"$date":"2024-04-04T10:21:30.225+00:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"main","msg":"Multi threading initialized"}
E               {"t":{"$date":"2024-04-04T10:21:30.226+00:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":310,"port":27954,"dbPath":"/var/lib/mongo","architecture":"64-bit","host":"rs103"}}
E               {"t":{"$date":"2024-04-04T10:21:30.226+00:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.24-21","gitVersion":"751fc35891514cf219872e1134196614b972d9d3","openSSLVersion":"OpenSSL 1.1.1k  FIPS 25 Mar 2021","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.226+00:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Oracle Linux Server release 8.9","version":"Kernel 6.5.0-1016-azure"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.226+00:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/tmp/pbmMongdTmpConf3685899278","net":{"bindIp":"localhost","port":27954},"setParameter":{"recoverFromOplogAsStandalone":"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-04-04T10:21:30.227+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-04-04T10:21:30.227+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=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
E               {"t":{"$date":"2024-04-04T10:21:30.374+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1712226090:374387][310:0x7efef441ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 8 through 9"}}
E               {"t":{"$date":"2024-04-04T10:21:30.403+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1712226090:403531][310:0x7efef441ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 9 through 9"}}
E               {"t":{"$date":"2024-04-04T10:21:30.465+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1712226090:465915][310:0x7efef441ac00], txn-recover: [WT_VERB_RECOVERY_ALL] Main recovery loop: starting at 8/65920 to 9/256"}}
E               {"t":{"$date":"2024-04-04T10:21:30.516+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1712226090:516781][310:0x7efef441ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 8 through 9"}}
E               {"t":{"$date":"2024-04-04T10:21:30.562+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1712226090:562676][310:0x7efef441ac00], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 9 through 9"}}
E               {"t":{"$date":"2024-04-04T10:21:30.592+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1712226090:592131][310:0x7efef441ac00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global recovery timestamp: (1712225976, 3)"}}
E               {"t":{"$date":"2024-04-04T10:21:30.592+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1712226090:592183][310:0x7efef441ac00], txn-recover: [WT_VERB_RECOVERY_ALL] Set global oldest timestamp: (1712225676, 3)"}}
E               {"t":{"$date":"2024-04-04T10:21:30.596+00:00"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1712226090:596169][310:0x7efef441ac00], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 1, snapshot max: 1 snapshot count: 0, oldest timestamp: (1712225676, 3) , meta checkpoint timestamp: (1712225976, 3) base write gen: 69"}}
E               {"t":{"$date":"2024-04-04T10:21:30.599+00:00"},"s":"I",  "c":"STORAGE",  "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":372}}
E               {"t":{"$date":"2024-04-04T10:21:30.599+00:00"},"s":"I",  "c":"RECOVERY", "id":23987,   "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":1712225976,"i":3}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.599+00:00"},"s":"I",  "c":"RECOVERY", "id":5380106, "ctx":"initandlisten","msg":"WiredTiger oldestTimestamp","attr":{"oldestTimestamp":{"$timestamp":{"t":1712225676,"i":3}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.634+00:00"},"s":"I",  "c":"STORAGE",  "id":22262,   "ctx":"initandlisten","msg":"Timestamp monitor starting"}
E               {"t":{"$date":"2024-04-04T10:21:30.635+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-04-04T10:21:30.635+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'","tags":["startupWarnings"]}
E               {"t":{"$date":"2024-04-04T10:21:30.649+00:00"},"s":"I",  "c":"NETWORK",  "id":4915702, "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":13,"maxWireVersion":13},"outgoing":{"minWireVersion":13,"maxWireVersion":13},"isInternalClient":true}}}
E               {"t":{"$date":"2024-04-04T10:21:30.649+00:00"},"s":"I",  "c":"STORAGE",  "id":5071100, "ctx":"initandlisten","msg":"Clearing temp directory"}
E               {"t":{"$date":"2024-04-04T10:21:30.673+00:00"},"s":"I",  "c":"CONTROL",  "id":20536,   "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}
E               {"t":{"$date":"2024-04-04T10:21:30.673+00:00"},"s":"I",  "c":"STORAGE",  "id":5380103, "ctx":"initandlisten","msg":"Unpin oldest timestamp request","attr":{"service":"_wt_startup","requestedTs":{"$timestamp":{"t":1712225676,"i":3}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.674+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":"660e7cd9fad19ea74050c4d5"},"configsvrConnectionString":"rscfg/rscfg01:27017,rscfg02:27017,rscfg03:27017"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.674+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-04-04T10:21:30.679+00:00"},"s":"I",  "c":"REPL",     "id":21557,   "ctx":"initandlisten","msg":"Removing unapplied oplog entries after oplogTruncateAfterPoint","attr":{"oplogTruncateAfterPoint":{"":{"$timestamp":{"t":1712226025,"i":4}}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.679+00:00"},"s":"I",  "c":"REPL",     "id":21553,   "ctx":"initandlisten","msg":"Truncating oplog from truncateAfterOplogEntryTimestamp (non-inclusive)","attr":{"truncateAfterOplogEntryTimestamp":{"$timestamp":{"t":1712226023,"i":70}},"oplogTruncateAfterPoint":{"$timestamp":{"t":1712226025,"i":4}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.679+00:00"},"s":"I",  "c":"REPL",     "id":21554,   "ctx":"initandlisten","msg":"Replication recovery oplog truncation finished","attr":{"durationMillis":0}}
E               {"t":{"$date":"2024-04-04T10:21:30.679+00:00"},"s":"I",  "c":"REPL",     "id":21544,   "ctx":"initandlisten","msg":"Recovering from stable timestamp","attr":{"stableTimestamp":{"$timestamp":{"t":1712225976,"i":3}},"topOfOplog":{"ts":{"$timestamp":{"t":1712226023,"i":70}},"t":4},"appliedThrough":{"ts":{"$timestamp":{"t":0,"i":0}},"t":-1}}}
E               {"t":{"$date":"2024-04-04T10:21:30.679+00:00"},"s":"I",  "c":"REPL",     "id":21545,   "ctx":"initandlisten","msg":"Starting recovery oplog application at the stable timestamp","attr":{"stableTimestamp":{"$timestamp":{"t":1712225976,"i":3}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.681+00:00"},"s":"I",  "c":"REPL",     "id":5466604, "ctx":"initandlisten","msg":"Start point for recovery oplog application exists in oplog. No adjustment necessary","attr":{"startPoint":{"$timestamp":{"t":1712225976,"i":3}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.681+00:00"},"s":"I",  "c":"REPL",     "id":21550,   "ctx":"initandlisten","msg":"Replaying stored operations from startPoint (exclusive) to endPoint (inclusive)","attr":{"startPoint":{"$timestamp":{"t":1712225976,"i":3}},"endPoint":{"$timestamp":{"t":1712226023,"i":70}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.683+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-0","msg":"createCollection","attr":{"namespace":"config.cache.chunks.config.system.sessions","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"04aa7321-3ada-42dd-a7bc-887275f4f482"}},"options":{"uuid":{"$uuid":"04aa7321-3ada-42dd-a7bc-887275f4f482"}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.688+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.cache.chunks.config.system.sessions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1712225977,"i":2}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.693+00:00"},"s":"I",  "c":"INDEX",    "id":20384,   "ctx":"ReplWriterWorker-0","msg":"Index build: starting","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"04aa7321-3ada-42dd-a7bc-887275f4f482"}},"namespace":"config.cache.chunks.config.system.sessions","properties":{"v":2,"key":{"lastmod":1},"name":"lastmod_1"},"method":"Hybrid","maxTemporaryMemoryUsageMB":200}}
E               {"t":{"$date":"2024-04-04T10:21:30.693+00:00"},"s":"I",  "c":"INDEX",    "id":20391,   "ctx":"ReplWriterWorker-0","msg":"Index build: collection scan done","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"04aa7321-3ada-42dd-a7bc-887275f4f482"}},"namespace":"config.cache.chunks.config.system.sessions","totalRecords":0,"readSource":"kNoTimestamp","durationMillis":0}}
E               {"t":{"$date":"2024-04-04T10:21:30.693+00:00"},"s":"I",  "c":"INDEX",    "id":20685,   "ctx":"ReplWriterWorker-0","msg":"Index build: inserted keys from external sorter into index","attr":{"namespace":"config.cache.chunks.config.system.sessions","index":"lastmod_1","keysInserted":0,"durationMillis":0}}
E               {"t":{"$date":"2024-04-04T10:21:30.694+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.cache.chunks.config.system.sessions","index":"lastmod_1","commitTimestamp":{"$timestamp":{"t":1712225977,"i":3}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.696+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-0","msg":"createCollection","attr":{"namespace":"config.system.sessions","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"67e7c2f0-aa9b-45d4-b932-ce594bac5d32"}},"options":{"uuid":{"$uuid":"67e7c2f0-aa9b-45d4-b932-ce594bac5d32"}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.701+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.system.sessions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1712225977,"i":9}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.705+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-3","msg":"createCollection","attr":{"namespace":"config.migrationCoordinators","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"0d197554-1abd-4a8a-b0c9-06cde2dec8cb"}},"options":{"uuid":{"$uuid":"0d197554-1abd-4a8a-b0c9-06cde2dec8cb"}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.710+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-3","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.migrationCoordinators","index":"_id_","commitTimestamp":{"$timestamp":{"t":1712225977,"i":1165}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.711+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-1","msg":"createCollection","attr":{"namespace":"config.rangeDeletions","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"865676b2-f0e4-4fca-9869-23b677dcda62"}},"options":{"uuid":{"$uuid":"865676b2-f0e4-4fca-9869-23b677dcda62"}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.717+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-1","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.rangeDeletions","index":"_id_","commitTimestamp":{"$timestamp":{"t":1712225977,"i":1239}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.721+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-0","msg":"createCollection","attr":{"namespace":"config.vectorClock","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"20b1ac51-ed72-4a94-a5ea-0db5356790ea"}},"options":{"uuid":{"$uuid":"20b1ac51-ed72-4a94-a5ea-0db5356790ea"}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.727+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-0","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.vectorClock","index":"_id_","commitTimestamp":{"$timestamp":{"t":1712225978,"i":1052}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.798+00:00"},"s":"I",  "c":"REPL",     "id":21536,   "ctx":"initandlisten","msg":"Completed oplog application for recovery","attr":{"numOpsApplied":1809,"numBatches":179,"applyThroughOpTime":{"ts":{"$timestamp":{"t":1712226023,"i":70}},"t":4}}}
E               {"t":{"$date":"2024-04-04T10:21:30.800+00:00"},"s":"W",  "c":"REPL",     "id":21558,   "ctx":"initandlisten","msg":"Setting mongod to readOnly mode as a result of specifying 'recoverFromOplogAsStandalone'"}
E               {"t":{"$date":"2024-04-04T10:21:30.800+00:00"},"s":"I",  "c":"REPL",     "id":6015317, "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigReplicationDisabled","oldState":"ConfigPreStart"}}
E               {"t":{"$date":"2024-04-04T10:21:30.801+00:00"},"s":"I",  "c":"CONTROL",  "id":20712,   "ctx":"LogicalSessionCacheReap","msg":"Sessions collection is not set up; waiting until next sessions reap interval","attr":{"error":"IndexNotFound: config.system.sessions does not have the required TTL index"}}
E               {"t":{"$date":"2024-04-04T10:21:30.801+00:00"},"s":"I",  "c":"INDEX",    "id":20438,   "ctx":"LogicalSessionCacheRefresh","msg":"Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"62b0f09f-2db4-4419-9e30-9dd141d61b8e"}},"namespace":"config.system.sessions","collectionUUID":{"uuid":{"$uuid":"67e7c2f0-aa9b-45d4-b932-ce594bac5d32"}},"indexes":1,"firstIndex":{"name":"lsidTTLIndex"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.801+00:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-27954.sock"}}
E               {"t":{"$date":"2024-04-04T10:21:30.801+00:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}
E               {"t":{"$date":"2024-04-04T10:21:30.801+00:00"},"s":"I",  "c":"NETWORK",  "id":23016,   "ctx":"listener","msg":"Waiting for connections","attr":{"port":27954,"ssl":"off"}}
E               {"t":{"$date":"2024-04-04T10:21:30.802+00:00"},"s":"E",  "c":"INDEX",    "id":20393,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Caught exception while cleaning up partially built indexes","attr":{"error":"IllegalOperation: Cannot execute a write operation in read-only mode"}}
E               {"t":{"$date":"2024-04-04T10:21:30.802+00:00"},"s":"F",  "c":"-",        "id":23089,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Fatal assertion","attr":{"msgid":18644,"file":"src/mongo/db/catalog/multi_index_block.cpp","line":152}}
E               {"t":{"$date":"2024-04-04T10:21:30.802+00:00"},"s":"F",  "c":"-",        "id":23090,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"\n\n***aborting after fassert() failure\n\n"}
E               {"t":{"$date":"2024-04-04T10:21:30.802+00:00"},"s":"F",  "c":"CONTROL",  "id":6384300, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31380,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"BACKTRACE","attr":{"bt":{"backtrace":[{"a":"55BCE5EB26E3","b":"55BCE1CED000","o":"41C56E3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"},{"a":"55BCE5EB5127","b":"55BCE1CED000","o":"41C8127","s":"_ZN5mongo15printStackTraceEv","s+":"37"},{"a":"55BCE5EAD2D6","b":"55BCE1CED000","o":"41C02D6","s":"abruptQuit","s+":"66"},{"a":"7EFEF1B99D40","b":"7EFEF1B87000","o":"12D40","s":"funlockfile","s+":"50"},{"a":"7EFEF1810B8F","b":"7EFEF17C2000","o":"4EB8F","s":"gsignal","s+":"10F"},{"a":"7EFEF17E3EA5","b":"7EFEF17C2000","o":"21EA5","s":"abort","s+":"127"},{"a":"55BCE3252D2B","b":"55BCE1CED000","o":"1565D2B","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"},{"a":"55BCE300173F","b":"55BCE1CED000","o":"131473F","s":"_ZN5mongo21AuthzVersionParameter13setFromStringERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"55EF"},{"a":"55BCE44C0AAF","b":"55BCE1CED000","o":"27D3AAF","s":"_ZN5mongo18IndexBuildsManager15abortIndexBuildEPNS_16OperationContextERNS_16CollectionWriterERKNS_4UUIDESt8functionIFvvEE","s+":"FF"},{"a":"55BCE2F6F7D8","b":"55BCE1CED000","o":"12827D8","s":"_ZZNK5mongo11BSONElement6NumberEvENKUlvE_clEv","s+":"7C08"},{"a":"55BCE4431947","b":"55BCE1CED000","o":"2744947","s":"_ZN5mongo22IndexBuildsCoordinator16_setUpIndexBuildEPNS_16OperationContextERKNS_4UUIDENS_9TimestampERKNS0_17IndexBuildOptionsE","s+":"D7"},{"a":"55BCE4140B78","b":"55BCE1CED000","o":"2453B78","s":"_ZN5mongo28IndexBuildsCoordinatorMongod33_checkVoteCommitIndexCmdSucceededERKNS_7BSONObjERKNS_4UUIDE","s+":"CB8"},{"a":"55BCE5C6BBB5","b":"55BCE1CED000","o":"3F7EBB5","s":"_ZN5mongo10ThreadPool4Impl10_doOneTaskEPSt11unique_lockINS_12latch_detail5LatchEE","s+":"135"},{"a":"55BCE5C6D40B","b":"55BCE1CED000","o":"3F8040B","s":"_ZN5mongo10ThreadPool4Impl13_consumeTasksEv","s+":"8B"},{"a":"55BCE5C6E92C","b":"55BCE1CED000","o":"3F8192C","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"26C"},{"a":"55BCE5C6EED0","b":"55BCE1CED000","o":"3F81ED0","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"810"},{"a":"7EFEF2404B23","b":"7EFEF2342000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"},{"a":"7EFEF1B8F1DA","b":"7EFEF1B87000","o":"81DA","s":"start_thread","s+":"EA"},{"a":"7EFEF17FBE73","b":"7EFEF17C2000","o":"39E73","s":"clone","s+":"43"}],"processInfo":{"mongodbVersion":"5.0.24-21","gitVersion":"751fc35891514cf219872e1134196614b972d9d3","compiledModules":[],"uname":{"sysname":"Linux","release":"6.5.0-1016-azure","version":"#16~22.04.1-Ubuntu SMP Fri Feb 16 15:42:02 UTC 2024","machine":"x86_64"},"somap":[{"b":"55BCE1CED000","elfType":3,"buildId":"DA4870CDDA3114158E5C3DAB653D63D4F6C9E499"},{"b":"7EFEF2342000","path":"/lib64/libstdc++.so.6","elfType":3,"buildId":"5CA844DFEE0FE8E20B2A0F7CF8EF4291838E8806"},{"b":"7EFEF1B87000","path":"/lib64/libpthread.so.0","elfType":3,"buildId":"D1ADEF9579CE9780C97DB1A37BD08552A91F4564"},{"b":"7EFEF17C2000","path":"/lib64/libc.so.6","elfType":3,"buildId":"BA5A6A6FF582CD9C692D725BAD086CBB48AC723D"}]}}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE5EB26E3","b":"55BCE1CED000","o":"41C56E3","s":"_ZN5mongo34StackTraceAddressMetadataGenerator4loadEPv","s+":"FC3"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE5EB5127","b":"55BCE1CED000","o":"41C8127","s":"_ZN5mongo15printStackTraceEv","s+":"37"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE5EAD2D6","b":"55BCE1CED000","o":"41C02D6","s":"abruptQuit","s+":"66"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7EFEF1B99D40","b":"7EFEF1B87000","o":"12D40","s":"funlockfile","s+":"50"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7EFEF1810B8F","b":"7EFEF17C2000","o":"4EB8F","s":"gsignal","s+":"10F"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7EFEF17E3EA5","b":"7EFEF17C2000","o":"21EA5","s":"abort","s+":"127"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE3252D2B","b":"55BCE1CED000","o":"1565D2B","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"F6"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE300173F","b":"55BCE1CED000","o":"131473F","s":"_ZN5mongo21AuthzVersionParameter13setFromStringERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"55EF"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE44C0AAF","b":"55BCE1CED000","o":"27D3AAF","s":"_ZN5mongo18IndexBuildsManager15abortIndexBuildEPNS_16OperationContextERNS_16CollectionWriterERKNS_4UUIDESt8functionIFvvEE","s+":"FF"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE2F6F7D8","b":"55BCE1CED000","o":"12827D8","s":"_ZZNK5mongo11BSONElement6NumberEvENKUlvE_clEv","s+":"7C08"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE4431947","b":"55BCE1CED000","o":"2744947","s":"_ZN5mongo22IndexBuildsCoordinator16_setUpIndexBuildEPNS_16OperationContextERKNS_4UUIDENS_9TimestampERKNS0_17IndexBuildOptionsE","s+":"D7"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE4140B78","b":"55BCE1CED000","o":"2453B78","s":"_ZN5mongo28IndexBuildsCoordinatorMongod33_checkVoteCommitIndexCmdSucceededERKNS_7BSONObjERKNS_4UUIDE","s+":"CB8"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE5C6BBB5","b":"55BCE1CED000","o":"3F7EBB5","s":"_ZN5mongo10ThreadPool4Impl10_doOneTaskEPSt11unique_lockINS_12latch_detail5LatchEE","s+":"135"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE5C6D40B","b":"55BCE1CED000","o":"3F8040B","s":"_ZN5mongo10ThreadPool4Impl13_consumeTasksEv","s+":"8B"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE5C6E92C","b":"55BCE1CED000","o":"3F8192C","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"26C"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"55BCE5C6EED0","b":"55BCE1CED000","o":"3F81ED0","s":"_ZN5mongo10ThreadPool4Impl17_workerThreadBodyERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"810"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7EFEF2404B23","b":"7EFEF2342000","o":"C2B23","s":"_ZNKSt10error_code23default_error_conditionEv","s+":"33"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7EFEF1B8F1DA","b":"7EFEF1B87000","o":"81DA","s":"start_thread","s+":"EA"}}}
E               {"t":{"$date":"2024-04-04T10:21:30.845+00:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Frame","attr":{"frame":{"a":"7EFEF17FBE73","b":"7EFEF17C2000","o":"39E73","s":"clone","s+":"43"}}}

cluster.py:460: AssertionError