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

    @pytest.mark.timeout(600,func_only=True)
    def test_external_PBM_T240(start_cluster,cluster):
        time.sleep(5)
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        backup = cluster.external_backup_start()
        result=pymongo.MongoClient(cluster.connection)["test"]["test"].delete_many({})
        assert int(result.deleted_count) == len(documents)
        cluster.external_backup_copy(backup)
        cluster.external_backup_finish(backup)
        time.sleep(10)
>       restore=cluster.external_restore_start()

test_PBM-979.py:181: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f36ed49b4d0>

    def external_restore_start(self):
        timeout = time.time() + 60
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                n = testinfra.get_host("docker://" + self.pbm_cli)
                logs = n.check_output("pbm logs -sD -t0")
>               assert False, "Cannot start restore, another operation running: " + str(self.get_status()['running']) + "\n" + logs
E               AssertionError: Cannot start restore, another operation running: {'type': 'backup', 'opID': '66ec2372687dbda9936a5031', 'name': '2024-09-19T13:13:22Z', 'startTS': 1726751602, 'status': 'copyDone'}
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] starting PITR routine
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] starting PITR routine
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] node: rs1/rs103:27017
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] starting PITR routine
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] node: rs1/rs102:27017
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] node: rs1/rs101:27017
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] listening for the commands
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] listening for the commands
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] listening for the commands
E               2024-09-19T13:13:02Z I [rs1/rs104:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:13:02Z I [rs1/rs104:27017] node: rs1/rs104:27017
E               2024-09-19T13:13:02Z I [rs1/rs104:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:13:02Z I [rs1/rs104:27017] listening for the commands
E               2024-09-19T13:13:05Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:13:05Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:13:05Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:05Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:05Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:13:05Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:07Z W [rs1/rs104:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:13:07Z E [rs1/rs104:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:10Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:10Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:10Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:12Z W [rs1/rs104:27017] [agentCheckup] storage is not initialized
E               2024-09-19T13:13:12Z I [rs1/rs104:27017] got command resync <ts: 1726751591>
E               2024-09-19T13:13:12Z I [rs1/rs104:27017] got epoch {1726751590 6}
E               2024-09-19T13:13:12Z I [rs1/rs104:27017] [resync] started
E               2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E               2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] got backups list: 0
E               2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] got physical restores list: 0
E               2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] epoch set to {1726751592 10}
E               2024-09-19T13:13:12Z I [rs1/rs104:27017] [resync] succeed
E               2024-09-19T13:13:12Z I [rs1/rs103:27017] got command resync <ts: 1726751591>
E               2024-09-19T13:13:12Z I [rs1/rs102:27017] got command resync <ts: 1726751591>
E               2024-09-19T13:13:12Z I [rs1/rs101:27017] got command resync <ts: 1726751591>
E               2024-09-19T13:13:12Z I [rs1/rs103:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:12Z I [rs1/rs102:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:12Z I [rs1/rs101:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:12Z D [rs1/rs101:27017] [resync] lock not acquired
E               2024-09-19T13:13:12Z D [rs1/rs102:27017] [resync] lock not acquired
E               2024-09-19T13:13:12Z D [rs1/rs103:27017] [resync] get lock: duplicate operation: 66ec236782f7d809ca024cc6 [Resync storage]
E               2024-09-19T13:13:12Z D [rs1/rs103:27017] [resync] lock not acquired
E               2024-09-19T13:13:22Z I [rs1/rs103:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
E               2024-09-19T13:13:22Z I [rs1/rs102:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
E               2024-09-19T13:13:22Z I [rs1/rs103:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:22Z I [rs1/rs101:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
E               2024-09-19T13:13:22Z I [rs1/rs102:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:22Z I [rs1/rs101:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] init backup meta
E               2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] nomination list for rs1: [[rs103:27017] [rs102:27017] [rs101:27017]]
E               2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] nomination rs1, set candidates [rs103:27017]
E               2024-09-19T13:13:22Z I [rs1/rs103:27017] [backup/2024-09-19T13:13:22Z] backup started
E               2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] skip after nomination, probably started by another node
E               2024-09-19T13:13:23Z I [rs1/rs104:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
E               2024-09-19T13:13:23Z I [rs1/rs104:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:23Z D [rs1/rs102:27017] [backup/2024-09-19T13:13:22Z] skip after nomination, probably started by another node
E               2024-09-19T13:13:23Z D [rs1/rs104:27017] [backup/2024-09-19T13:13:22Z] skip after nomination, probably started by another node
E               2024-09-19T13:13:23Z D [rs1/rs103:27017] [backup/2024-09-19T13:13:22Z] backup cursor id: de4f11d4-840b-44fb-9cce-13cce6ad75c3
E               2024-09-19T13:13:26Z D [rs1/rs103:27017] [backup/2024-09-19T13:13:22Z] set journal up to {1726751603 5}
E               2024-09-19T13:13:27Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] bcp nomination: rs1 won by rs103:27017

cluster.py:866: AssertionError

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

    @pytest.mark.timeout(600,func_only=True)
    def test_external_PBM_T239(start_cluster,cluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        backup = cluster.external_backup_start()
        result=pymongo.MongoClient(cluster.connection)["test"]["test"].delete_many({})
        assert int(result.deleted_count) == len(documents)
        cluster.external_backup_copy(backup)
        cluster.external_backup_finish(backup)
        time.sleep(10)
    
>       restore=cluster.external_restore_start()

test_vault.py:74: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f36ebe4f410>

    def external_restore_start(self):
        timeout = time.time() + 60
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                n = testinfra.get_host("docker://" + self.pbm_cli)
                logs = n.check_output("pbm logs -sD -t0")
>               assert False, "Cannot start restore, another operation running: " + str(self.get_status()['running']) + "\n" + logs
E               AssertionError: Cannot start restore, another operation running: {'type': 'backup', 'opID': '66ec27e444069529e3dbeaae', 'name': '2024-09-19T13:32:20Z', 'startTS': 1726752740, 'status': 'copyDone'}
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] starting PITR routine
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] starting PITR routine
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] node: rs1/rs102:27017
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] starting PITR routine
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] node: rs1/rs101:27017
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] listening for the commands
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] node: rs1/rs103:27017
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] listening for the commands
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] listening for the commands
E               2024-09-19T13:32:13Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:32:13Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:32:13Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:32:13Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:32:13Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:32:13Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:32:15Z I [rs1/rs102:27017] got command resync <ts: 1726752734>
E               2024-09-19T13:32:15Z I [rs1/rs101:27017] got command resync <ts: 1726752734>
E               2024-09-19T13:32:15Z I [rs1/rs102:27017] got epoch {1726752733 11}
E               2024-09-19T13:32:15Z I [rs1/rs101:27017] got epoch {1726752733 11}
E               2024-09-19T13:32:15Z I [rs1/rs103:27017] got command resync <ts: 1726752734>
E               2024-09-19T13:32:15Z I [rs1/rs103:27017] got epoch {1726752733 11}
E               2024-09-19T13:32:15Z I [rs1/rs102:27017] [resync] started
E               2024-09-19T13:32:15Z D [rs1/rs101:27017] [resync] lock not acquired
E               2024-09-19T13:32:15Z D [rs1/rs103:27017] [resync] lock not acquired
E               2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E               2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] got backups list: 0
E               2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] got physical restores list: 2
E               2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] epoch set to {1726752735 16}
E               2024-09-19T13:32:15Z I [rs1/rs102:27017] [resync] succeed
E               2024-09-19T13:32:20Z I [rs1/rs101:27017] got command backup [name: 2024-09-19T13:32:20Z, compression: s2 (level: default)] <ts: 1726752740>
E               2024-09-19T13:32:20Z I [rs1/rs102:27017] got command backup [name: 2024-09-19T13:32:20Z, compression: s2 (level: default)] <ts: 1726752740>
E               2024-09-19T13:32:20Z I [rs1/rs101:27017] got epoch {1726752735 16}
E               2024-09-19T13:32:20Z I [rs1/rs102:27017] got epoch {1726752735 16}
E               2024-09-19T13:32:20Z I [rs1/rs103:27017] got command backup [name: 2024-09-19T13:32:20Z, compression: s2 (level: default)] <ts: 1726752740>
E               2024-09-19T13:32:20Z I [rs1/rs103:27017] got epoch {1726752735 16}
E               2024-09-19T13:32:20Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] init backup meta
E               2024-09-19T13:32:20Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] nomination list for rs1: [[rs102:27017 rs103:27017] [rs101:27017]]
E               2024-09-19T13:32:20Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] nomination rs1, set candidates [rs102:27017 rs103:27017]
E               2024-09-19T13:32:21Z I [rs1/rs102:27017] [backup/2024-09-19T13:32:20Z] backup started
E               2024-09-19T13:32:21Z D [rs1/rs103:27017] [backup/2024-09-19T13:32:20Z] skip: lock not acquired
E               2024-09-19T13:32:21Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] skip after nomination, probably started by another node
E               2024-09-19T13:32:22Z D [rs1/rs102:27017] [backup/2024-09-19T13:32:20Z] backup cursor id: 35edf6ca-27ff-406d-a5e0-c1eb502a819e
E               2024-09-19T13:32:25Z D [rs1/rs102:27017] [backup/2024-09-19T13:32:20Z] set journal up to {1726752741 6}
E               2024-09-19T13:32:25Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] bcp nomination: rs1 won by rs102:27017

cluster.py:866: AssertionError