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

    @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.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-16T14:48:26Z 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-16_14:47_UTC
E             GoVersion: go1.22.5
E             2024-07-16T14:48:26Z I [rs1/rs101:27017] starting PITR routine
E             2024-07-16T14:48:26Z 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-16_14:47_UTC
E             GoVersion: go1.22.5
E             2024-07-16T14:48:26Z I [rs2/rs201:27017] starting PITR routine
E             2024-07-16T14:48:26Z 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-16_14:47_UTC
E             GoVersion: go1.22.5
E             2024-07-16T14:48:26Z I [rs1/rs102:27017] starting PITR routine
E             2024-07-16T14:48:26Z 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-16_14:47_UTC
E             GoVersion: go1.22.5
E             2024-07-16T14:48:26Z I [rs1/rs103:27017] starting PITR routine
E             2024-07-16T14:48:26Z I [rs1/rs103:27017] node: rs1/rs103:27017
E             2024-07-16T14:48:26Z I [rs1/rs102:27017] node: rs1/rs102:27017
E             2024-07-16T14:48:26Z I [rs2/rs201:27017] node: rs2/rs201:27017
E             2024-07-16T14:48:26Z I [rs1/rs101:27017] node: rs1/rs101:27017
E             2024-07-16T14:48:26Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-16T14:48:26Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-16T14:48:26Z I [rs2/rs201:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-16T14:48:26Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-16T14:48:26Z I [rs1/rs102:27017] listening for the commands
E             2024-07-16T14:48:26Z I [rs1/rs103:27017] listening for the commands
E             2024-07-16T14:48:26Z I [rs1/rs101:27017] listening for the commands
E             2024-07-16T14:48:26Z I [rs2/rs201:27017] listening for the commands
E             2024-07-16T14:48:28Z 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-16_14:47_UTC
E             GoVersion: go1.22.5
E             2024-07-16T14:48:28Z I [rs2/rs202:27017] starting PITR routine
E             2024-07-16T14:48:28Z I [rs2/rs202:27017] node: rs2/rs202:27017
E             2024-07-16T14:48:28Z I [rs2/rs202:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-16T14:48:28Z I [rs2/rs202:27017] listening for the commands
E             2024-07-16T14:48:28Z 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-16_14:47_UTC
E             GoVersion: go1.22.5
E             2024-07-16T14:48:28Z I [rs2/rs203:27017] starting PITR routine
E             2024-07-16T14:48:28Z I [rs2/rs203:27017] node: rs2/rs203:27017
E             2024-07-16T14:48:28Z I [rs2/rs203:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-16T14:48:28Z I [rs2/rs203:27017] listening for the commands
E             2024-07-16T14:48:28Z 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-16_14:47_UTC
E             GoVersion: go1.22.5
E             2024-07-16T14:48:28Z I [rscfg/rscfg01:27017] starting PITR routine
E             2024-07-16T14:48:28Z I [rscfg/rscfg01:27017] node: rscfg/rscfg01:27017
E             2024-07-16T14:48:28Z I [rscfg/rscfg01:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-16T14:48:28Z I [rscfg/rscfg01:27017] listening for the commands
E             2024-07-16T14:48:28Z 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-16_14:47_UTC
E             GoVersion: go1.22.5
E             2024-07-16T14:48:28Z I [rscfg/rscfg02:27017] starting PITR routine
E             2024-07-16T14:48:28Z I [rscfg/rscfg02:27017] node: rscfg/rscfg02:27017
E             2024-07-16T14:48:28Z I [rscfg/rscfg02:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-16T14:48:28Z I [rscfg/rscfg02:27017] listening for the commands
E             2024-07-16T14:48:30Z 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-16_14:47_UTC
E             GoVersion: go1.22.5
E             2024-07-16T14:48:30Z I [rscfg/rscfg03:27017] starting PITR routine
E             2024-07-16T14:48:30Z I [rscfg/rscfg03:27017] node: rscfg/rscfg03:27017
E             2024-07-16T14:48:30Z I [rscfg/rscfg03:27017] conn level ReadConcern: majority; WriteConcern: majority
E             2024-07-16T14:48:30Z I [rscfg/rscfg03:27017] listening for the commands
E             2024-07-16T14:48:31Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-16T14:48:31Z W [rs2/rs201:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-16T14:48:31Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-16T14:48:31Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-16T14:48:31Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-16T14:48:31Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-16T14:48:31Z E [rs2/rs201:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-16T14:48:31Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-16T14:48:33Z W [rs2/rs202:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-16T14:48:33Z E [rs2/rs202:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-16T14:48:33Z W [rs2/rs203:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-16T14:48:33Z E [rs2/rs203:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-16T14:48:33Z W [rscfg/rscfg01:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-16T14:48:33Z E [rscfg/rscfg01:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-16T14:48:33Z W [rscfg/rscfg02:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-16T14:48:33Z E [rscfg/rscfg02:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-16T14:48:35Z W [rscfg/rscfg03:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E             2024-07-16T14:48:35Z E [rscfg/rscfg03:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E             2024-07-16T14:48:36Z I [rs2/rs203:27017] got command resync <ts: 1721141316>
E             2024-07-16T14:48:36Z I [rs2/rs203:27017] got epoch {1721141316 1}
E             2024-07-16T14:48:36Z I [rs2/rs203:27017] [resync] not a member of the leader rs
E             2024-07-16T14:48:36Z I [rscfg/rscfg01:27017] got command resync <ts: 1721141316>
E             2024-07-16T14:48:36Z I [rscfg/rscfg01:27017] got epoch {1721141316 1}
E             2024-07-16T14:48:36Z I [rscfg/rscfg01:27017] [resync] started
E             2024-07-16T14:48:36Z D [rscfg/rscfg01:27017] [resync] got backups list: 0
E             2024-07-16T14:48:36Z D [rscfg/rscfg01:27017] [resync] got physical restores list: 0
E             2024-07-16T14:48:36Z D [rscfg/rscfg01:27017] [resync] epoch set to {1721141316 14}
E             2024-07-16T14:48:36Z I [rscfg/rscfg01:27017] [resync] succeed
E             2024-07-16T14:48:36Z I [rscfg/rscfg02:27017] got command resync <ts: 1721141316>
E             2024-07-16T14:48:36Z I [rscfg/rscfg02:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:36Z D [rscfg/rscfg02:27017] [resync] get lock: duplicate operation: 6696884483a5331dc7d5be11 [Resync storage]
E             2024-07-16T14:48:36Z D [rscfg/rscfg02:27017] [resync] lock not acquired
E             2024-07-16T14:48:36Z I [rs1/rs103:27017] got command resync <ts: 1721141316>
E             2024-07-16T14:48:36Z I [rs1/rs102:27017] got command resync <ts: 1721141316>
E             2024-07-16T14:48:36Z I [rs2/rs201:27017] got command resync <ts: 1721141316>
E             2024-07-16T14:48:36Z I [rs1/rs101:27017] got command resync <ts: 1721141316>
E             2024-07-16T14:48:36Z I [rs1/rs103:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:36Z I [rs1/rs102:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:36Z I [rs2/rs201:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:36Z I [rs1/rs101:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:36Z I [rs1/rs103:27017] [resync] not a member of the leader rs
E             2024-07-16T14:48:36Z I [rs1/rs102:27017] [resync] not a member of the leader rs
E             2024-07-16T14:48:36Z I [rs2/rs201:27017] [resync] not a member of the leader rs
E             2024-07-16T14:48:36Z I [rs1/rs101:27017] [resync] not a member of the leader rs
E             2024-07-16T14:48:37Z I [rscfg/rscfg03:27017] got command resync <ts: 1721141316>
E             2024-07-16T14:48:37Z I [rscfg/rscfg03:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:37Z D [rscfg/rscfg03:27017] [resync] get lock: duplicate operation: 6696884483a5331dc7d5be11 [Resync storage]
E             2024-07-16T14:48:37Z D [rscfg/rscfg03:27017] [resync] lock not acquired
E             2024-07-16T14:48:37Z I [rs2/rs202:27017] got command resync <ts: 1721141316>
E             2024-07-16T14:48:37Z I [rs2/rs202:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:37Z I [rs2/rs202:27017] [resync] not a member of the leader rs
E             2024-07-16T14:48:44Z I [rs2/rs202:27017] got command backup [name: 2024-07-16T14:48:44Z, compression: s2 (level: default)] <ts: 1721141324>
E             2024-07-16T14:48:44Z I [rs2/rs202:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:44Z I [rs2/rs203:27017] got command backup [name: 2024-07-16T14:48:44Z, compression: s2 (level: default)] <ts: 1721141324>
E             2024-07-16T14:48:44Z I [rs2/rs203:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:44Z I [rscfg/rscfg01:27017] got command backup [name: 2024-07-16T14:48:44Z, compression: s2 (level: default)] <ts: 1721141324>
E             2024-07-16T14:48:44Z I [rscfg/rscfg01:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:44Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] init backup meta
E             2024-07-16T14:48:44Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] nomination list for rs1: [[rs103:27017 rs102:27017] [rs101:27017]]
E             2024-07-16T14:48:44Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] nomination list for rs2: [[rs202:27017 rs203:27017] [rs201:27017]]
E             2024-07-16T14:48:44Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] nomination list for rscfg: [[rscfg02:27017 rscfg03:27017] [rscfg01:27017]]
E             2024-07-16T14:48:44Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] nomination rs2, set candidates [rs202:27017 rs203:27017]
E             2024-07-16T14:48:44Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] nomination rs1, set candidates [rs103:27017 rs102:27017]
E             2024-07-16T14:48:44Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] nomination rscfg, set candidates [rscfg02:27017 rscfg03:27017]
E             2024-07-16T14:48:44Z I [rscfg/rscfg02:27017] got command backup [name: 2024-07-16T14:48:44Z, compression: s2 (level: default)] <ts: 1721141324>
E             2024-07-16T14:48:44Z I [rscfg/rscfg02:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:44Z I [rs1/rs102:27017] got command backup [name: 2024-07-16T14:48:44Z, compression: s2 (level: default)] <ts: 1721141324>
E             2024-07-16T14:48:44Z I [rs1/rs103:27017] got command backup [name: 2024-07-16T14:48:44Z, compression: s2 (level: default)] <ts: 1721141324>
E             2024-07-16T14:48:44Z I [rs2/rs201:27017] got command backup [name: 2024-07-16T14:48:44Z, compression: s2 (level: default)] <ts: 1721141324>
E             2024-07-16T14:48:44Z I [rs1/rs101:27017] got command backup [name: 2024-07-16T14:48:44Z, compression: s2 (level: default)] <ts: 1721141324>
E             2024-07-16T14:48:44Z I [rs1/rs103:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:44Z I [rs1/rs102:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:44Z I [rs2/rs201:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:44Z I [rs1/rs101:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:45Z I [rs2/rs202:27017] [backup/2024-07-16T14:48:44Z] backup started
E             2024-07-16T14:48:45Z D [rs2/rs203:27017] [backup/2024-07-16T14:48:44Z] skip after nomination, probably started by another node
E             2024-07-16T14:48:45Z I [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] backup started
E             2024-07-16T14:48:45Z I [rscfg/rscfg03:27017] got command backup [name: 2024-07-16T14:48:44Z, compression: s2 (level: default)] <ts: 1721141324>
E             2024-07-16T14:48:45Z D [rs2/rs201:27017] [backup/2024-07-16T14:48:44Z] skip after nomination, probably started by another node
E             2024-07-16T14:48:45Z I [rscfg/rscfg03:27017] got epoch {1721141316 14}
E             2024-07-16T14:48:45Z D [rs1/rs102:27017] [backup/2024-07-16T14:48:44Z] skip: lock not acquired
E             2024-07-16T14:48:45Z D [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] waiting for balancer off
E             2024-07-16T14:48:45Z I [rs1/rs103:27017] [backup/2024-07-16T14:48:44Z] backup started
E             2024-07-16T14:48:45Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] skip after nomination, probably started by another node
E             2024-07-16T14:48:45Z D [rs1/rs101:27017] [backup/2024-07-16T14:48:44Z] skip after nomination, probably started by another node
E             2024-07-16T14:48:45Z D [rscfg/rscfg03:27017] [backup/2024-07-16T14:48:44Z] skip after nomination, probably started by another node
E             2024-07-16T14:48:45Z D [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] balancer status: off
E             2024-07-16T14:48:48Z D [rs2/rs202:27017] [backup/2024-07-16T14:48:44Z] wait for tmp users {1721141328 5}
E             2024-07-16T14:48:48Z I [rs2/rs202:27017] [backup/2024-07-16T14:48:44Z] mongodump finished, waiting for the oplog
E             2024-07-16T14:48:48Z D [rs1/rs103:27017] [backup/2024-07-16T14:48:44Z] wait for tmp users {1721141328 5}
E             2024-07-16T14:48:48Z I [rs1/rs103:27017] [backup/2024-07-16T14:48:44Z] mongodump finished, waiting for the oplog
E             2024-07-16T14:48:49Z D [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] wait for tmp users {1721141329 3}
E             2024-07-16T14:48:49Z I [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] mongodump finished, waiting for the oplog
E             2024-07-16T14:48:49Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] bcp nomination: rs2 won by rs202:27017
E             2024-07-16T14:48:49Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] bcp nomination: rs1 won by rs103:27017
E             2024-07-16T14:48:49Z D [rscfg/rscfg01:27017] [backup/2024-07-16T14:48:44Z] bcp nomination: rscfg won by rscfg02:27017
E             2024-07-16T14:48:51Z I [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] created chunk 2024-07-16T14:48:45 - 2024-07-16T14:48:50
E             2024-07-16T14:49:02Z I [rs1/rs103:27017] [backup/2024-07-16T14:48:44Z] created chunk 2024-07-16T14:48:44 - 2024-07-16T14:48:48
E             2024-07-16T14:49:02Z I [rs1/rs103:27017] [backup/2024-07-16T14:48:44Z] dropping tmp collections
E             2024-07-16T14:49:02Z I [rs2/rs202:27017] [backup/2024-07-16T14:48:44Z] created chunk 2024-07-16T14:48:44 - 2024-07-16T14:48:48
E             2024-07-16T14:49:02Z I [rs2/rs202:27017] [backup/2024-07-16T14:48:44Z] dropping tmp collections
E             2024-07-16T14:49:03Z I [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] dropping tmp collections
E             2024-07-16T14:49:04Z D [rs2/rs202:27017] [backup/2024-07-16T14:48:44Z] set balancer on
E             2024-07-16T14:49:04Z I [rs2/rs202:27017] [backup/2024-07-16T14:48:44Z] backup finished
E             2024-07-16T14:49:04Z D [rs2/rs202:27017] [backup/2024-07-16T14:48:44Z] releasing lock
E             2024-07-16T14:49:05Z D [rs1/rs103:27017] [backup/2024-07-16T14:48:44Z] set balancer on
E             2024-07-16T14:49:05Z I [rs1/rs103:27017] [backup/2024-07-16T14:48:44Z] backup finished
E             2024-07-16T14:49:05Z D [rs1/rs103:27017] [backup/2024-07-16T14:48:44Z] releasing lock
E             2024-07-16T14:49:05Z D [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] set balancer on
E             2024-07-16T14:49:05Z I [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] backup finished
E             2024-07-16T14:49:05Z D [rscfg/rscfg02:27017] [backup/2024-07-16T14:48:44Z] releasing lock
E             
E           assert False

test_PBM-1043.py:63: AssertionError