start_cluster = True, cluster = <cluster.Cluster object at 0x7f142e08b3d0>
newcluster = <cluster.Cluster object at 0x7f142e6d7d90>

    @pytest.mark.timeout(600, func_only=True)
    def test_logical_pitr_PBM_T253(start_cluster,cluster,newcluster):
        cluster.check_pbm_status()
        cluster.make_backup("logical")
        cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=0.5")
        #Create the first database during oplog slicing
        client=pymongo.MongoClient(cluster.connection)
        client.admin.command("enableSharding", "test")
        client.admin.command("shardCollection", "test.test", key={"_id": "hashed"})
        for i in range(100):
            pymongo.MongoClient(cluster.connection)["test"]["test"].insert_one({"doc":i})
        time.sleep(30)
        pitr = datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%S")
        backup="--time=" + pitr
        Cluster.log("Time for PITR is: " + pitr)
        time.sleep(30)
        cluster.disable_pitr()
        time.sleep(10)
        cluster.destroy()
    
        newcluster.create()
        newcluster.setup_pbm()
        time.sleep(10)
        newcluster.check_pbm_status()
>       newcluster.make_restore(backup,check_pbm_status=True)

test_PBM-1297.py:86: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f142e6d7d90>
name = '--time=2024-09-18T07:19:42', kwargs = {'check_pbm_status': True}
client = MongoClient(host=['newmongos:27017'], document_class=dict, tz_aware=False, connect=True)
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f142e1f4bd0>, exit_status=1, command=b'time...26643951, 15), lastMod: 1 } }, o2: { _id: "test" }, ui: UUID("d449321c-f5da-4f88-a98d-519266301652") }\n', _stderr=b'')
n = <testinfra.host.Host docker://newrscfg01>, timeout = 240, error = ''
host = 'newrscfg01', container = <Container: 49872d42fb52>

    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
            else:
>               assert False, result.stdout + result.stderr
E               AssertionError: Starting restore 2024-09-18T07:21:17.969503978Z to point-in-time 2024-09-18T07:19:42 from '2024-09-18T07:18:19Z'....Started logical restore.
E               Waiting to finish...Error: operation failed with: reply oplog: replay chunk 1726643903.1726643981: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1726643951,"I":17},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"config.databases","Object":[{"Key":"_id","Value":"test"},{"Key":"primary","Value":"rs2"},{"Key":"partitioned","Value":false},{"Key":"version","Value":[{"Key":"uuid","Value":{"Subtype":4,"Data":"S/ZxH+7BRRmY+Tt7skQ3Gg=="}},{"Key":"timestamp","Value":{"T":1726643951,"I":15}},{"Key":"lastMod","Value":1}]}],"Query":[{"Key":"_id","Value":"test"}],"UI":{"Subtype":4,"Data":"1EkyHPXaT4ipjVGSZjAWUg=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (NamespaceNotFound) cannot apply insert or update operation on a non-existent namespace config.databases: { ts: Timestamp(1726643951, 17), t: 1, v: 2, op: "i", ns: "config.databases", o: { _id: "test", primary: "rs2", partitioned: false, version: { uuid: UUID("4bf6711f-eec1-4519-98f9-3b7bb244371a"), timestamp: Timestamp(1726643951, 15), lastMod: 1 } }, o2: { _id: "test" }, ui: UUID("d449321c-f5da-4f88-a98d-519266301652") }

cluster.py:464: AssertionError

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

    @pytest.mark.timeout(300,func_only=True)
    def test_logical_PBM_T221(start_cluster,cluster):
        cluster.check_pbm_status()
        cluster.make_backup("logical")
        cluster.enable_pitr()
    
        client = pymongo.MongoClient(cluster.connection)
        db = client.test
        collection = db.test
        collection.insert_many(documents)
        time.sleep(10)
    
        with client.start_session() as session:
            with session.start_transaction():
                collection.insert_one({"e": 5}, session=session)
                collection.insert_one({"f": 6}, session=session)
                collection.insert_one({"g": 7}, session=session)
                collection.insert_one({"h": 8}, session=session)
                collection.insert_one({"i": 9}, session=session)
                collection.insert_one({"j": 10}, session=session)
                collection.insert_one({"k": 11}, session=session)
                collection.insert_one({"l": 12}, session=session)
                session.commit_transaction()
        time.sleep(10)
        pitr = datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%S")
        backup="--time=" + pitr
        Cluster.log("Time for PITR is: " + pitr)
        time.sleep(10)
    
        cluster.disable_pitr()
        cluster.make_restore(backup,check_pbm_status=True)
        assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == len(documents) + 8
    
        folder="/backups/pbmPitr/rs1/" + datetime.utcnow().strftime("%Y%m%d") + "/"
        for entry in os.scandir(folder):
            file = entry.path
        with open(file, "rb") as f:
            data= f.read()
            docs = bson.decode_all(data)
            for doc in docs:
                if "commitTransaction" in doc["o"]:
                    if doc["o"]["commitTransaction"] == 1:
                        Cluster.log("Oplog entry with commitTransaction: \n" + str(doc))
                        index = docs.index(doc)
                        Cluster.log("Index: " + str(index))
    
        Cluster.log("Modifying oplog backup for shard rs1")
        Cluster.log("Removing oplog entry with commitTransaction and all entries after it")
>       del docs[index:]
E       UnboundLocalError: cannot access local variable 'index' where it is not associated with a value

test_PBM-773.py:102: UnboundLocalError

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

    @pytest.mark.timeout(300, func_only=True)
    def test_logical(start_cluster, cluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
>       backup = cluster.make_backup("logical")

test_azurite.py:69: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f142defffd0>, type = 'logical'

    def make_backup(self, type):
        n = testinfra.get_host("docker://" + self.pbm_cli)
        timeout = time.time() + 120
        while True:
            running = self.get_status()['running']
            Cluster.log("Current operation: " + str(running))
            if not running:
                if type:
                    start = n.run(
                        'pbm backup --out=json --type=' + type)
                else:
                    start = n.run('pbm backup --out=json')
                if start.rc == 0:
                    name = json.loads(start.stdout)['name']
                    Cluster.log("Backup started")
                    break
                elif "resync" in start.stdout:
                    Cluster.log("Resync in progress, retrying: " + start.stdout)
                else:
                    logs = n.check_output("pbm logs -sD -t0")
>                   assert False, "Backup failed" + start.stdout + start.stderr + '\n' + logs
E                   AssertionError: Backup failed{"Error":"get backup metadata: get: context deadline exceeded"}
E                   
E                   2024-09-18T07:30:48Z I [rs2/rs201:27017] pbm-agent:
E                   Version:   2.6.0
E                   Platform:  linux/amd64
E                   GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47
E                   GitBranch: dev
E                   BuildTime: 2024-09-18_06:52_UTC
E                   GoVersion: go1.23.1
E                   2024-09-18T07:30:48Z I [rs1/rs102:27017] pbm-agent:
E                   Version:   2.6.0
E                   Platform:  linux/amd64
E                   GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47
E                   GitBranch: dev
E                   BuildTime: 2024-09-18_06:52_UTC
E                   GoVersion: go1.23.1
E                   2024-09-18T07:30:48Z I [rs2/rs201:27017] starting PITR routine
E                   2024-09-18T07:30:48Z I [rs1/rs102:27017] starting PITR routine
E                   2024-09-18T07:30:48Z I [rs1/rs101:27017] starting PITR routine
E                   2024-09-18T07:30:48Z I [rs1/rs101:27017] pbm-agent:
E                   Version:   2.6.0
E                   Platform:  linux/amd64
E                   GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47
E                   GitBranch: dev
E                   BuildTime: 2024-09-18_06:52_UTC
E                   GoVersion: go1.23.1
E                   2024-09-18T07:30:48Z I [rs1/rs103:27017] pbm-agent:
E                   Version:   2.6.0
E                   Platform:  linux/amd64
E                   GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47
E                   GitBranch: dev
E                   BuildTime: 2024-09-18_06:52_UTC
E                   GoVersion: go1.23.1
E                   2024-09-18T07:30:48Z I [rs1/rs103:27017] starting PITR routine
E                   2024-09-18T07:30:48Z I [rs1/rs102:27017] node: rs1/rs102:27017
E                   2024-09-18T07:30:48Z I [rs1/rs101:27017] node: rs1/rs101:27017
E                   2024-09-18T07:30:48Z I [rs2/rs201:27017] node: rs2/rs201:27017
E                   2024-09-18T07:30:48Z I [rs1/rs103:27017] node: rs1/rs103:27017
E                   2024-09-18T07:30:48Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-09-18T07:30:48Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-09-18T07:30:48Z I [rs2/rs201:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-09-18T07:30:48Z I [rs1/rs102:27017] listening for the commands
E                   2024-09-18T07:30:48Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-09-18T07:30:48Z I [rs2/rs201:27017] listening for the commands
E                   2024-09-18T07:30:48Z I [rs1/rs101:27017] listening for the commands
E                   2024-09-18T07:30:48Z I [rs1/rs103:27017] listening for the commands
E                   2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] pbm-agent:
E                   Version:   2.6.0
E                   Platform:  linux/amd64
E                   GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47
E                   GitBranch: dev
E                   BuildTime: 2024-09-18_06:52_UTC
E                   GoVersion: go1.23.1
E                   2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] starting PITR routine
E                   2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] node: rscfg/rscfg01:27017
E                   2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] listening for the commands
E                   2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] pbm-agent:
E                   Version:   2.6.0
E                   Platform:  linux/amd64
E                   GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47
E                   GitBranch: dev
E                   BuildTime: 2024-09-18_06:52_UTC
E                   GoVersion: go1.23.1
E                   2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] starting PITR routine
E                   2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] node: rscfg/rscfg02:27017
E                   2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-09-18T07:30:50Z I [rs2/rs203:27017] pbm-agent:
E                   Version:   2.6.0
E                   Platform:  linux/amd64
E                   GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47
E                   GitBranch: dev
E                   BuildTime: 2024-09-18_06:52_UTC
E                   GoVersion: go1.23.1
E                   2024-09-18T07:30:50Z I [rs2/rs203:27017] starting PITR routine
E                   2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] listening for the commands
E                   2024-09-18T07:30:50Z I [rs2/rs203:27017] node: rs2/rs203:27017
E                   2024-09-18T07:30:50Z I [rs2/rs203:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-09-18T07:30:50Z I [rs2/rs203:27017] listening for the commands
E                   2024-09-18T07:30:50Z I [rs2/rs202:27017] pbm-agent:
E                   Version:   2.6.0
E                   Platform:  linux/amd64
E                   GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47
E                   GitBranch: dev
E                   BuildTime: 2024-09-18_06:52_UTC
E                   GoVersion: go1.23.1
E                   2024-09-18T07:30:50Z I [rs2/rs202:27017] starting PITR routine
E                   2024-09-18T07:30:50Z I [rs2/rs202:27017] node: rs2/rs202:27017
E                   2024-09-18T07:30:50Z I [rs2/rs202:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-09-18T07:30:50Z I [rs2/rs202:27017] listening for the commands
E                   2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] pbm-agent:
E                   Version:   2.6.0
E                   Platform:  linux/amd64
E                   GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47
E                   GitBranch: dev
E                   BuildTime: 2024-09-18_06:52_UTC
E                   GoVersion: go1.23.1
E                   2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] starting PITR routine
E                   2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] node: rscfg/rscfg03:27017
E                   2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] listening for the commands
E                   2024-09-18T07:30:53Z W [rs2/rs201:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E                   2024-09-18T07:30:53Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E                   2024-09-18T07:30:53Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E                   2024-09-18T07:30:53Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E                   2024-09-18T07:30:53Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-09-18T07:30:53Z E [rs2/rs201:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-09-18T07:30:53Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-09-18T07:30:53Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-09-18T07:30:55Z W [rscfg/rscfg01:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E                   2024-09-18T07:30:55Z E [rscfg/rscfg01:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-09-18T07:30:55Z W [rscfg/rscfg02:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E                   2024-09-18T07:30:55Z E [rscfg/rscfg02:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-09-18T07:30:55Z W [rs2/rs203:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E                   2024-09-18T07:30:55Z E [rs2/rs203:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-09-18T07:30:55Z W [rs2/rs202:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E                   2024-09-18T07:30:55Z E [rs2/rs202:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-09-18T07:30:56Z W [rscfg/rscfg03:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E                   2024-09-18T07:30:56Z E [rscfg/rscfg03:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-09-18T07:30:58Z I [rscfg/rscfg01:27017] got command resync <ts: 1726644657>
E                   2024-09-18T07:30:58Z I [rscfg/rscfg01:27017] got epoch {1726644656 3}
E                   2024-09-18T07:30:58Z I [rscfg/rscfg02:27017] got command resync <ts: 1726644657>
E                   2024-09-18T07:30:58Z I [rscfg/rscfg01:27017] [resync] started
E                   2024-09-18T07:30:58Z I [rscfg/rscfg02:27017] got epoch {1726644656 3}
E                   2024-09-18T07:30:58Z I [rs2/rs203:27017] got command resync <ts: 1726644657>
E                   2024-09-18T07:30:58Z I [rs2/rs203:27017] got epoch {1726644656 3}
E                   2024-09-18T07:30:58Z D [rscfg/rscfg02:27017] [resync] lock not acquired
E                   2024-09-18T07:30:58Z I [rs2/rs203:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:30:58Z D [rscfg/rscfg01:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E                   2024-09-18T07:30:58Z I [rs2/rs202:27017] got command resync <ts: 1726644657>
E                   2024-09-18T07:30:58Z I [rs2/rs202:27017] got epoch {1726644656 3}
E                   2024-09-18T07:30:58Z I [rs2/rs202:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:30:58Z D [rscfg/rscfg01:27017] [resync] got backups list: 0
E                   2024-09-18T07:30:58Z D [rscfg/rscfg01:27017] [resync] got physical restores list: 0
E                   2024-09-18T07:30:58Z D [rscfg/rscfg01:27017] [resync] epoch set to {1726644658 18}
E                   2024-09-18T07:30:58Z I [rscfg/rscfg01:27017] [resync] succeed
E                   2024-09-18T07:30:58Z I [rs1/rs101:27017] got command resync <ts: 1726644657>
E                   2024-09-18T07:30:58Z I [rs2/rs201:27017] got command resync <ts: 1726644657>
E                   2024-09-18T07:30:58Z I [rs1/rs102:27017] got command resync <ts: 1726644657>
E                   2024-09-18T07:30:58Z I [rs1/rs103:27017] got command resync <ts: 1726644657>
E                   2024-09-18T07:30:58Z I [rs1/rs101:27017] got epoch {1726644658 18}
E                   2024-09-18T07:30:58Z I [rs1/rs102:27017] got epoch {1726644658 18}
E                   2024-09-18T07:30:58Z I [rs2/rs201:27017] got epoch {1726644658 18}
E                   2024-09-18T07:30:58Z I [rs1/rs101:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:30:58Z I [rs1/rs102:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:30:58Z I [rs1/rs103:27017] got epoch {1726644658 18}
E                   2024-09-18T07:30:58Z I [rs2/rs201:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:30:58Z I [rs1/rs103:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:30:58Z I [rscfg/rscfg03:27017] got command resync <ts: 1726644657>
E                   2024-09-18T07:30:58Z I [rscfg/rscfg03:27017] got epoch {1726644658 18}
E                   2024-09-18T07:30:58Z D [rscfg/rscfg03:27017] [resync] get lock: duplicate operation: 66ea81b15d7ce290e76422b1 [Resync storage]
E                   2024-09-18T07:30:58Z D [rscfg/rscfg03:27017] [resync] lock not acquired
E                   2024-09-18T07:31:03Z I [rs2/rs201:27017] got command resync <ts: 1726644663>
E                   2024-09-18T07:31:03Z I [rs1/rs101:27017] got command resync <ts: 1726644663>
E                   2024-09-18T07:31:03Z I [rs1/rs103:27017] got command resync <ts: 1726644663>
E                   2024-09-18T07:31:03Z I [rs1/rs102:27017] got command resync <ts: 1726644663>
E                   2024-09-18T07:31:03Z I [rs2/rs201:27017] got epoch {1726644658 18}
E                   2024-09-18T07:31:03Z I [rs1/rs103:27017] got epoch {1726644658 18}
E                   2024-09-18T07:31:03Z I [rs1/rs101:27017] got epoch {1726644658 18}
E                   2024-09-18T07:31:03Z I [rs1/rs103:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:31:03Z I [rs2/rs201:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:31:03Z I [rs1/rs102:27017] got epoch {1726644658 18}
E                   2024-09-18T07:31:03Z I [rs1/rs102:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:31:03Z I [rs1/rs101:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:31:03Z I [rscfg/rscfg03:27017] got command resync <ts: 1726644663>
E                   2024-09-18T07:31:03Z I [rscfg/rscfg03:27017] got epoch {1726644658 18}
E                   2024-09-18T07:31:03Z I [rscfg/rscfg03:27017] [resync] started
E                   2024-09-18T07:31:03Z D [rscfg/rscfg03:27017] [resync] BufferSize is set to 10485760 (~10Mb) | 5
E                   2024-09-18T07:31:03Z D [rscfg/rscfg03:27017] [resync] got backups list: 0
E                   2024-09-18T07:31:03Z D [rscfg/rscfg03:27017] [resync] got physical restores list: 0
E                   2024-09-18T07:31:03Z D [rscfg/rscfg03:27017] [resync] epoch set to {1726644663 154}
E                   2024-09-18T07:31:03Z I [rscfg/rscfg03:27017] [resync] succeed
E                   2024-09-18T07:31:04Z I [rscfg/rscfg01:27017] got command resync <ts: 1726644663>
E                   2024-09-18T07:31:04Z I [rscfg/rscfg01:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rscfg/rscfg02:27017] got command resync <ts: 1726644663>
E                   2024-09-18T07:31:04Z D [rscfg/rscfg01:27017] [resync] get lock: duplicate operation: 66ea81b7f3c13e681043f6a6 [Resync storage]
E                   2024-09-18T07:31:04Z D [rscfg/rscfg01:27017] [resync] lock not acquired
E                   2024-09-18T07:31:04Z I [rscfg/rscfg02:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rscfg/rscfg01:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664>
E                   2024-09-18T07:31:04Z I [rs2/rs203:27017] got command resync <ts: 1726644663>
E                   2024-09-18T07:31:04Z I [rscfg/rscfg01:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rs2/rs203:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rs2/rs203:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:31:04Z E [rscfg/rscfg01:27017] [backup/2024-09-18T07:31:04Z] unable to proceed with the backup, active lock is present
E                   2024-09-18T07:31:04Z D [rscfg/rscfg02:27017] [resync] get lock: duplicate operation: 66ea81b7f3c13e681043f6a6 [Resync storage]
E                   2024-09-18T07:31:04Z I [rs2/rs203:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664>
E                   2024-09-18T07:31:04Z I [rs2/rs202:27017] got command resync <ts: 1726644663>
E                   2024-09-18T07:31:04Z D [rscfg/rscfg02:27017] [resync] lock not acquired
E                   2024-09-18T07:31:04Z I [rs2/rs202:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rs2/rs203:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rscfg/rscfg02:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664>
E                   2024-09-18T07:31:04Z I [rs2/rs202:27017] [resync] not a member of the leader rs
E                   2024-09-18T07:31:04Z I [rscfg/rscfg02:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rs2/rs202:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664>
E                   2024-09-18T07:31:04Z I [rs2/rs202:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rs1/rs101:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664>
E                   2024-09-18T07:31:04Z I [rs2/rs201:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664>
E                   2024-09-18T07:31:04Z I [rs1/rs103:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664>
E                   2024-09-18T07:31:04Z I [rs1/rs102:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664>
E                   2024-09-18T07:31:04Z I [rs2/rs201:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rs1/rs101:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rs1/rs103:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rs1/rs102:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:04Z I [rscfg/rscfg03:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664>
E                   2024-09-18T07:31:04Z I [rscfg/rscfg03:27017] got epoch {1726644663 154}
E                   2024-09-18T07:31:19Z D [rs2/rs203:27017] [backup/2024-09-18T07:31:04Z] nomination timeout
E                   2024-09-18T07:31:19Z D [rs2/rs203:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node
E                   2024-09-18T07:31:19Z D [rscfg/rscfg02:27017] [backup/2024-09-18T07:31:04Z] nomination timeout
E                   2024-09-18T07:31:19Z D [rscfg/rscfg02:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node
E                   2024-09-18T07:31:19Z D [rs2/rs202:27017] [backup/2024-09-18T07:31:04Z] nomination timeout
E                   2024-09-18T07:31:19Z D [rs2/rs202:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node
E                   2024-09-18T07:31:19Z D [rs1/rs102:27017] [backup/2024-09-18T07:31:04Z] nomination timeout
E                   2024-09-18T07:31:19Z D [rs1/rs103:27017] [backup/2024-09-18T07:31:04Z] nomination timeout
E                   2024-09-18T07:31:19Z D [rs2/rs201:27017] [backup/2024-09-18T07:31:04Z] nomination timeout
E                   2024-09-18T07:31:19Z D [rs1/rs101:27017] [backup/2024-09-18T07:31:04Z] nomination timeout
E                   2024-09-18T07:31:19Z D [rs1/rs103:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node
E                   2024-09-18T07:31:19Z D [rs1/rs101:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node
E                   2024-09-18T07:31:19Z D [rs1/rs102:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node
E                   2024-09-18T07:31:19Z D [rs2/rs201:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node
E                   2024-09-18T07:31:19Z D [rscfg/rscfg03:27017] [backup/2024-09-18T07:31:04Z] nomination timeout
E                   2024-09-18T07:31:19Z D [rscfg/rscfg03:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node

cluster.py:393: AssertionError

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

    @pytest.mark.timeout(300,func_only=True)
    def test_logical_timeseries_PBM_T224(start_cluster,cluster):
        cluster.check_pbm_status()
        client=pymongo.MongoClient(cluster.connection)
        mongod_version=client.server_info()["version"]
        if version.parse(mongod_version) < version.parse("5.0.0"):
            pytest.skip("Unsupported version for timeseries")
        pymongo.MongoClient(cluster.connection)["test"].create_collection('test1',timeseries={'timeField':'timestamp','metaField': 'data'})
        for i in range(10):
            pymongo.MongoClient(cluster.connection)["test"]["test1"].insert_one({"timestamp": datetime.now(), "data": i})
            time.sleep(0.1)
        cluster.make_backup("logical")
        cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=0.5")
        time.sleep(30)
        #create new timeseries collection
        pymongo.MongoClient(cluster.connection)["test"].create_collection('test2',timeseries={'timeField':'timestamp','metaField': 'data'})
        for i in range(10):
            pymongo.MongoClient(cluster.connection)["test"]["test1"].insert_one({"timestamp": datetime.now(), "data": i})
            pymongo.MongoClient(cluster.connection)["test"]["test2"].insert_one({"timestamp": datetime.now(), "data": i})
            time.sleep(0.1)
        time.sleep(5)
        pitr = datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%S")
        backup="--time=" + pitr
        Cluster.log("Time for PITR is: " + pitr)
        time.sleep(30)
        pymongo.MongoClient(cluster.connection).drop_database('test')
>       cluster.make_restore(backup,check_pbm_status=True)

test_replicaset.py:110: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f142ded3590>
name = '--time=2024-09-18T07:49:10', kwargs = {'check_pbm_status': True}
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f142e142e90>, exit_status=1, command=b'time...o2: { _id: "test.test2" }, ui: UUID("709167fc-deb2-4c9b-a95e-ee4185b9e8c0"), h: 0, wall: new Date(0) }\n', _stderr=b'')
n = <testinfra.host.Host docker://rs101>, timeout = 240, error = ''
host = 'rs103', container = <Container: 2b3df7ec930d>

    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
            else:
>               assert False, result.stdout + result.stderr
E               AssertionError: Starting restore 2024-09-18T07:49:41.210305672Z to point-in-time 2024-09-18T07:49:10 from '2024-09-18T07:47:59Z'...Started logical restore.
E               Waiting to finish...Error: operation failed with: reply oplog: replay chunk 1726645744.1726645774: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1726645744,"I":6},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"test.system.views","Object":[{"Key":"_id","Value":"test.test2"},{"Key":"viewOn","Value":"system.buckets.test2"},{"Key":"pipeline","Value":[[{"Key":"$_internalUnpackBucket","Value":[{"Key":"timeField","Value":"timestamp"},{"Key":"metaField","Value":"data"},{"Key":"bucketMaxSpanSeconds","Value":3600}]}]]}],"Query":[{"Key":"_id","Value":"test.test2"}],"UI":{"Subtype":4,"Data":"cJFn/N6yTJupXu5BhbnowA=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (NamespaceNotFound) Failed to apply operation due to missing collection (709167fc-deb2-4c9b-a95e-ee4185b9e8c0): { ts: Timestamp(1726645744, 6), t: 1, v: 2, op: "i", ns: "test.system.views", o: { _id: "test.test2", viewOn: "system.buckets.test2", pipeline: [ { $_internalUnpackBucket: { timeField: "timestamp", metaField: "data", bucketMaxSpanSeconds: 3600 } } ] }, o2: { _id: "test.test2" }, ui: UUID("709167fc-deb2-4c9b-a95e-ee4185b9e8c0"), h: 0, wall: new Date(0) }

cluster.py:464: AssertionError