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

    @pytest.mark.timeout(300,func_only=True)
    def test_logical_PBM_T221(start_cluster,cluster):
        cluster.check_pbm_status()
>       cluster.make_backup("logical")

test_PBM-773.py:57: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f0f5cb14e10>, 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-11-14T12:43:56Z I [rs2/rs201:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T12:43:56Z I [rs2/rs201:27017] starting PITR routine
E                   2024-11-14T12:43:56Z I [rs2/rs201:27017] node: rs2/rs201:27017
E                   2024-11-14T12:43:56Z I [rs1/rs101:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T12:43:56Z I [rs1/rs101:27017] starting PITR routine
E                   2024-11-14T12:43:56Z E [rs2/rs201:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:43:56Z I [rs1/rs102:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T12:43:56Z I [rs1/rs102:27017] starting PITR routine
E                   2024-11-14T12:43:56Z I [rs1/rs102:27017] node: rs1/rs102:27017
E                   2024-11-14T12:43:56Z I [rs1/rs101:27017] node: rs1/rs101:27017
E                   2024-11-14T12:43:56Z I [rs2/rs201:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T12:43:56Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:43:56Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:43:56Z I [rs1/rs103:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T12:43:56Z I [rs1/rs103:27017] starting PITR routine
E                   2024-11-14T12:43:56Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T12:43:56Z I [rs2/rs201:27017] listening for the commands
E                   2024-11-14T12:43:56Z I [rs1/rs103:27017] node: rs1/rs103:27017
E                   2024-11-14T12:43:56Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T12:43:56Z I [rs1/rs101:27017] listening for the commands
E                   2024-11-14T12:43:56Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:43:56Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T12:43:56Z I [rs1/rs102:27017] listening for the commands
E                   2024-11-14T12:43:56Z I [rs1/rs103:27017] listening for the commands
E                   2024-11-14T12:43:58Z I [rscfg/rscfg01:27017] starting PITR routine
E                   2024-11-14T12:43:58Z I [rscfg/rscfg01:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T12:43:58Z E [rscfg/rscfg01:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:43:58Z I [rscfg/rscfg01:27017] node: rscfg/rscfg01:27017
E                   2024-11-14T12:43:58Z I [rscfg/rscfg01:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T12:43:58Z I [rscfg/rscfg02:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T12:43:58Z I [rscfg/rscfg01:27017] listening for the commands
E                   2024-11-14T12:43:58Z I [rscfg/rscfg02:27017] starting PITR routine
E                   2024-11-14T12:43:58Z E [rscfg/rscfg02:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:43:58Z I [rscfg/rscfg02:27017] node: rscfg/rscfg02:27017
E                   2024-11-14T12:43:58Z I [rscfg/rscfg02:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T12:43:58Z I [rscfg/rscfg02:27017] listening for the commands
E                   2024-11-14T12:43:58Z I [rs2/rs203:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T12:43:58Z I [rs2/rs203:27017] starting PITR routine
E                   2024-11-14T12:43:58Z I [rs2/rs203:27017] node: rs2/rs203:27017
E                   2024-11-14T12:43:58Z I [rs2/rs202:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T12:43:58Z I [rs2/rs202:27017] starting PITR routine
E                   2024-11-14T12:43:58Z I [rs2/rs202:27017] node: rs2/rs202:27017
E                   2024-11-14T12:43:58Z E [rs2/rs203:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:43:58Z E [rs2/rs202:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:43:58Z I [rs2/rs203:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T12:43:58Z I [rs2/rs202:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T12:43:58Z I [rs2/rs203:27017] listening for the commands
E                   2024-11-14T12:43:58Z I [rs2/rs202:27017] listening for the commands
E                   2024-11-14T12:43:59Z I [rscfg/rscfg03:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T12:43:59Z I [rscfg/rscfg03:27017] starting PITR routine
E                   2024-11-14T12:43:59Z I [rscfg/rscfg03:27017] node: rscfg/rscfg03:27017
E                   2024-11-14T12:43:59Z E [rscfg/rscfg03:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:43:59Z I [rscfg/rscfg03:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T12:43:59Z I [rscfg/rscfg03:27017] listening for the commands
E                   2024-11-14T12:44:01Z E [rs2/rs201:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:44:01Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:44:01Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:44:01Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:44:03Z E [rscfg/rscfg01:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:44:03Z E [rscfg/rscfg02:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:44:03Z E [rs2/rs203:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:44:03Z E [rs2/rs202:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:44:04Z E [rscfg/rscfg03:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T12:44:06Z I [rscfg/rscfg01:27017] got command resync <ts: 1731588246>, opid: 6735f096748db213c78f2505
E                   2024-11-14T12:44:06Z I [rscfg/rscfg01:27017] got epoch {1731588244 2}
E                   2024-11-14T12:44:06Z I [rscfg/rscfg01:27017] [resync] started
E                   2024-11-14T12:44:06Z I [rscfg/rscfg02:27017] got command resync <ts: 1731588246>, opid: 6735f096748db213c78f2505
E                   2024-11-14T12:44:06Z I [rscfg/rscfg02:27017] got epoch {1731588244 2}
E                   2024-11-14T12:44:06Z D [rscfg/rscfg02:27017] [resync] lock not acquired
E                   2024-11-14T12:44:06Z D [rscfg/rscfg01:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E                   2024-11-14T12:44:06Z D [rscfg/rscfg01:27017] [resync] got backups list: 0
E                   2024-11-14T12:44:06Z I [rs2/rs203:27017] got command resync <ts: 1731588246>, opid: 6735f096748db213c78f2505
E                   2024-11-14T12:44:06Z I [rs2/rs203:27017] got epoch {1731588244 2}
E                   2024-11-14T12:44:06Z D [rscfg/rscfg01:27017] [resync] got physical restores list: 0
E                   2024-11-14T12:44:06Z I [rs2/rs202:27017] got command resync <ts: 1731588246>, opid: 6735f096748db213c78f2505
E                   2024-11-14T12:44:06Z I [rs2/rs203:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:06Z I [rs2/rs202:27017] got epoch {1731588244 2}
E                   2024-11-14T12:44:06Z D [rscfg/rscfg01:27017] [resync] epoch set to {1731588246 20}
E                   2024-11-14T12:44:06Z I [rs2/rs202:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:06Z I [rscfg/rscfg01:27017] [resync] succeed
E                   2024-11-14T12:44:06Z I [rs2/rs201:27017] got command resync <ts: 1731588246>, opid: 6735f096748db213c78f2505
E                   2024-11-14T12:44:06Z I [rs1/rs101:27017] got command resync <ts: 1731588246>, opid: 6735f096748db213c78f2505
E                   2024-11-14T12:44:06Z I [rs2/rs201:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:06Z I [rs1/rs102:27017] got command resync <ts: 1731588246>, opid: 6735f096748db213c78f2505
E                   2024-11-14T12:44:06Z I [rs1/rs103:27017] got command resync <ts: 1731588246>, opid: 6735f096748db213c78f2505
E                   2024-11-14T12:44:06Z I [rs1/rs101:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:06Z I [rs2/rs201:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:06Z I [rs1/rs102:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:06Z I [rs1/rs101:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:06Z I [rs1/rs103:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:06Z I [rs1/rs102:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:06Z I [rs1/rs103:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:06Z I [rscfg/rscfg03:27017] got command resync <ts: 1731588246>, opid: 6735f096748db213c78f2505
E                   2024-11-14T12:44:06Z I [rscfg/rscfg03:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:06Z D [rscfg/rscfg03:27017] [resync] get lock: duplicate operation: 6735f096748db213c78f2505 [Resync storage]
E                   2024-11-14T12:44:06Z D [rscfg/rscfg03:27017] [resync] lock not acquired
E                   2024-11-14T12:44:11Z I [rs2/rs203:27017] got command resync <ts: 1731588251>, opid: 6735f09bfe576de848e21c2a
E                   2024-11-14T12:44:11Z I [rs2/rs202:27017] got command resync <ts: 1731588251>, opid: 6735f09bfe576de848e21c2a
E                   2024-11-14T12:44:11Z I [rs2/rs203:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:11Z I [rs2/rs202:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:11Z I [rs2/rs203:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:11Z I [rs2/rs202:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:11Z I [rs2/rs201:27017] got command resync <ts: 1731588251>, opid: 6735f09bfe576de848e21c2a
E                   2024-11-14T12:44:11Z I [rs1/rs101:27017] got command resync <ts: 1731588251>, opid: 6735f09bfe576de848e21c2a
E                   2024-11-14T12:44:11Z I [rs2/rs201:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:11Z I [rs1/rs101:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:11Z I [rs1/rs103:27017] got command resync <ts: 1731588251>, opid: 6735f09bfe576de848e21c2a
E                   2024-11-14T12:44:11Z I [rs2/rs201:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:11Z I [rs1/rs102:27017] got command resync <ts: 1731588251>, opid: 6735f09bfe576de848e21c2a
E                   2024-11-14T12:44:11Z I [rs1/rs101:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:11Z I [rs1/rs103:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:11Z I [rs1/rs102:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:11Z I [rs1/rs103:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:11Z I [rs1/rs102:27017] [resync] not a member of the leader rs
E                   2024-11-14T12:44:11Z I [rscfg/rscfg03:27017] got command resync <ts: 1731588251>, opid: 6735f09bfe576de848e21c2a
E                   2024-11-14T12:44:11Z I [rscfg/rscfg03:27017] got epoch {1731588246 20}
E                   2024-11-14T12:44:11Z I [rscfg/rscfg03:27017] [resync] started
E                   2024-11-14T12:44:11Z D [rscfg/rscfg03:27017] [resync] got backups list: 0
E                   2024-11-14T12:44:11Z D [rscfg/rscfg03:27017] [resync] got physical restores list: 0
E                   2024-11-14T12:44:11Z D [rscfg/rscfg03:27017] [resync] epoch set to {1731588251 71}
E                   2024-11-14T12:44:11Z I [rscfg/rscfg03:27017] [resync] succeed
E                   2024-11-14T12:44:12Z I [rscfg/rscfg01:27017] got command resync <ts: 1731588251>, opid: 6735f09bfe576de848e21c2a
E                   2024-11-14T12:44:12Z I [rscfg/rscfg01:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z I [rscfg/rscfg02:27017] got command resync <ts: 1731588251>, opid: 6735f09bfe576de848e21c2a
E                   2024-11-14T12:44:12Z D [rscfg/rscfg01:27017] [resync] get lock: duplicate operation: 6735f09bfe576de848e21c2a [Resync storage]
E                   2024-11-14T12:44:12Z I [rscfg/rscfg02:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z D [rscfg/rscfg01:27017] [resync] lock not acquired
E                   2024-11-14T12:44:12Z I [rscfg/rscfg01:27017] got command backup [name: 2024-11-14T12:44:11Z, compression: none (level: default)] <ts: 1731588251>, opid: 6735f09b2b9fe05197fac7cb
E                   2024-11-14T12:44:12Z I [rscfg/rscfg01:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z D [rscfg/rscfg02:27017] [resync] get lock: duplicate operation: 6735f09bfe576de848e21c2a [Resync storage]
E                   2024-11-14T12:44:12Z E [rscfg/rscfg01:27017] [backup/2024-11-14T12:44:11Z] unable to proceed with the backup, active lock is present
E                   2024-11-14T12:44:12Z D [rscfg/rscfg02:27017] [resync] lock not acquired
E                   2024-11-14T12:44:12Z I [rscfg/rscfg02:27017] got command backup [name: 2024-11-14T12:44:11Z, compression: none (level: default)] <ts: 1731588251>, opid: 6735f09b2b9fe05197fac7cb
E                   2024-11-14T12:44:12Z I [rs2/rs203:27017] got command backup [name: 2024-11-14T12:44:11Z, compression: none (level: default)] <ts: 1731588251>, opid: 6735f09b2b9fe05197fac7cb
E                   2024-11-14T12:44:12Z I [rscfg/rscfg02:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z I [rs2/rs202:27017] got command backup [name: 2024-11-14T12:44:11Z, compression: none (level: default)] <ts: 1731588251>, opid: 6735f09b2b9fe05197fac7cb
E                   2024-11-14T12:44:12Z I [rs2/rs203:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z I [rs2/rs202:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z I [rs2/rs201:27017] got command backup [name: 2024-11-14T12:44:11Z, compression: none (level: default)] <ts: 1731588251>, opid: 6735f09b2b9fe05197fac7cb
E                   2024-11-14T12:44:12Z I [rs1/rs101:27017] got command backup [name: 2024-11-14T12:44:11Z, compression: none (level: default)] <ts: 1731588251>, opid: 6735f09b2b9fe05197fac7cb
E                   2024-11-14T12:44:12Z I [rs2/rs201:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z I [rs1/rs101:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z I [rs1/rs103:27017] got command backup [name: 2024-11-14T12:44:11Z, compression: none (level: default)] <ts: 1731588251>, opid: 6735f09b2b9fe05197fac7cb
E                   2024-11-14T12:44:12Z I [rs1/rs102:27017] got command backup [name: 2024-11-14T12:44:11Z, compression: none (level: default)] <ts: 1731588251>, opid: 6735f09b2b9fe05197fac7cb
E                   2024-11-14T12:44:12Z I [rs1/rs103:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z I [rs1/rs102:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:12Z I [rscfg/rscfg03:27017] got command backup [name: 2024-11-14T12:44:11Z, compression: none (level: default)] <ts: 1731588251>, opid: 6735f09b2b9fe05197fac7cb
E                   2024-11-14T12:44:12Z I [rscfg/rscfg03:27017] got epoch {1731588251 71}
E                   2024-11-14T12:44:27Z D [rscfg/rscfg02:27017] [backup/2024-11-14T12:44:11Z] nomination timeout
E                   2024-11-14T12:44:27Z D [rscfg/rscfg02:27017] [backup/2024-11-14T12:44:11Z] skip after nomination, probably started by another node
E                   2024-11-14T12:44:27Z D [rs2/rs203:27017] [backup/2024-11-14T12:44:11Z] nomination timeout
E                   2024-11-14T12:44:27Z D [rs2/rs202:27017] [backup/2024-11-14T12:44:11Z] nomination timeout
E                   2024-11-14T12:44:27Z D [rs2/rs203:27017] [backup/2024-11-14T12:44:11Z] skip after nomination, probably started by another node
E                   2024-11-14T12:44:27Z D [rs2/rs202:27017] [backup/2024-11-14T12:44:11Z] skip after nomination, probably started by another node
E                   2024-11-14T12:44:27Z D [rs2/rs201:27017] [backup/2024-11-14T12:44:11Z] nomination timeout
E                   2024-11-14T12:44:27Z D [rs1/rs101:27017] [backup/2024-11-14T12:44:11Z] nomination timeout
E                   2024-11-14T12:44:27Z D [rs2/rs201:27017] [backup/2024-11-14T12:44:11Z] skip after nomination, probably started by another node
E                   2024-11-14T12:44:27Z D [rs1/rs101:27017] [backup/2024-11-14T12:44:11Z] skip after nomination, probably started by another node
E                   2024-11-14T12:44:27Z D [rs1/rs103:27017] [backup/2024-11-14T12:44:11Z] nomination timeout
E                   2024-11-14T12:44:27Z D [rs1/rs102:27017] [backup/2024-11-14T12:44:11Z] nomination timeout
E                   2024-11-14T12:44:27Z D [rs1/rs103:27017] [backup/2024-11-14T12:44:11Z] skip after nomination, probably started by another node
E                   2024-11-14T12:44:27Z D [rs1/rs102:27017] [backup/2024-11-14T12:44:11Z] skip after nomination, probably started by another node
E                   2024-11-14T12:44:27Z D [rscfg/rscfg03:27017] [backup/2024-11-14T12:44:11Z] nomination timeout
E                   2024-11-14T12:44:27Z D [rscfg/rscfg03:27017] [backup/2024-11-14T12:44:11Z] skip after nomination, probably started by another node

cluster.py:393: AssertionError

start_cluster = True, cluster = <cluster.Cluster object at 0x7f0f5cc973d0>
collection = 'updates'

    @pytest.mark.timeout(300,func_only=True)
    @pytest.mark.parametrize('collection',['inserts','replaces','updates','deletes','indexes'])
    def test_logical_pitr_crud_PBM_T270(start_cluster,cluster,collection):
        cluster.check_pbm_status()
>       cluster.make_backup("logical")

test_rename_replicaset.py:54: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f0f5cc973d0>, 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-11-14T13:10:52Z I [rs1/rs102:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T13:10:52Z I [rs1/rs102:27017] starting PITR routine
E                   2024-11-14T13:10:52Z I [rs1/rs103:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T13:10:52Z I [rs1/rs103:27017] starting PITR routine
E                   2024-11-14T13:10:52Z I [rs1/rs101:27017] starting PITR routine
E                   2024-11-14T13:10:52Z I [rs1/rs101:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T13:10:52Z I [rs1/rs102:27017] node: rs1/rs102:27017
E                   2024-11-14T13:10:52Z I [rs1/rs101:27017] node: rs1/rs101:27017
E                   2024-11-14T13:10:52Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:10:52Z I [rs1/rs103:27017] node: rs1/rs103:27017
E                   2024-11-14T13:10:52Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:10:52Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:10:52Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T13:10:52Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T13:10:52Z I [rs1/rs102:27017] listening for the commands
E                   2024-11-14T13:10:52Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T13:10:52Z I [rs1/rs101:27017] listening for the commands
E                   2024-11-14T13:10:52Z I [rs1/rs103:27017] listening for the commands
E                   2024-11-14T13:10:57Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:10:57Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:10:57Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:10:59Z I [rs1/rs102:27017] got command resync <ts: 1731589859>, opid: 6735f6e31e3ac33df64afebc
E                   2024-11-14T13:10:59Z I [rs1/rs102:27017] got epoch {1731589857 6}
E                   2024-11-14T13:10:59Z I [rs1/rs101:27017] got command resync <ts: 1731589859>, opid: 6735f6e31e3ac33df64afebc
E                   2024-11-14T13:10:59Z I [rs1/rs103:27017] got command resync <ts: 1731589859>, opid: 6735f6e31e3ac33df64afebc
E                   2024-11-14T13:10:59Z I [rs1/rs101:27017] got epoch {1731589857 6}
E                   2024-11-14T13:10:59Z I [rs1/rs103:27017] got epoch {1731589857 6}
E                   2024-11-14T13:10:59Z I [rs1/rs102:27017] [resync] started
E                   2024-11-14T13:10:59Z D [rs1/rs101:27017] [resync] lock not acquired
E                   2024-11-14T13:10:59Z D [rs1/rs103:27017] [resync] lock not acquired
E                   2024-11-14T13:10:59Z D [rs1/rs102:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E                   2024-11-14T13:10:59Z D [rs1/rs102:27017] [resync] got backups list: 0
E                   2024-11-14T13:10:59Z D [rs1/rs102:27017] [resync] got physical restores list: 0
E                   2024-11-14T13:10:59Z D [rs1/rs102:27017] [resync] epoch set to {1731589859 19}
E                   2024-11-14T13:10:59Z I [rs1/rs102:27017] [resync] succeed
E                   2024-11-14T13:11:05Z I [rs1/rs102:27017] got command resync <ts: 1731589864>, opid: 6735f6e8b253b4e41adf9f64
E                   2024-11-14T13:11:05Z I [rs1/rs102:27017] got epoch {1731589859 19}
E                   2024-11-14T13:11:05Z I [rs1/rs103:27017] got command resync <ts: 1731589864>, opid: 6735f6e8b253b4e41adf9f64
E                   2024-11-14T13:11:05Z I [rs1/rs101:27017] got command resync <ts: 1731589864>, opid: 6735f6e8b253b4e41adf9f64
E                   2024-11-14T13:11:05Z I [rs1/rs103:27017] got epoch {1731589859 19}
E                   2024-11-14T13:11:05Z I [rs1/rs101:27017] got epoch {1731589859 19}
E                   2024-11-14T13:11:05Z I [rs1/rs102:27017] [resync] started
E                   2024-11-14T13:11:05Z D [rs1/rs103:27017] [resync] lock not acquired
E                   2024-11-14T13:11:05Z I [rs1/rs103:27017] got command backup [name: 2024-11-14T13:11:05Z, compression: none (level: default)] <ts: 1731589865>, opid: 6735f6e90a3fca9f41e7d569
E                   2024-11-14T13:11:05Z D [rs1/rs101:27017] [resync] lock not acquired
E                   2024-11-14T13:11:05Z D [rs1/rs102:27017] [resync] got backups list: 0
E                   2024-11-14T13:11:05Z I [rs1/rs103:27017] got epoch {1731589859 19}
E                   2024-11-14T13:11:05Z I [rs1/rs101:27017] got command backup [name: 2024-11-14T13:11:05Z, compression: none (level: default)] <ts: 1731589865>, opid: 6735f6e90a3fca9f41e7d569
E                   2024-11-14T13:11:05Z D [rs1/rs102:27017] [resync] got physical restores list: 0
E                   2024-11-14T13:11:05Z I [rs1/rs101:27017] got epoch {1731589859 19}
E                   2024-11-14T13:11:05Z D [rs1/rs102:27017] [resync] epoch set to {1731589865 59}
E                   2024-11-14T13:11:05Z E [rs1/rs101:27017] [backup/2024-11-14T13:11:05Z] unable to proceed with the backup, active lock is present
E                   2024-11-14T13:11:05Z I [rs1/rs102:27017] [resync] succeed
E                   2024-11-14T13:11:05Z I [rs1/rs102:27017] got command backup [name: 2024-11-14T13:11:05Z, compression: none (level: default)] <ts: 1731589865>, opid: 6735f6e90a3fca9f41e7d569
E                   2024-11-14T13:11:05Z I [rs1/rs102:27017] got epoch {1731589865 59}
E                   2024-11-14T13:11:20Z D [rs1/rs103:27017] [backup/2024-11-14T13:11:05Z] nomination timeout
E                   2024-11-14T13:11:20Z D [rs1/rs103:27017] [backup/2024-11-14T13:11:05Z] skip after nomination, probably started by another node
E                   2024-11-14T13:11:20Z D [rs1/rs102:27017] [backup/2024-11-14T13:11:05Z] nomination timeout
E                   2024-11-14T13:11:20Z D [rs1/rs102:27017] [backup/2024-11-14T13:11:05Z] skip after nomination, probably started by another node

cluster.py:393: AssertionError

start_cluster = True, cluster = <cluster.Cluster object at 0x7f0f5cc973d0>
collection = 'inserts'

    @pytest.mark.timeout(300,func_only=True)
    @pytest.mark.parametrize('collection',['inserts','replaces','updates','deletes'])
    def test_logical_pitr_with_txn_PBM_T271(start_cluster,cluster,collection):
        cluster.check_pbm_status()
>       cluster.make_backup("logical")

test_rename_replicaset.py:107: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f0f5cc973d0>, 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-11-14T13:16:15Z I [rs1/rs102:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T13:16:15Z I [rs1/rs102:27017] starting PITR routine
E                   2024-11-14T13:16:15Z I [rs1/rs101:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T13:16:15Z I [rs1/rs101:27017] starting PITR routine
E                   2024-11-14T13:16:15Z I [rs1/rs103:27017] pbm-agent:
E                   Version:   2.7.0
E                   Platform:  linux/amd64
E                   GitCommit: 7c1a42639e696fe9b3aa38a3172a901127334157
E                   GitBranch: dev
E                   BuildTime: 2024-11-14_12:06_UTC
E                   GoVersion: go1.23.3
E                   2024-11-14T13:16:15Z I [rs1/rs103:27017] starting PITR routine
E                   2024-11-14T13:16:15Z I [rs1/rs101:27017] node: rs1/rs101:27017
E                   2024-11-14T13:16:15Z I [rs1/rs102:27017] node: rs1/rs102:27017
E                   2024-11-14T13:16:15Z I [rs1/rs103:27017] node: rs1/rs103:27017
E                   2024-11-14T13:16:15Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:16:15Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:16:15Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:16:15Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T13:16:15Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T13:16:15Z I [rs1/rs102:27017] listening for the commands
E                   2024-11-14T13:16:15Z I [rs1/rs101:27017] listening for the commands
E                   2024-11-14T13:16:15Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E                   2024-11-14T13:16:15Z I [rs1/rs103:27017] listening for the commands
E                   2024-11-14T13:16:20Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:16:20Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:16:20Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E                   2024-11-14T13:16:22Z I [rs1/rs101:27017] got command resync <ts: 1731590182>, opid: 6735f826df4df99c97b10448
E                   2024-11-14T13:16:22Z I [rs1/rs101:27017] got epoch {1731590180 6}
E                   2024-11-14T13:16:22Z I [rs1/rs102:27017] got command resync <ts: 1731590182>, opid: 6735f826df4df99c97b10448
E                   2024-11-14T13:16:22Z I [rs1/rs103:27017] got command resync <ts: 1731590182>, opid: 6735f826df4df99c97b10448
E                   2024-11-14T13:16:22Z I [rs1/rs102:27017] got epoch {1731590180 6}
E                   2024-11-14T13:16:22Z I [rs1/rs101:27017] [resync] started
E                   2024-11-14T13:16:22Z I [rs1/rs103:27017] got epoch {1731590180 6}
E                   2024-11-14T13:16:22Z D [rs1/rs102:27017] [resync] lock not acquired
E                   2024-11-14T13:16:22Z D [rs1/rs103:27017] [resync] lock not acquired
E                   2024-11-14T13:16:22Z D [rs1/rs101:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E                   2024-11-14T13:16:22Z D [rs1/rs101:27017] [resync] got backups list: 0
E                   2024-11-14T13:16:22Z D [rs1/rs101:27017] [resync] got physical restores list: 0
E                   2024-11-14T13:16:22Z D [rs1/rs101:27017] [resync] epoch set to {1731590182 19}
E                   2024-11-14T13:16:22Z I [rs1/rs101:27017] [resync] succeed
E                   2024-11-14T13:16:28Z I [rs1/rs101:27017] got command resync <ts: 1731590187>, opid: 6735f82b903d530de22d14f8
E                   2024-11-14T13:16:28Z I [rs1/rs102:27017] got command resync <ts: 1731590187>, opid: 6735f82b903d530de22d14f8
E                   2024-11-14T13:16:28Z I [rs1/rs103:27017] got command resync <ts: 1731590187>, opid: 6735f82b903d530de22d14f8
E                   2024-11-14T13:16:28Z I [rs1/rs102:27017] got epoch {1731590182 19}
E                   2024-11-14T13:16:28Z I [rs1/rs101:27017] got epoch {1731590182 19}
E                   2024-11-14T13:16:28Z I [rs1/rs103:27017] got epoch {1731590182 19}
E                   2024-11-14T13:16:28Z D [rs1/rs103:27017] [resync] lock not acquired
E                   2024-11-14T13:16:28Z D [rs1/rs101:27017] [resync] lock not acquired
E                   2024-11-14T13:16:28Z I [rs1/rs102:27017] [resync] started
E                   2024-11-14T13:16:28Z I [rs1/rs103:27017] got command backup [name: 2024-11-14T13:16:28Z, compression: none (level: default)] <ts: 1731590188>, opid: 6735f82c0ef963cdcebe5f93
E                   2024-11-14T13:16:28Z I [rs1/rs101:27017] got command backup [name: 2024-11-14T13:16:28Z, compression: none (level: default)] <ts: 1731590188>, opid: 6735f82c0ef963cdcebe5f93
E                   2024-11-14T13:16:28Z I [rs1/rs103:27017] got epoch {1731590182 19}
E                   2024-11-14T13:16:28Z I [rs1/rs101:27017] got epoch {1731590182 19}
E                   2024-11-14T13:16:28Z D [rs1/rs102:27017] [resync] got backups list: 0
E                   2024-11-14T13:16:28Z D [rs1/rs102:27017] [resync] got physical restores list: 0
E                   2024-11-14T13:16:28Z E [rs1/rs101:27017] [backup/2024-11-14T13:16:28Z] unable to proceed with the backup, active lock is present
E                   2024-11-14T13:16:28Z D [rs1/rs102:27017] [resync] epoch set to {1731590188 21}
E                   2024-11-14T13:16:28Z I [rs1/rs102:27017] [resync] succeed
E                   2024-11-14T13:16:28Z I [rs1/rs102:27017] got command backup [name: 2024-11-14T13:16:28Z, compression: none (level: default)] <ts: 1731590188>, opid: 6735f82c0ef963cdcebe5f93
E                   2024-11-14T13:16:28Z I [rs1/rs102:27017] got epoch {1731590188 21}
E                   2024-11-14T13:16:43Z D [rs1/rs103:27017] [backup/2024-11-14T13:16:28Z] nomination timeout
E                   2024-11-14T13:16:43Z D [rs1/rs103:27017] [backup/2024-11-14T13:16:28Z] skip after nomination, probably started by another node
E                   2024-11-14T13:16:43Z D [rs1/rs102:27017] [backup/2024-11-14T13:16:28Z] nomination timeout
E                   2024-11-14T13:16:43Z D [rs1/rs102:27017] [backup/2024-11-14T13:16:28Z] skip after nomination, probably started by another node

cluster.py:393: AssertionError