start_cluster = True, cluster = <cluster.Cluster object at 0x7fecca5cafd0>
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 0x7fecca5cafd0>
name = '--time=2024-11-14T10:57:04'
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 0x7feccbdc6f50>, exit_status=1, command=b'time...r":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (NotWritablePrimary) not primary\n', _stderr=b'')
n = <testinfra.host.Host docker://rscfg01>, timeout = 240
error = '{"t":{"$date":"2024-11-14T10:59:12.759+00:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatica...  "id":23092,   "svc":"S", "ctx":"monitoring-keys-for-HMAC","msg":"\\n\\n***aborting after fassert() failure\\n\\n"}\n'
host = 'rscfg01', container = <Container: 96fe91fb1e54>

    def make_restore(self, name, **kwargs):
        if self.layout == "sharded":
            client = pymongo.MongoClient(self.connection)
            result = client.admin.command("balancerStop")
            client.close()
            Cluster.log("Stopping balancer: " + str(result))
            self.stop_mongos()
        self.stop_arbiters()
        n = testinfra.get_host("docker://" + self.pbm_cli)
        timeout = time.time() + 60
    
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                assert False, "Cannot start restore, another operation running"
            time.sleep(1)
        Cluster.log("Restore started")
        timeout=kwargs.get('timeout', 240)
        result = n.run('timeout ' + str(timeout) + ' pbm restore ' + name + ' --wait')
    
        if result.rc == 0:
            Cluster.log(result.stdout)
        else:
            # try to catch possible failures if timeout exceeded
            error=''
            for host in self.mongod_hosts:
                try:
                    container = docker.from_env().containers.get(host)
                    get_logs = container.exec_run(
                        'cat /var/lib/mongo/pbm.restore.log', stderr=False)
                    if get_logs.exit_code == 0:
                        Cluster.log(
                            "!!!!Possible failure on {}, file pbm.restore.log was found:".format(host))
                        logs = get_logs.output.decode('utf-8')
                        Cluster.log(logs)
                        if '"s":"F"' in logs:
                            error = logs
                except docker.errors.APIError:
                    pass
            if error:
>               assert False, result.stdout + result.stderr + "\n" + error
E               AssertionError: Starting restore 2024-11-14T10:58:27.741085291Z to point-in-time 2024-11-14T10:57:04 from '2024-11-14T10:53:25Z'..........................Started physical restore.
E               Waiting to finish....................Error: operation failed with: replay pitr oplog: reply oplog: replay chunk 1731581607.1731581671: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1731581618,"I":2},"Term":1,"Hash":null,"Version":2,"Operation":"u","Namespace":"config.settings","Object":[{"Key":"$v","Value":2},{"Key":"diff","Value":[{"Key":"u","Value":[{"Key":"mode","Value":"full"},{"Key":"stopped","Value":false}]}]}],"Query":[{"Key":"_id","Value":"balancer"}],"UI":{"Subtype":4,"Data":"tRD4nFnhTU66EmKlAWFOjA=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (NotWritablePrimary) not primary
E               
E               {"t":{"$date":"2024-11-14T10:59:12.759+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-11-14T10:59:12.760+00:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "svc":"-", "ctx":"main","msg":"Multi threading initialized"}
E               {"t":{"$date":"2024-11-14T10:59:12.761+00:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "svc":"-", "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set at least one of the related parameters","attr":{"relatedParameters":["tcpFastOpenServer","tcpFastOpenClient","tcpFastOpenQueueSize"]}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "svc":"-", "ctx":"main","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":25},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":25},"outgoing":{"minWireVersion":6,"maxWireVersion":25},"isInternalClient":true}}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "svc":"-", "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"ReshardingCoordinatorService","namespace":"config.reshardingOperations"}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "svc":"-", "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"ConfigsvrCoordinatorService","namespace":"config.sharding_configsvr_coordinators"}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "svc":"-", "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"RenameCollectionParticipantService","namespace":"config.localRenameParticipants"}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "svc":"-", "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"ShardingDDLCoordinator","namespace":"config.system.sharding_ddl_coordinators"}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "svc":"-", "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"ReshardingDonorService","namespace":"config.localReshardingOperations.donor"}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "svc":"-", "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"ReshardingRecipientService","namespace":"config.localReshardingOperations.recipient"}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"REPL",     "id":5123008, "svc":"-", "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"MultiUpdateCoordinatorService","namespace":"config.localMigrationBlockingOperations.multiUpdateCoordinators"}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"TENANT_M", "id":7091600, "svc":"-", "ctx":"main","msg":"Starting TenantMigrationAccessBlockerRegistry"}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "svc":"S", "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":1959,"port":27581,"dbPath":"/var/lib/mongo","architecture":"64-bit","host":"rscfg01"}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "svc":"S", "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"8.0.1-1","gitVersion":"88788b464f844b9120ed4a22ebe72cbfa873626c","openSSLVersion":"OpenSSL 1.1.1k  FIPS 25 Mar 2021","modules":[],"proFeatures":[],"allocator":"tcmalloc-google","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "svc":"S", "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Oracle Linux Server release 8.10","version":"Kernel 6.5.0-1025-azure"}}}
E               {"t":{"$date":"2024-11-14T10:59:12.762+00:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "svc":"S", "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/tmp/pbmMongdTmpConf1413616101","net":{"bindIp":"localhost","port":27581},"replication":{"replSet":"rscfg"},"setParameter":{"disableLogicalSessionCacheRefresh":"true","takeUnstableCheckpointOnShutdown":"true"},"sharding":{"clusterRole":"configsvr"},"storage":{"dbPath":"/var/lib/mongo","directoryPerDB":false,"wiredTiger":{"collectionConfig":{"blockCompressor":"snappy"},"engineConfig":{"directoryForIndexes":false,"journalCompressor":"snappy"},"indexConfig":{"prefixCompression":true}}},"systemLog":{"destination":"file","path":"/var/lib/mongo/pbm.restore.log"}}}}
E               {"t":{"$date":"2024-11-14T10:59:12.763+00:00"},"s":"I",  "c":"STORAGE",  "id":22270,   "svc":"S", "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongo","storageEngine":"wiredTiger"}}
E               {"t":{"$date":"2024-11-14T10:59:12.763+00:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "svc":"S", "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],prefetch=(available=true,default=false),"}}
E               {"t":{"$date":"2024-11-14T10:59:12.908+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581952,"ts_usec":908178,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Recovering log 5 through 6"}}}
E               {"t":{"$date":"2024-11-14T10:59:12.933+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581952,"ts_usec":933427,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Recovering log 6 through 6"}}}
E               {"t":{"$date":"2024-11-14T10:59:12.990+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581952,"ts_usec":990248,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Main recovery loop: starting at 5/176768 to 6/256"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.036+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":36707,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Recovering log 5 through 6"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.068+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":68410,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Recovering log 6 through 6"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.092+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":92126,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"recovery log replay has successfully finished and ran for 184 milliseconds"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.092+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":92194,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Set global recovery timestamp: (0, 0)"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.092+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":92221,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"Set global oldest timestamp: (0, 0)"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.094+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":94216,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"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-11-14T10:59:13.097+00:00"},"s":"I",  "c":"WTCHKPT",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":97184,"thread":"1959:0x7f9664517180","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":7,"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: 72"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.099+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":99130,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"recovery checkpoint has successfully finished and ran for 4 milliseconds"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.099+00:00"},"s":"I",  "c":"WTRECOV",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":99190,"thread":"1959:0x7f9664517180","session_name":"txn-recover","category":"WT_VERB_RECOVERY_PROGRESS","category_id":34,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"recovery was completed successfully and took 191ms, including 184ms for the log replay, 1ms for the rollback to stable, and 4ms for the checkpoint."}}}
E               {"t":{"$date":"2024-11-14T10:59:13.101+00:00"},"s":"I",  "c":"STORAGE",  "id":4795906, "svc":"S", "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":338}}
E               {"t":{"$date":"2024-11-14T10:59:13.101+00:00"},"s":"I",  "c":"RECOVERY", "id":23987,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}
E               {"t":{"$date":"2024-11-14T10:59:13.109+00:00"},"s":"I",  "c":"STORAGE",  "id":7393203, "svc":"S", "ctx":"initandlisten","msg":"The size storer reports that the collection contains","attr":{"numRecords":220,"dataSize":85024}}
E               {"t":{"$date":"2024-11-14T10:59:13.109+00:00"},"s":"I",  "c":"STORAGE",  "id":7393212, "svc":"S", "ctx":"initandlisten","msg":"Scanning collection to determine where to place markers for truncation","attr":{"namespace":"local.oplog.rs"}}
E               {"t":{"$date":"2024-11-14T10:59:13.109+00:00"},"s":"I",  "c":"STORAGE",  "id":22382,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger record store oplog processing finished","attr":{"durationMillis":0}}
E               {"t":{"$date":"2024-11-14T10:59:13.149+00:00"},"s":"W",  "c":"CONTROL",  "id":22120,   "svc":"S", "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted. You can use percona-server-mongodb-enable-auth.sh to fix it","tags":["startupWarnings"]}
E               {"t":{"$date":"2024-11-14T10:59:13.149+00:00"},"s":"W",  "c":"CONTROL",  "id":9068900, "svc":"S", "ctx":"initandlisten","msg":"For customers running the current memory allocator, we suggest changing the contents of the following sysfsFile","attr":{"allocator":"tcmalloc-google","sysfsFile":"/sys/kernel/mm/transparent_hugepage/defrag","currentValue":"madvise","desiredValue":"defer+madvise"},"tags":["startupWarnings"]}
E               {"t":{"$date":"2024-11-14T10:59:13.149+00:00"},"s":"W",  "c":"CONTROL",  "id":8640302, "svc":"S", "ctx":"initandlisten","msg":"We suggest setting the contents of sysfsFile to 0.","attr":{"sysfsFile":"/sys/kernel/mm/transparent_hugepage/khugepaged/max_ptes_none","currentValue":511},"tags":["startupWarnings"]}
E               {"t":{"$date":"2024-11-14T10:59:13.149+00:00"},"s":"W",  "c":"NETWORK",  "id":5123300, "svc":"S", "ctx":"initandlisten","msg":"vm.max_map_count is too low","attr":{"currentValue":262144,"recommendedMinimum":1677720,"maxConns":838860},"tags":["startupWarnings"]}
E               {"t":{"$date":"2024-11-14T10:59:13.149+00:00"},"s":"W",  "c":"CONTROL",  "id":8386700, "svc":"S", "ctx":"initandlisten","msg":"We suggest setting swappiness to 0 or 1, as swapping can cause performance problems.","attr":{"sysfsFile":"/proc/sys/vm/swappiness","currentValue":60},"tags":["startupWarnings"]}
E               {"t":{"$date":"2024-11-14T10:59:13.172+00:00"},"s":"I",  "c":"NETWORK",  "id":4915702, "svc":"S", "ctx":"initandlisten","msg":"Updated wire specification","attr":{"oldSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":25},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":25},"outgoing":{"minWireVersion":6,"maxWireVersion":25},"isInternalClient":true},"newSpec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":25},"incomingInternalClient":{"minWireVersion":25,"maxWireVersion":25},"outgoing":{"minWireVersion":25,"maxWireVersion":25},"isInternalClient":true}}}
E               {"t":{"$date":"2024-11-14T10:59:13.172+00:00"},"s":"I",  "c":"REPL",     "id":5853300, "svc":"S", "ctx":"initandlisten","msg":"current featureCompatibilityVersion value","attr":{"featureCompatibilityVersion":"8.0","context":"startup"}}
E               {"t":{"$date":"2024-11-14T10:59:13.173+00:00"},"s":"I",  "c":"STORAGE",  "id":5071100, "svc":"S", "ctx":"initandlisten","msg":"Clearing temp directory"}
E               {"t":{"$date":"2024-11-14T10:59:13.200+00:00"},"s":"W",  "c":"QUERY",    "id":3216000, "svc":"S", "ctx":"initandlisten","msg":"$jsonSchema validator does not allow '_id' field. This validator will reject all documents, consider adding '_id' to the allowed fields."}
E               {"t":{"$date":"2024-11-14T10:59:13.200+00:00"},"s":"W",  "c":"QUERY",    "id":3216000, "svc":"S", "ctx":"initandlisten","msg":"$jsonSchema validator does not allow '_id' field. This validator will reject all documents, consider adding '_id' to the allowed fields."}
E               {"t":{"$date":"2024-11-14T10:59:13.209+00:00"},"s":"I",  "c":"CONTROL",  "id":20536,   "svc":"S", "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}
E               {"t":{"$date":"2024-11-14T10:59:13.210+00:00"},"s":"I",  "c":"FTDC",     "id":20625,   "svc":"S", "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/var/lib/mongo/diagnostic.data"}}
E               {"t":{"$date":"2024-11-14T10:59:13.212+00:00"},"s":"I",  "c":"REPL",     "id":40440,   "svc":"S", "ctx":"initandlisten","msg":"Starting the TopologyVersionObserver"}
E               {"t":{"$date":"2024-11-14T10:59:13.212+00:00"},"s":"I",  "c":"REPL",     "id":40445,   "svc":"S", "ctx":"TopologyVersionObserver","msg":"Started TopologyVersionObserver"}
E               {"t":{"$date":"2024-11-14T10:59:13.214+00:00"},"s":"I",  "c":"SHARDING", "id":22727,   "svc":"-", "ctx":"ShardRegistryUpdater","msg":"Error running periodic reload of shard registry","attr":{"error":"NotYetInitialized: Config shard has not been set up yet","shardRegistryReloadIntervalSeconds":30}}
E               {"t":{"$date":"2024-11-14T10:59:13.214+00:00"},"s":"W",  "c":"SHARDING", "id":7012500, "svc":"S", "ctx":"QueryAnalysisConfigurationsRefresher","msg":"Failed to refresh query analysis configurations, will try again at the next interval","attr":{"error":"NotYetInitialized: Config shard has not been set up yet"}}
E               {"t":{"$date":"2024-11-14T10:59:13.214+00:00"},"s":"I",  "c":"-",        "id":4939300, "svc":"S", "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"ReadConcernMajorityNotAvailableYet: Read concern majority reads are currently not possible.","nextWakeupMillis":200}}
E               {"t":{"$date":"2024-11-14T10:59:13.214+00:00"},"s":"I",  "c":"SHARDING", "id":22072,   "svc":"S", "ctx":"initandlisten","msg":"Initializing sharding state","attr":{"initialShardIdentity":{"shardName":"config","clusterId":{"$oid":"6735d69321308f33cb3b1eae"},"configsvrConnectionString":"rscfg/rscfg01:27017"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.214+00:00"},"s":"I",  "c":"SHARDING", "id":22071,   "svc":"S", "ctx":"initandlisten","msg":"Finished initializing sharding components","attr":{"memberState":"secondary"}}
E               {"t":{"$date":"2024-11-14T10:59:13.214+00:00"},"s":"I",  "c":"SHARDING", "id":22081,   "svc":"S", "ctx":"initandlisten","msg":"Sharding status of the node recovered successfully","attr":{"role":"6735d69321308f33cb3b1eae : ClusterRole{shard|config|router} : rscfg/rscfg01:27017 : config"}}
E               {"t":{"$date":"2024-11-14T10:59:13.215+00:00"},"s":"I",  "c":"REPL",     "id":6015317, "svc":"S", "ctx":"initandlisten","msg":"Setting new configuration state","attr":{"newState":"ConfigStartingUp","oldState":"ConfigPreStart"}}
E               {"t":{"$date":"2024-11-14T10:59:13.215+00:00"},"s":"I",  "c":"REPL",     "id":6005300, "svc":"S", "ctx":"initandlisten","msg":"Starting up replica set aware services"}
E               {"t":{"$date":"2024-11-14T10:59:13.216+00:00"},"s":"I",  "c":"REPL",     "id":4280500, "svc":"S", "ctx":"initandlisten","msg":"Attempting to create internal replication collections"}
E               {"t":{"$date":"2024-11-14T10:59:13.218+00:00"},"s":"I",  "c":"REPL",     "id":4280501, "svc":"S", "ctx":"initandlisten","msg":"Attempting to load local voted for document"}
E               {"t":{"$date":"2024-11-14T10:59:13.218+00:00"},"s":"I",  "c":"REPL",     "id":21311,   "svc":"S", "ctx":"initandlisten","msg":"Did not find local initialized voted for document at startup"}
E               {"t":{"$date":"2024-11-14T10:59:13.218+00:00"},"s":"I",  "c":"REPL",     "id":4280502, "svc":"S", "ctx":"initandlisten","msg":"Searching for local Rollback ID document"}
E               {"t":{"$date":"2024-11-14T10:59:13.219+00:00"},"s":"I",  "c":"REPL",     "id":21529,   "svc":"S", "ctx":"initandlisten","msg":"Initializing rollback ID","attr":{"rbid":1}}
E               {"t":{"$date":"2024-11-14T10:59:13.219+00:00"},"s":"I",  "c":"REPL",     "id":4280504, "svc":"S", "ctx":"initandlisten","msg":"Cleaning up any partially applied oplog batches & reading last op from oplog"}
E               {"t":{"$date":"2024-11-14T10:59:13.220+00:00"},"s":"I",  "c":"CONTROL",  "id":6608200, "svc":"S", "ctx":"initandlisten","msg":"Initializing cluster server parameters from disk"}
E               {"t":{"$date":"2024-11-14T10:59:13.221+00:00"},"s":"I",  "c":"SHARDING", "id":22072,   "svc":"S", "ctx":"initandlisten","msg":"Initializing sharding state","attr":{"initialShardIdentity":{"shardName":"config","clusterId":{"$oid":"6735d69321308f33cb3b1eae"},"configsvrConnectionString":"rscfg/rscfg01:27017"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.221+00:00"},"s":"I",  "c":"REPL",     "id":21546,   "svc":"S", "ctx":"initandlisten","msg":"Recovering from an unstable checkpoint","attr":{"topOfOplog":{"ts":{"$timestamp":{"t":1731581607,"i":1}},"t":1},"appliedThrough":{"ts":{"$timestamp":{"t":0,"i":0}},"t":-1}}}
E               {"t":{"$date":"2024-11-14T10:59:13.221+00:00"},"s":"I",  "c":"REPL",     "id":21547,   "svc":"S", "ctx":"initandlisten","msg":"No oplog entries to apply for recovery. appliedThrough is null"}
E               {"t":{"$date":"2024-11-14T10:59:13.223+00:00"},"s":"I",  "c":"WTCHKPT",  "id":22430,   "svc":"S", "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":{"ts_sec":1731581953,"ts_usec":223537,"thread":"1959:0x7f9664517180","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":7,"verbose_level":"DEBUG_1","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 103, snapshot max: 103 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 72"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.227+00:00"},"s":"I",  "c":"REPL",     "id":4280505, "svc":"S", "ctx":"initandlisten","msg":"Creating any necessary TenantMigrationAccessBlockers for unfinished migrations"}
E               {"t":{"$date":"2024-11-14T10:59:13.227+00:00"},"s":"I",  "c":"TENANT_M", "id":6531504, "svc":"S", "ctx":"initandlisten","msg":"Clearing serverless operation lock registry on shutdown","attr":{"ns":null}}
E               {"t":{"$date":"2024-11-14T10:59:13.227+00:00"},"s":"I",  "c":"REPL",     "id":4280506, "svc":"S", "ctx":"initandlisten","msg":"Reconstructing prepared transactions"}
E               {"t":{"$date":"2024-11-14T10:59:13.228+00:00"},"s":"I",  "c":"REPL",     "id":4280507, "svc":"S", "ctx":"initandlisten","msg":"Loaded replica set config, scheduled callback to set local config"}
E               {"t":{"$date":"2024-11-14T10:59:13.228+00:00"},"s":"I",  "c":"REPL",     "id":4280508, "svc":"S", "ctx":"ReplCoord-0","msg":"Attempting to set local replica set config; validating config for startup"}
E               {"t":{"$date":"2024-11-14T10:59:13.228+00:00"},"s":"I",  "c":"STORAGE",  "id":22262,   "svc":"S", "ctx":"initandlisten","msg":"Timestamp monitor starting"}
E               {"t":{"$date":"2024-11-14T10:59:13.228+00:00"},"s":"I",  "c":"STORAGE",  "id":7333401, "svc":"S", "ctx":"initandlisten","msg":"Starting the DiskSpaceMonitor"}
E               {"t":{"$date":"2024-11-14T10:59:13.229+00:00"},"s":"I",  "c":"QUERY",    "id":7080100, "svc":"-", "ctx":"ChangeStreamExpiredPreImagesRemover","msg":"Starting Change Stream Expired Pre-images Remover thread"}
E               {"t":{"$date":"2024-11-14T10:59:13.229+00:00"},"s":"I",  "c":"-",        "id":7658604, "svc":"S", "ctx":"ChangeStreamExpiredPreImagesRemover","msg":"Decided on initial creation method for pre-images truncate markers initialization","attr":{"initialCreationMethod":"emptyCollection","dataSize":0,"numRecords":0,"preImagesCollectionUUID":{"uuid":{"$uuid":"4b9bd2f2-251e-4bf2-be4f-df6d1965303f"}},"tenantId":null}}
E               {"t":{"$date":"2024-11-14T10:59:13.229+00:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "svc":"-", "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-27581.sock"}}
E               {"t":{"$date":"2024-11-14T10:59:13.229+00:00"},"s":"I",  "c":"NETWORK",  "id":23015,   "svc":"-", "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1:27581"}}
E               {"t":{"$date":"2024-11-14T10:59:13.229+00:00"},"s":"I",  "c":"NETWORK",  "id":23016,   "svc":"-", "ctx":"listener","msg":"Waiting for connections","attr":{"port":27581,"ssl":"off"}}
E               {"t":{"$date":"2024-11-14T10:59:13.229+00:00"},"s":"I",  "c":"CONTROL",  "id":8423403, "svc":"S", "ctx":"initandlisten","msg":"mongod startup complete","attr":{"Summary of time elapsed":{"Startup from clean shutdown?":true,"Statistics":{"Set up periodic runner":"0 ms","Set up online certificate status protocol manager":"0 ms","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":"378 ms","Write current PID to file":"0 ms","Write a new metadata for storage engine":"0 ms","Initialize FCV before rebuilding indexes":"23 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 the sharding components for a config server":"2 ms","Initialize information needed to make a mongod instance shard aware":"0 ms","Load global settings from config server":"0 ms","Start up the replication coordinator":"14 ms","Create an oplog view for tenant migrations":"0 ms","Ensure the change stream collections on startup contain consistent data":"0 ms","Write startup options to the audit log":"0 ms","Start transport layer":"0 ms","_initAndListen total elapsed time":"467 ms"}}}}
E               {"t":{"$date":"2024-11-14T10:59:13.229+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "svc":"-", "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:45200","uuid":{"uuid":{"$uuid":"48fe5554-e9f7-42d4-9b86-6e3332bf868f"}},"connectionId":2,"connectionCount":1}}
E               {"t":{"$date":"2024-11-14T10:59:13.229+00:00"},"s":"I",  "c":"NETWORK",  "id":6788700, "svc":"S", "ctx":"conn2","msg":"Received first command on ingress connection since session start or auth handshake","attr":{"elapsedMillis":0}}
E               {"t":{"$date":"2024-11-14T10:59:13.229+00:00"},"s":"I",  "c":"REPL",     "id":4280509, "svc":"S", "ctx":"ReplCoord-0","msg":"Local configuration validated for startup"}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"REPL",     "id":6015317, "svc":"S", "ctx":"ReplCoord-0","msg":"Setting new configuration state","attr":{"newState":"ConfigSteady","oldState":"ConfigStartingUp"}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"-",        "id":9023600, "svc":"S", "ctx":"ChangeStreamExpiredPreImagesRemover","msg":"Completed initialization of pre-image tenant truncate markers","attr":{"preImagesCollectionUUID":{"uuid":{"$uuid":"4b9bd2f2-251e-4bf2-be4f-df6d1965303f"}},"tenantId":null}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "svc":"S", "ctx":"conn2","msg":"Connection ended","attr":{"remote":"127.0.0.1:45200","uuid":{"uuid":{"$uuid":"48fe5554-e9f7-42d4-9b86-6e3332bf868f"}},"connectionId":2,"connectionCount":0}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"SHARDING", "id":7063400, "svc":"S", "ctx":"ReplCoord-0","msg":"Updating implicit default writeConcern majority","attr":{"newImplicitDefaultWCMajority":true}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"REPL",     "id":21392,   "svc":"S", "ctx":"ReplCoord-0","msg":"New replica set config in use","attr":{"config":{"_id":"rscfg","version":1,"members":[{"_id":0,"host":"localhost:27581","arbiterOnly":false,"buildIndexes":true,"hidden":false,"priority":1,"tags":{},"secondaryDelaySecs":0,"votes":1}],"configsvr":true,"protocolVersion":1,"writeConcernMajorityJournalDefault":true,"settings":{"chainingAllowed":true,"heartbeatIntervalMillis":2000,"heartbeatTimeoutSecs":10,"electionTimeoutMillis":10000,"catchUpTimeoutMillis":-1,"catchUpTakeoverDelayMillis":30000,"getLastErrorModes":{},"getLastErrorDefaults":{"w":1,"wtimeout":0}}}}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"REPL",     "id":21393,   "svc":"S", "ctx":"ReplCoord-0","msg":"Found self in config","attr":{"hostAndPort":"localhost:27581"}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"REPL",     "id":21358,   "svc":"S", "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"STARTUP2","oldState":"STARTUP"}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"REPL",     "id":21827,   "svc":"S", "ctx":"ReplCoord-0","msg":"Updating term","attr":{"oldTerm":0,"newTerm":1}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"REPL",     "id":21320,   "svc":"S", "ctx":"ReplCoord-0","msg":"Updated term","attr":{"term":1}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"NETWORK",  "id":4603701, "svc":"S", "ctx":"ReplCoord-0","msg":"Starting Replica Set Monitor","attr":{"protocol":"streamable","uri":"rscfg/localhost:27581"}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"-",        "id":4333223, "svc":"S", "ctx":"ReplCoord-0","msg":"RSM now monitoring replica set","attr":{"replicaSet":"rscfg","nReplicaSetMembers":1}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"-",        "id":4333226, "svc":"S", "ctx":"ReplCoord-0","msg":"RSM host was added to the topology","attr":{"replicaSet":"rscfg","host":"localhost:27581"}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"REPL",     "id":21306,   "svc":"S", "ctx":"ReplCoord-0","msg":"Starting replication storage threads"}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"CONNPOOL", "id":22576,   "svc":"-", "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"Connecting","attr":{"hostAndPort":"localhost:27581"}}
E               {"t":{"$date":"2024-11-14T10:59:13.230+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "svc":"-", "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:45206","uuid":{"uuid":{"$uuid":"ccd29b8f-4871-46a1-aef8-c17b6fb7c450"}},"connectionId":3,"connectionCount":1}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"REPL",     "id":4280512, "svc":"S", "ctx":"ReplCoord-0","msg":"No initial sync required. Attempting to begin steady replication","attr":{"lastOpTime":{"ts":{"$timestamp":{"t":1731581607,"i":1}},"t":1},"isInitialSyncFlagSet":false}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"REPL",     "id":21358,   "svc":"S", "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"RECOVERING","oldState":"STARTUP2"}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "svc":"S", "ctx":"ReplCoord-0","msg":"createCollection","attr":{"namespace":"local.replset.initialSyncId","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"2590590a-7fbd-4767-964d-92cd43189815"}},"options":{}}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "svc":"S", "ctx":"conn3","msg":"client metadata","attr":{"remote":"127.0.0.1:45206","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.22.9","env":{"container":{"runtime":"docker"}}}}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "svc":"-", "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:45218","uuid":{"uuid":{"$uuid":"8ca75c2a-9dff-4896-850d-c5aecaabb754"}},"connectionId":5,"connectionCount":2}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "svc":"S", "ctx":"conn5","msg":"client metadata","attr":{"remote":"127.0.0.1:45218","client":"conn5","negotiatedCompressors":["snappy","zstd","zlib"],"doc":{"driver":{"name":"NetworkInterfaceTL-ReplicaSetMonitor-TaskExecutor","version":"8.0.1-1"},"os":{"type":"Linux","name":"Oracle Linux Server release 8.10","architecture":"x86_64","version":"Kernel 6.5.0-1025-azure"}}}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"NETWORK",  "id":23729,   "svc":"-", "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"ServerPingMonitor is now monitoring host","attr":{"host":"localhost:27581","replicaSet":"rscfg"}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"NETWORK",  "id":4333213, "svc":"-", "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM Topology Change","attr":{"replicaSet":"rscfg","newTopologyDescription":{"id":"845379fb-75cf-40e1-a959-b61df705c4af","topologyType":"ReplicaSetNoPrimary","servers":{"localhost:27581":{"address":"localhost:27581","topologyVersion":{"processId":{"$oid":"6735d8000fe1992b6929392b"},"counter":2},"roundTripTime":293,"lastWriteDate":{"$date":"2024-11-14T10:53:27.000Z"},"opTime":{"ts":{"$timestamp":{"t":1731581607,"i":1}},"t":1},"type":"RSOther","minWireVersion":25,"maxWireVersion":25,"me":"localhost:27581","setName":"rscfg","setVersion":1,"lastUpdateTime":{"$date":"2024-11-14T10:59:13.231Z"},"logicalSessionTimeoutMinutes":30,"hosts":{"0":"localhost:27581"},"arbiters":{},"passives":{}}},"setName":"rscfg","compatible":true},"previousTopologyDescription":{"id":"42f59124-8230-459a-b8d6-b82531641d3a","topologyType":"ReplicaSetNoPrimary","servers":{"localhost:27581":{"address":"localhost:27581","type":"Unknown","minWireVersion":0,"maxWireVersion":0,"lastUpdateTime":{"$date":{"$numberLong":"-9223372036854775808"}},"hosts":{},"arbiters":{},"passives":{}}},"setName":"rscfg","compatible":true}}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "svc":"-", "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:45226","uuid":{"uuid":{"$uuid":"9768ba39-d8cf-4eaf-91d1-8f33a89e2f95"}},"connectionId":6,"connectionCount":3}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "svc":"-", "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:45230","uuid":{"uuid":{"$uuid":"fa3f4537-08ca-4b20-b270-c0bb8c5c3189"}},"connectionId":7,"connectionCount":4}}
E               {"t":{"$date":"2024-11-14T10:59:13.231+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "svc":"S", "ctx":"conn6","msg":"client metadata","attr":{"remote":"127.0.0.1:45226","client":"conn6","negotiatedCompressors":[],"doc":{"application":{"name":"pbm-physical-restore"},"driver":{"name":"mongo-go-driver","version":"1.16.0"},"os":{"type":"linux","architecture":"amd64"},"platform":"go1.22.9","env":{"container":{"runtime":"docker"}}}}}
E               {"t":{"$date":"2024-11-14T10:59:13.232+00:00"},"s":"I",  "c":"NETWORK",  "id":6788700, "svc":"S", "ctx":"conn5","msg":"Received first command on ingress connection since session start or auth handshake","attr":{"elapsedMillis":0}}
E               {"t":{"$date":"2024-11-14T10:59:13.232+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "svc":"S", "ctx":"conn7","msg":"client metadata","attr":{"remote":"127.0.0.1:45230","client":"conn7","negotiatedCompressors":[],"doc":{"application":{"name":"pbm-physical-restore"},"driver":{"name":"mongo-go-driver","version":"1.16.0"},"os":{"type":"linux","architecture":"amd64"},"platform":"go1.22.9","env":{"container":{"runtime":"docker"}}}}}
E               {"t":{"$date":"2024-11-14T10:59:13.232+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "svc":"-", "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:45240","uuid":{"uuid":{"$uuid":"b0b29a5e-3090-4e81-9eff-1c5278cac5c1"}},"connectionId":8,"connectionCount":5}}
E               {"t":{"$date":"2024-11-14T10:59:13.232+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "svc":"S", "ctx":"conn8","msg":"client metadata","attr":{"remote":"127.0.0.1:45240","client":"conn8","negotiatedCompressors":["snappy","zstd","zlib"],"doc":{"driver":{"name":"NetworkInterfaceTL-ReplicaSetMonitor-TaskExecutor","version":"8.0.1-1"},"os":{"type":"Linux","name":"Oracle Linux Server release 8.10","architecture":"x86_64","version":"Kernel 6.5.0-1025-azure"}}}}
E               {"t":{"$date":"2024-11-14T10:59:13.232+00:00"},"s":"I",  "c":"NETWORK",  "id":6788700, "svc":"S", "ctx":"conn7","msg":"Received first command on ingress connection since session start or auth handshake","attr":{"elapsedMillis":0}}
E               {"t":{"$date":"2024-11-14T10:59:13.237+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "svc":"S", "ctx":"ReplCoord-0","msg":"Index build: done building","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"2590590a-7fbd-4767-964d-92cd43189815"}},"namespace":"local.replset.initialSyncId","index":"_id_","ident":"index-1-5879726551017189016","collectionIdent":"collection-0-5879726551017189016","commitTimestamp":null}}
E               {"t":{"$date":"2024-11-14T10:59:13.237+00:00"},"s":"I",  "c":"REPL",     "id":21299,   "svc":"S", "ctx":"ReplCoord-0","msg":"Starting replication fetcher thread"}
E               {"t":{"$date":"2024-11-14T10:59:13.237+00:00"},"s":"I",  "c":"REPL",     "id":8569800, "svc":"S", "ctx":"ReplCoord-0","msg":"Starting replication writer thread"}
E               {"t":{"$date":"2024-11-14T10:59:13.237+00:00"},"s":"I",  "c":"REPL",     "id":8543100, "svc":"S", "ctx":"OplogWriter-0","msg":"Starting oplog write"}
E               {"t":{"$date":"2024-11-14T10:59:13.237+00:00"},"s":"I",  "c":"REPL",     "id":21300,   "svc":"S", "ctx":"ReplCoord-0","msg":"Starting replication applier thread"}
E               {"t":{"$date":"2024-11-14T10:59:13.237+00:00"},"s":"I",  "c":"REPL",     "id":8423402, "svc":"S", "ctx":"BackgroundSync","msg":"Failed to select a sync source on the first attempt. Starting second attempt"}
E               {"t":{"$date":"2024-11-14T10:59:13.237+00:00"},"s":"I",  "c":"REPL",     "id":21224,   "svc":"S", "ctx":"OplogApplier-0","msg":"Starting oplog application"}
E               {"t":{"$date":"2024-11-14T10:59:13.237+00:00"},"s":"I",  "c":"REPL",     "id":21301,   "svc":"S", "ctx":"ReplCoord-0","msg":"Starting replication reporter thread"}
E               {"t":{"$date":"2024-11-14T10:59:13.237+00:00"},"s":"I",  "c":"REPL",     "id":21358,   "svc":"S", "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"RECOVERING"}}
E               {"t":{"$date":"2024-11-14T10:59:13.258+00:00"},"s":"I",  "c":"ELECTION", "id":4615652, "svc":"S", "ctx":"ReplCoord-0","msg":"Starting an election, since we've seen no PRIMARY in election timeout period","attr":{"electionTimeoutPeriodMillis":10000}}
E               {"t":{"$date":"2024-11-14T10:59:13.258+00:00"},"s":"I",  "c":"ELECTION", "id":21438,   "svc":"S", "ctx":"ReplCoord-0","msg":"Conducting a dry run election to see if we could be elected","attr":{"currentTerm":1}}
E               {"t":{"$date":"2024-11-14T10:59:13.259+00:00"},"s":"I",  "c":"REPL",     "id":4280511, "svc":"S", "ctx":"ReplCoord-0","msg":"Set local replica set config"}
E               {"t":{"$date":"2024-11-14T10:59:13.259+00:00"},"s":"I",  "c":"ELECTION", "id":21444,   "svc":"S", "ctx":"ReplCoord-1","msg":"Dry election run succeeded, running for election","attr":{"newTerm":2}}
E               {"t":{"$date":"2024-11-14T10:59:13.259+00:00"},"s":"I",  "c":"REPL",     "id":21827,   "svc":"S", "ctx":"ReplCoord-1","msg":"Updating term","attr":{"oldTerm":1,"newTerm":2}}
E               {"t":{"$date":"2024-11-14T10:59:13.259+00:00"},"s":"I",  "c":"ELECTION", "id":6015300, "svc":"S", "ctx":"ReplCoord-0","msg":"Storing last vote document in local storage for my election","attr":{"lastVote":{"term":2,"candidateIndex":0}}}
E               {"t":{"$date":"2024-11-14T10:59:13.259+00:00"},"s":"I",  "c":"NETWORK",  "id":4333213, "svc":"-", "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM Topology Change","attr":{"replicaSet":"rscfg","newTopologyDescription":{"id":"f2564551-16d2-4d62-ad81-4d9040d55104","topologyType":"ReplicaSetNoPrimary","servers":{"localhost:27581":{"address":"localhost:27581","topologyVersion":{"processId":{"$oid":"6735d8000fe1992b6929392b"},"counter":3},"roundTripTime":384,"lastWriteDate":{"$date":"2024-11-14T10:53:27.000Z"},"opTime":{"ts":{"$timestamp":{"t":1731581607,"i":1}},"t":1},"type":"RSSecondary","minWireVersion":25,"maxWireVersion":25,"me":"localhost:27581","setName":"rscfg","setVersion":1,"lastUpdateTime":{"$date":"2024-11-14T10:59:13.259Z"},"logicalSessionTimeoutMinutes":30,"hosts":{"0":"localhost:27581"},"arbiters":{},"passives":{}}},"logicalSessionTimeoutMinutes":30,"setName":"rscfg","compatible":true},"previousTopologyDescription":{"id":"c50fbd47-2ee9-4d03-9d1f-d627f1299852","topologyType":"ReplicaSetNoPrimary","servers":{"localhost:27581":{"address":"localhost:27581","topologyVersion":{"processId":{"$oid":"6735d8000fe1992b6929392b"},"counter":2},"roundTripTime":384,"lastWriteDate":{"$date":"2024-11-14T10:53:27.000Z"},"opTime":{"ts":{"$timestamp":{"t":1731581607,"i":1}},"t":1},"type":"RSOther","minWireVersion":25,"maxWireVersion":25,"me":"localhost:27581","setName":"rscfg","setVersion":1,"lastUpdateTime":{"$date":"2024-11-14T10:59:13.232Z"},"logicalSessionTimeoutMinutes":30,"hosts":{"0":"localhost:27581"},"arbiters":{},"passives":{}}},"setName":"rscfg","compatible":true}}}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"ELECTION", "id":21450,   "svc":"S", "ctx":"ReplCoord-0","msg":"Election succeeded, assuming primary role","attr":{"term":2}}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"REPL",     "id":21358,   "svc":"S", "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"REPL",     "id":21106,   "svc":"S", "ctx":"ReplCoord-0","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "svc":"-", "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:45254","uuid":{"uuid":{"$uuid":"c934c68e-4fe4-4081-af95-2ac027769db0"}},"connectionId":11,"connectionCount":6}}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"REPL",     "id":21359,   "svc":"S", "ctx":"ReplCoord-0","msg":"Entering primary catch-up mode"}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"REPL",     "id":6015304, "svc":"S", "ctx":"ReplCoord-0","msg":"Skipping primary catchup since we are the only node in the replica set."}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"REPL",     "id":21363,   "svc":"S", "ctx":"ReplCoord-0","msg":"Exited primary catch-up mode"}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"REPL",     "id":21107,   "svc":"S", "ctx":"ReplCoord-0","msg":"Stopping replication producer"}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"REPL",     "id":8938402, "svc":"S", "ctx":"OplogWriter-0","msg":"Oplog writer buffer has been drained","attr":{"term":2}}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "svc":"S", "ctx":"conn11","msg":"client metadata","attr":{"remote":"127.0.0.1:45254","client":"conn11","negotiatedCompressors":["snappy","zstd","zlib"],"doc":{"driver":{"name":"NetworkInterfaceTL-ShardRegistry","version":"8.0.1-1"},"os":{"type":"Linux","name":"Oracle Linux Server release 8.10","architecture":"x86_64","version":"Kernel 6.5.0-1025-azure"}}}}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"NETWORK",  "id":4333213, "svc":"-", "ctx":"ReplicaSetMonitor-TaskExecutor","msg":"RSM Topology Change","attr":{"replicaSet":"rscfg","newTopologyDescription":{"id":"ce00e92e-a13d-4559-9f06-61fb470acfd5","topologyType":"ReplicaSetNoPrimary","servers":{"localhost:27581":{"address":"localhost:27581","topologyVersion":{"processId":{"$oid":"6735d8000fe1992b6929392b"},"counter":4},"roundTripTime":384,"lastWriteDate":{"$date":"2024-11-14T10:53:27.000Z"},"opTime":{"ts":{"$timestamp":{"t":1731581607,"i":1}},"t":1},"type":"RSSecondary","minWireVersion":25,"maxWireVersion":25,"me":"localhost:27581","setName":"rscfg","setVersion":1,"electionId":{"$oid":"7fffffff0000000000000002"},"primary":"localhost:27581","lastUpdateTime":{"$date":"2024-11-14T10:59:13.260Z"},"logicalSessionTimeoutMinutes":30,"hosts":{"0":"localhost:27581"},"arbiters":{},"passives":{}}},"logicalSessionTimeoutMinutes":30,"setName":"rscfg","compatible":true},"previousTopologyDescription":{"id":"f2564551-16d2-4d62-ad81-4d9040d55104","topologyType":"ReplicaSetNoPrimary","servers":{"localhost:27581":{"address":"localhost:27581","topologyVersion":{"processId":{"$oid":"6735d8000fe1992b6929392b"},"counter":3},"roundTripTime":384,"lastWriteDate":{"$date":"2024-11-14T10:53:27.000Z"},"opTime":{"ts":{"$timestamp":{"t":1731581607,"i":1}},"t":1},"type":"RSSecondary","minWireVersion":25,"maxWireVersion":25,"me":"localhost:27581","setName":"rscfg","setVersion":1,"lastUpdateTime":{"$date":"2024-11-14T10:59:13.259Z"},"logicalSessionTimeoutMinutes":30,"hosts":{"0":"localhost:27581"},"arbiters":{},"passives":{}}},"logicalSessionTimeoutMinutes":30,"setName":"rscfg","compatible":true}}}
E               {"t":{"$date":"2024-11-14T10:59:13.260+00:00"},"s":"I",  "c":"REPL",     "id":21239,   "svc":"S", "ctx":"ReplBatcher","msg":"Oplog applier buffer has been drained","attr":{"term":2}}
E               {"t":{"$date":"2024-11-14T10:59:13.261+00:00"},"s":"I",  "c":"REPL",     "id":21239,   "svc":"S", "ctx":"ReplBatcher","msg":"Oplog applier buffer has been drained","attr":{"term":2}}
E               {"t":{"$date":"2024-11-14T10:59:13.261+00:00"},"s":"I",  "c":"REPL",     "id":21343,   "svc":"S", "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}
E               {"t":{"$date":"2024-11-14T10:59:13.261+00:00"},"s":"I",  "c":"REPL",     "id":21344,   "svc":"S", "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"}
E               {"t":{"$date":"2024-11-14T10:59:13.261+00:00"},"s":"I",  "c":"REPL",     "id":21340,   "svc":"S", "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepUp","totalOpsKilled":0,"totalOpsRunning":6}}}
E               {"t":{"$date":"2024-11-14T10:59:13.261+00:00"},"s":"I",  "c":"REPL",     "id":6015310, "svc":"S", "ctx":"OplogApplier-0","msg":"Starting to transition to primary."}
E               {"t":{"$date":"2024-11-14T10:59:13.261+00:00"},"s":"I",  "c":"REPL",     "id":6015309, "svc":"S", "ctx":"OplogApplier-0","msg":"Logging transition to primary to oplog on stepup"}
E               {"t":{"$date":"2024-11-14T10:59:13.262+00:00"},"s":"W",  "c":"QUERY",    "id":3216000, "svc":"S", "ctx":"OplogApplier-0","msg":"$jsonSchema validator does not allow '_id' field. This validator will reject all documents, consider adding '_id' to the allowed fields."}
E               {"t":{"$date":"2024-11-14T10:59:13.262+00:00"},"s":"W",  "c":"QUERY",    "id":3216000, "svc":"S", "ctx":"OplogApplier-0","msg":"$jsonSchema validator does not allow '_id' field. This validator will reject all documents, consider adding '_id' to the allowed fields."}
E               {"t":{"$date":"2024-11-14T10:59:13.262+00:00"},"s":"I",  "c":"COMMAND",  "id":5324200, "svc":"S", "ctx":"OplogApplier-0","msg":"CMD: collMod","attr":{"cmdObj":{"collMod":"settings","validator":{"$jsonSchema":{"oneOf":[{"properties":{"_id":{"enum":["balancer"]},"mode":{"enum":["full","off"]},"stopped":{"bsonType":"bool"},"activeWindow":{"bsonType":"object","required":["start","stop"]},"_secondaryThrottle":{"oneOf":[{"bsonType":"bool"},{"bsonType":"object"}]},"_waitForDelete":{"bsonType":"bool"},"attemptToBalanceJumboChunks":{"bsonType":"bool"}},"additionalProperties":false},{"properties":{"_id":{"enum":["chunksize"]},"value":{"bsonType":"number","minimum":1,"maximum":1024}},"additionalProperties":false},{"properties":{"_id":{"enum":["automerge","ReadWriteConcernDefaults","audit"]}}}]}},"validationLevel":"strict"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.262+00:00"},"s":"W",  "c":"QUERY",    "id":3216000, "svc":"S", "ctx":"OplogApplier-0","msg":"$jsonSchema validator does not allow '_id' field. This validator will reject all documents, consider adding '_id' to the allowed fields."}
E               {"t":{"$date":"2024-11-14T10:59:13.262+00:00"},"s":"W",  "c":"QUERY",    "id":3216000, "svc":"S", "ctx":"OplogApplier-0","msg":"$jsonSchema validator does not allow '_id' field. This validator will reject all documents, consider adding '_id' to the allowed fields."}
E               {"t":{"$date":"2024-11-14T10:59:13.263+00:00"},"s":"I",  "c":"REPL",     "id":7360104, "svc":"S", "ctx":"OplogApplier-0","msg":"Wrote oplog entry for collMod","attr":{"namespace":"config.$cmd","uuid":{"uuid":{"$uuid":"b510f89c-59e1-4d4e-ba12-62a501614e8c"}},"opTime":{"ts":{"$timestamp":{"t":1731581953,"i":3}},"t":2},"object":{"collMod":"settings","validator":{"$jsonSchema":{"oneOf":[{"properties":{"_id":{"enum":["balancer"]},"mode":{"enum":["full","off"]},"stopped":{"bsonType":"bool"},"activeWindow":{"bsonType":"object","required":["start","stop"]},"_secondaryThrottle":{"oneOf":[{"bsonType":"bool"},{"bsonType":"object"}]},"_waitForDelete":{"bsonType":"bool"},"attemptToBalanceJumboChunks":{"bsonType":"bool"}},"additionalProperties":false},{"properties":{"_id":{"enum":["chunksize"]},"value":{"bsonType":"number","minimum":1,"maximum":1024}},"additionalProperties":false},{"properties":{"_id":{"enum":["automerge","ReadWriteConcernDefaults","audit"]}}}]}},"validationLevel":"strict"}}}
E               {"t":{"$date":"2024-11-14T10:59:13.264+00:00"},"s":"I",  "c":"SHARDING", "id":22049,   "svc":"S", "ctx":"PeriodicShardedIndexConsistencyChecker","msg":"Checking consistency of sharded collection indexes across the cluster"}
E               {"t":{"$date":"2024-11-14T10:59:13.265+00:00"},"s":"E",  "c":"WT",       "id":22435,   "svc":"S", "ctx":"monitoring-keys-for-HMAC","msg":"WiredTiger error message","attr":{"error":2,"message":{"ts_sec":1731581953,"ts_usec":265232,"thread":"1959:0x7f9632dcb700","session_dhandle_name":"file:collection-37-17934271869806947678.wt","session_name":"WT_SESSION.open_cursor","category":"WT_VERB_DEFAULT","category_id":12,"verbose_level":"ERROR","verbose_level_id":-3,"msg":"__posix_open_file:924:/var/lib/mongo/collection-37-17934271869806947678.wt: handle-open: open","error_str":"No such file or directory","error_code":2}}}
E               {"t":{"$date":"2024-11-14T10:59:13.265+00:00"},"s":"F",  "c":"STORAGE",  "id":50883,   "svc":"S", "ctx":"monitoring-keys-for-HMAC","msg":"Cursor not found","attr":{"error":{"code":43,"codeName":"CursorNotFound","errmsg":"Failed to open a WiredTiger cursor. Reason: UnknownError: 2: No such file or directory, uri: table:collection-37-17934271869806947678, config: "}}}
E               {"t":{"$date":"2024-11-14T10:59:13.265+00:00"},"s":"F",  "c":"ASSERT",   "id":23091,   "svc":"S", "ctx":"monitoring-keys-for-HMAC","msg":"Fatal assertion","attr":{"msgid":50883,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_cursor.cpp","line":111}}
E               {"t":{"$date":"2024-11-14T10:59:13.265+00:00"},"s":"F",  "c":"ASSERT",   "id":23092,   "svc":"S", "ctx":"monitoring-keys-for-HMAC","msg":"\n\n***aborting after fassert() failure\n\n"}

cluster.py:462: AssertionError

start_cluster = True, cluster = <cluster.Cluster object at 0x7fecca696b50>
backup_type = 'physical', restore_type = 'pitr'

    @pytest.mark.timeout(900,func_only=True)
    @pytest.mark.parametrize('backup_type',['logical','physical'])
    @pytest.mark.parametrize('restore_type',['base','pitr'])
    def test_general_PBM_T257(start_cluster,cluster,backup_type,restore_type):
        cluster.check_pbm_status()
        client=pymongo.MongoClient(cluster.connection)
        for i in range(600):
            client['test']['test'].insert_one({"doc":i})
    
        backup=cluster.make_backup(backup_type)
        restart = True if backup_type == 'physical' else False
        if restore_type == 'base':
            pymongo.MongoClient(cluster.connection).drop_database('test')
            cluster.make_restore(backup,restart_cluster=restart,check_pbm_status=True,make_resync=False)
            assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == 600
            assert pymongo.MongoClient(cluster.connection)["test"].command("collstats", "test").get("sharded", False)
        else:
            cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=0.5")
            for i in range(600):
                client['test']['test'].insert_one({"doc":i})
                time.sleep(0.1)
            time.sleep(60)
            pitr = datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%S")
            Cluster.log("Time for PITR is: " + pitr)
            pitr_backup="--time=" + pitr
            time.sleep(60)
            pymongo.MongoClient(cluster.connection).drop_database('test')
            cluster.make_restore(pitr_backup,restart_cluster=restart,check_pbm_status=True,make_resync=False)
>           assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == 1200
E           AssertionError: assert 901 == 1200
E            +  where 901 = count_documents({})
E            +    where count_documents = Collection(Database(MongoClient(host=['mongos:27017'], document_class=dict, tz_aware=False, connect=True), 'test'), 'test').count_documents

test_PBM-1355.py:102: AssertionError