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

    @pytest.mark.timeout(600,func_only=True)
    def test_logical_PBM_T255(start_cluster,cluster):
        def insert_docs():
            client=pymongo.MongoClient(cluster.connection)
            for i in range(200):
                client['test']['test'].insert_one({"doc":i})
                time.sleep(1)
    
        cluster.check_pbm_status()
        cluster.make_backup("logical")
        cluster.exec_pbm_cli("config --file=/etc/pbm-1043.conf")
        time.sleep(60)
        Cluster.log("Check if PITR is running")
        if not cluster.check_pitr():
            logs=cluster.exec_pbm_cli("logs -sD -t0")
>           assert False, logs.stdout
E           AssertionError: 2024-07-18T07:30:29Z I [rs2/rs201:27017] pbm-agent:
E             Version:   2.5.0
E             Platform:  linux/amd64
E             GitCommit: ae58fb510bc6cdb2648f154e729a205e78aae9cd
E             GitBranch: dev
E             BuildTime: 2024-07-18_07:29_UTC
E             GoVersion: go1.22.5
E             2024-07-18T07:30:29Z I [rs1/rs101:27017] starting PITR routine
E             2024-07-18T07:30:29Z I [rs1/rs102:27017] pbm-agent:
E             Version:   2.5.0
E             Platform:  linux/amd64
E             GitCommit: ae58fb510bc6cdb2648f154e729a205e78aae9cd
E             GitBranch: dev
E             BuildTime: 2024-07-18_07:29_UTC
E             GoVersion: go1.22.5
E             2024-07-18T07:30:29Z I [rs1/rs101:27017] pbm-agent:
E             Version:   2.5.0
E             Platform:  linux/amd64
E             GitCommit: ae58fb510bc6cdb2648f154e729a205e78aae9cd
E             GitBranch: dev
E             BuildTime: 2024-07-18_07:29_UTC
E             GoVersion: go1.22.5
E             2024-07-18T07:30:29Z I [rs2/rs201:27017] starting PITR routine
E             2024-07-18T07:30:29Z I [rs1/rs102:27017] starting PITR routine
E             2024-07-18T07:30:29Z I [rs1/rs103:27017] pbm-agent:
E             Version:   2.5.0
E             Platform:  linux/amd64
E             GitCommit: ae58fb510bc6cdb2648f154e729a205e78aae9cd
E             GitBranch: dev
E             BuildTime: 2024-07-18_07:29_UTC
E             GoVersion: go1.22.5
E             2024-07-18T07:30:29Z I [rs1/rs103:27017] starting PITR routine
E             2024-07-18T07:30:29Z I [rs1/rs101:27017] node: rs1/rs101:27017
E             2024-07-18T07:30:29Z I [rs2/rs201:27017] node: rs2/rs201:27017
E             2024-07-18T07:30:29Z I [rs1/rs102:27017] node: rs1/rs102:27017
E             2024-07-18T07:30:29Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-18T07:30:29Z I [rs1/rs103:27017] node: rs1/rs103:27017
E             2024-07-18T07:30:29Z I [rs2/rs201:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-18T07:30:29Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-18T07:30:29Z I [rs1/rs101:27017] listening for the commands
E             2024-07-18T07:30:29Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-18T07:30:29Z I [rs2/rs201:27017] listening for the commands
E             2024-07-18T07:30:29Z I [rs1/rs102:27017] listening for the commands
E             2024-07-18T07:30:29Z I [rs1/rs103:27017] listening for the commands
E             2024-07-18T07:30:30Z I [rs2/rs202:27017] pbm-agent:
E             Version:   2.5.0
E             Platform:  linux/amd64
E             GitCommit: ae58fb510bc6cdb2648f154e729a205e78aae9cd
E             GitBranch: dev
E             BuildTime: 2024-07-18_07:29_UTC
E             GoVersion: go1.22.5
E             2024-07-18T07:30:30Z I [rs2/rs202:27017] starting PITR routine
E             2024-07-18T07:30:30Z I [rs2/rs202:27017] node: rs2/rs202:27017
E             2024-07-18T07:30:30Z I [rs2/rs202:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-18T07:30:30Z I [rs2/rs202:27017] listening for the commands
E             2024-07-18T07:30:30Z I [rs2/rs203:27017] pbm-agent:
E             Version:   2.5.0
E             Platform:  linux/amd64
E             GitCommit: ae58fb510bc6cdb2648f154e729a205e78aae9cd
E             GitBranch: dev
E             BuildTime: 2024-07-18_07:29_UTC
E             GoVersion: go1.22.5
E             2024-07-18T07:30:30Z I [rs2/rs203:27017] starting PITR routine
E             2024-07-18T07:30:30Z I [rs2/rs203:27017] node: rs2/rs203:27017
E             2024-07-18T07:30:30Z I [rs2/rs203:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-18T07:30:30Z I [rs2/rs203:27017] listening for the commands
E             2024-07-18T07:30:30Z I [rscfg/rscfg02:27017] pbm-agent:
E             Version:   2.5.0
E             Platform:  linux/amd64
E             GitCommit: ae58fb510bc6cdb2648f154e729a205e78aae9cd
E             GitBranch: dev
E             BuildTime: 2024-07-18_07:29_UTC
E             GoVersion: go1.22.5
E             2024-07-18T07:30:30Z I [rscfg/rscfg02:27017] starting PITR routine
E             2024-07-18T07:30:30Z I [rscfg/rscfg02:27017] node: rscfg/rscfg02:27017
E             2024-07-18T07:30:30Z I [rscfg/rscfg02:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-18T07:30:30Z I [rscfg/rscfg02:27017] listening for the commands
E             2024-07-18T07:30:30Z I [rscfg/rscfg01:27017] pbm-agent:
E             Version:   2.5.0
E             Platform:  linux/amd64
E             GitCommit: ae58fb510bc6cdb2648f154e729a205e78aae9cd
E             GitBranch: dev
E             BuildTime: 2024-07-18_07:29_UTC
E             GoVersion: go1.22.5
E             2024-07-18T07:30:30Z I [rscfg/rscfg01:27017] starting PITR routine
E             2024-07-18T07:30:30Z I [rscfg/rscfg01:27017] node: rscfg/rscfg01:27017
E             2024-07-18T07:30:30Z I [rscfg/rscfg01:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-18T07:30:30Z I [rscfg/rscfg01:27017] listening for the commands
E             2024-07-18T07:30:32Z I [rscfg/rscfg03:27017] pbm-agent:
E             Version:   2.5.0
E             Platform:  linux/amd64
E             GitCommit: ae58fb510bc6cdb2648f154e729a205e78aae9cd
E             GitBranch: dev
E             BuildTime: 2024-07-18_07:29_UTC
E             GoVersion: go1.22.5
E             2024-07-18T07:30:32Z I [rscfg/rscfg03:27017] starting PITR routine
E             2024-07-18T07:30:32Z I [rscfg/rscfg03:27017] node: rscfg/rscfg03:27017
E             2024-07-18T07:30:32Z I [rscfg/rscfg03:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-18T07:30:32Z I [rscfg/rscfg03:27017] listening for the commands
E             2024-07-18T07:30:34Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-18T07:30:34Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-18T07:30:34Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-18T07:30:34Z W [rs2/rs201:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-18T07:30:34Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-18T07:30:34Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-18T07:30:34Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-18T07:30:34Z E [rs2/rs201:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-18T07:30:35Z W [rs2/rs202:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-18T07:30:35Z E [rs2/rs202:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-18T07:30:35Z W [rs2/rs203:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-18T07:30:35Z E [rs2/rs203:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-18T07:30:35Z W [rscfg/rscfg02:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-18T07:30:35Z E [rscfg/rscfg02:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-18T07:30:35Z W [rscfg/rscfg01:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-18T07:30:35Z E [rscfg/rscfg01:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-18T07:30:37Z W [rscfg/rscfg03:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-18T07:30:37Z E [rscfg/rscfg03:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-18T07:30:38Z I [rs2/rs202:27017] got command resync <ts: 1721287838>
E             2024-07-18T07:30:38Z I [rs2/rs202:27017] got epoch {1721287838 1}
E             2024-07-18T07:30:38Z I [rs2/rs202:27017] [resync] not a member of the leader rs
E             2024-07-18T07:30:38Z I [rs2/rs203:27017] got command resync <ts: 1721287838>
E             2024-07-18T07:30:38Z I [rs2/rs203:27017] got epoch {1721287838 1}
E             2024-07-18T07:30:38Z I [rs2/rs203:27017] [resync] not a member of the leader rs
E             2024-07-18T07:30:38Z I [rscfg/rscfg02:27017] got command resync <ts: 1721287838>
E             2024-07-18T07:30:38Z I [rscfg/rscfg02:27017] got epoch {1721287838 1}
E             2024-07-18T07:30:38Z I [rscfg/rscfg02:27017] [resync] started
E             2024-07-18T07:30:38Z I [rscfg/rscfg01:27017] got command resync <ts: 1721287838>
E             2024-07-18T07:30:38Z I [rscfg/rscfg01:27017] got epoch {1721287838 1}
E             2024-07-18T07:30:38Z D [rscfg/rscfg01:27017] [resync] lock not acquired
E             2024-07-18T07:30:38Z D [rscfg/rscfg02:27017] [resync] got backups list: 0
E             2024-07-18T07:30:38Z D [rscfg/rscfg02:27017] [resync] got physical restores list: 0
E             2024-07-18T07:30:38Z D [rscfg/rscfg02:27017] [resync] epoch set to {1721287838 21}
E             2024-07-18T07:30:38Z I [rscfg/rscfg02:27017] [resync] succeed
E             2024-07-18T07:30:39Z I [rs1/rs101:27017] got command resync <ts: 1721287838>
E             2024-07-18T07:30:39Z I [rs1/rs101:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:39Z I [rs1/rs102:27017] got command resync <ts: 1721287838>
E             2024-07-18T07:30:39Z I [rs1/rs103:27017] got command resync <ts: 1721287838>
E             2024-07-18T07:30:39Z I [rs1/rs101:27017] [resync] not a member of the leader rs
E             2024-07-18T07:30:39Z I [rs2/rs201:27017] got command resync <ts: 1721287838>
E             2024-07-18T07:30:39Z I [rs1/rs102:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:39Z I [rs1/rs103:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:39Z I [rs2/rs201:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:39Z I [rs1/rs102:27017] [resync] not a member of the leader rs
E             2024-07-18T07:30:39Z I [rs1/rs103:27017] [resync] not a member of the leader rs
E             2024-07-18T07:30:39Z I [rs2/rs201:27017] [resync] not a member of the leader rs
E             2024-07-18T07:30:39Z I [rscfg/rscfg03:27017] got command resync <ts: 1721287838>
E             2024-07-18T07:30:39Z I [rscfg/rscfg03:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:39Z D [rscfg/rscfg03:27017] [resync] get lock: duplicate operation: 6698c49e5eeeaef29d77e15c [Resync storage]
E             2024-07-18T07:30:39Z D [rscfg/rscfg03:27017] [resync] lock not acquired
E             2024-07-18T07:30:44Z I [rscfg/rscfg03:27017] got command backup [name: 2024-07-18T07:30:44Z, compression: s2 (level: default)] <ts: 1721287844>
E             2024-07-18T07:30:44Z I [rscfg/rscfg03:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:44Z I [rs2/rs202:27017] got command backup [name: 2024-07-18T07:30:44Z, compression: s2 (level: default)] <ts: 1721287844>
E             2024-07-18T07:30:44Z I [rs2/rs202:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:44Z I [rs2/rs203:27017] got command backup [name: 2024-07-18T07:30:44Z, compression: s2 (level: default)] <ts: 1721287844>
E             2024-07-18T07:30:44Z I [rs2/rs203:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:44Z I [rscfg/rscfg02:27017] got command backup [name: 2024-07-18T07:30:44Z, compression: s2 (level: default)] <ts: 1721287844>
E             2024-07-18T07:30:44Z I [rscfg/rscfg02:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:44Z I [rscfg/rscfg01:27017] got command backup [name: 2024-07-18T07:30:44Z, compression: s2 (level: default)] <ts: 1721287844>
E             2024-07-18T07:30:44Z I [rscfg/rscfg01:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:44Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] init backup meta
E             2024-07-18T07:30:44Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] nomination list for rscfg: [[rscfg02:27017 rscfg03:27017] [rscfg01:27017]]
E             2024-07-18T07:30:44Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] nomination list for rs1: [[rs102:27017 rs103:27017] [rs101:27017]]
E             2024-07-18T07:30:44Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] nomination list for rs2: [[rs202:27017 rs203:27017] [rs201:27017]]
E             2024-07-18T07:30:44Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] nomination rs1, set candidates [rs102:27017 rs103:27017]
E             2024-07-18T07:30:44Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] nomination rscfg, set candidates [rscfg02:27017 rscfg03:27017]
E             2024-07-18T07:30:44Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] nomination rs2, set candidates [rs202:27017 rs203:27017]
E             2024-07-18T07:30:45Z I [rs1/rs101:27017] got command backup [name: 2024-07-18T07:30:44Z, compression: s2 (level: default)] <ts: 1721287844>
E             2024-07-18T07:30:45Z I [rs1/rs102:27017] got command backup [name: 2024-07-18T07:30:44Z, compression: s2 (level: default)] <ts: 1721287844>
E             2024-07-18T07:30:45Z I [rs1/rs103:27017] got command backup [name: 2024-07-18T07:30:44Z, compression: s2 (level: default)] <ts: 1721287844>
E             2024-07-18T07:30:45Z I [rs1/rs101:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:45Z I [rs2/rs201:27017] got command backup [name: 2024-07-18T07:30:44Z, compression: s2 (level: default)] <ts: 1721287844>
E             2024-07-18T07:30:45Z I [rs1/rs102:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:45Z I [rs1/rs103:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:45Z I [rs2/rs201:27017] got epoch {1721287838 21}
E             2024-07-18T07:30:45Z I [rs2/rs202:27017] [backup/2024-07-18T07:30:44Z] backup started
E             2024-07-18T07:30:45Z D [rs2/rs203:27017] [backup/2024-07-18T07:30:44Z] skip after nomination, probably started by another node
E             2024-07-18T07:30:45Z I [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] backup started
E             2024-07-18T07:30:45Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] skip after nomination, probably started by another node
E             2024-07-18T07:30:45Z D [rscfg/rscfg03:27017] [backup/2024-07-18T07:30:44Z] skip after nomination, probably started by another node
E             2024-07-18T07:30:45Z D [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] waiting for balancer off
E             2024-07-18T07:30:45Z D [rs2/rs201:27017] [backup/2024-07-18T07:30:44Z] skip after nomination, probably started by another node
E             2024-07-18T07:30:45Z D [rs1/rs103:27017] [backup/2024-07-18T07:30:44Z] skip: lock not acquired
E             2024-07-18T07:30:45Z I [rs1/rs102:27017] [backup/2024-07-18T07:30:44Z] backup started
E             2024-07-18T07:30:46Z D [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] balancer status: off
E             2024-07-18T07:30:46Z D [rs1/rs101:27017] [backup/2024-07-18T07:30:44Z] skip after nomination, probably started by another node
E             2024-07-18T07:30:48Z D [rs2/rs202:27017] [backup/2024-07-18T07:30:44Z] wait for tmp users {1721287848 5}
E             2024-07-18T07:30:48Z D [rs1/rs102:27017] [backup/2024-07-18T07:30:44Z] wait for tmp users {1721287848 5}
E             2024-07-18T07:30:48Z I [rs1/rs102:27017] [backup/2024-07-18T07:30:44Z] mongodump finished, waiting for the oplog
E             2024-07-18T07:30:49Z D [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] wait for tmp users {1721287849 5}
E             2024-07-18T07:30:49Z I [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] mongodump finished, waiting for the oplog
E             2024-07-18T07:30:49Z I [rs2/rs202:27017] [backup/2024-07-18T07:30:44Z] mongodump finished, waiting for the oplog
E             2024-07-18T07:30:49Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] bcp nomination: rs1 won by rs102:27017
E             2024-07-18T07:30:49Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] bcp nomination: rs2 won by rs202:27017
E             2024-07-18T07:30:49Z D [rscfg/rscfg01:27017] [backup/2024-07-18T07:30:44Z] bcp nomination: rscfg won by rscfg02:27017
E             2024-07-18T07:30:52Z I [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] created chunk 2024-07-18T07:30:45 - 2024-07-18T07:30:50
E             2024-07-18T07:30:58Z I [rs2/rs202:27017] [backup/2024-07-18T07:30:44Z] created chunk 2024-07-18T07:30:44 - 2024-07-18T07:30:48
E             2024-07-18T07:30:58Z I [rs2/rs202:27017] [backup/2024-07-18T07:30:44Z] dropping tmp collections
E             2024-07-18T07:30:59Z I [rs1/rs102:27017] [backup/2024-07-18T07:30:44Z] created chunk 2024-07-18T07:30:44 - 2024-07-18T07:30:48
E             2024-07-18T07:30:59Z I [rs1/rs102:27017] [backup/2024-07-18T07:30:44Z] dropping tmp collections
E             2024-07-18T07:31:00Z I [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] dropping tmp collections
E             2024-07-18T07:31:01Z D [rs1/rs102:27017] [backup/2024-07-18T07:30:44Z] set balancer on
E             2024-07-18T07:31:01Z I [rs1/rs102:27017] [backup/2024-07-18T07:30:44Z] backup finished
E             2024-07-18T07:31:01Z D [rs1/rs102:27017] [backup/2024-07-18T07:30:44Z] releasing lock
E             2024-07-18T07:31:01Z D [rs2/rs202:27017] [backup/2024-07-18T07:30:44Z] set balancer on
E             2024-07-18T07:31:01Z I [rs2/rs202:27017] [backup/2024-07-18T07:30:44Z] backup finished
E             2024-07-18T07:31:01Z D [rs2/rs202:27017] [backup/2024-07-18T07:30:44Z] releasing lock
E             2024-07-18T07:31:02Z D [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] set balancer on
E             2024-07-18T07:31:02Z I [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] backup finished
E             2024-07-18T07:31:02Z D [rscfg/rscfg02:27017] [backup/2024-07-18T07:30:44Z] releasing lock
E             
E           assert False

test_PBM-1043.py:64: AssertionError