Skip to content

[PBM-907] slice oplog during logical backup #703

[PBM-907] slice oplog during logical backup

[PBM-907] slice oplog during logical backup #703

GitHub Actions / JUnit Test Report failed Jan 25, 2024 in 0s

15 tests run, 7 passed, 0 skipped, 8 failed.

Annotations

Check failure on line 79 in psmdb-testing/pbm-functional/pytest/test_PBM-1223.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_PBM-1223.test_logical

AssertionError: Starting restore 2024-01-25T20:29:44.995433036Z from '2024-01-25T20:29:17Z'...Started logical restore.
Waiting to finish....Error: operation failed with: waiting for dumpDone: cluster failed: reply oplog: replay chunk 1706214558.1706214561: apply oplog for chunk: applying a transaction entry: apply txn: {
 "Timestamp": {
  "T": 1706214558,
  "I": 13
 },
 "Term": 2,
 "Hash": null,
 "Version": 2,
 "Operation": "c",
 "Namespace": "admin.$cmd",
 "Object": [
  {
   "Key": "commitTransaction",
   "Value": 1
  },
  {
   "Key": "commitTimestamp",
   "Value": {
    "T": 1706214558,
    "I": 10
   }
  }
 ],
 "Query": null,
 "UI": null,
 "LSID": "SAAAAAVpZAAQAAAABHUr8Oc47k8YgpGEqTiQPpkFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA",
 "TxnNumber": 1,
 "PrevOpTime": "HAAAABF0cwAKAAAAnsSyZRJ0AAIAAAAAAAAAAA=="
}: unknown transaction id SAAAAAVpZAAQAAAABHUr8Oc47k8YgpGEqTiQPpkFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA-1
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f11576b8a90>

    @pytest.mark.testcase(test_case_key="T249", test_step_key=1)
    @pytest.mark.timeout(300,func_only=True)
    def test_logical(start_cluster,cluster):
        cluster.check_pbm_status()
        client = pymongo.MongoClient(cluster.connection)
        db = client.test
        collection = db.test
        with client.start_session() as session:
            with session.start_transaction():
                Cluster.log("Transaction started\n")
                collection.insert_one({"e": 5}, session=session)
                collection.insert_one({"f": 6}, session=session)
                collection.insert_one({"g": 7}, session=session)
                collection.insert_one({"h": 8}, session=session)
                collection.insert_one({"i": 9}, session=session)
                background_backup=concurrent.futures.ThreadPoolExecutor().submit(cluster.make_backup, 'logical')
                time.sleep(1)
                collection.insert_one({"j": 10}, session=session)
                collection.insert_one({"k": 11}, session=session)
                collection.insert_one({"l": 12}, session=session)
                session.commit_transaction()
                Cluster.log("Transaction commited\n")
        backup=background_backup.result()
        assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == 8
>       cluster.make_restore(backup,check_pbm_status=True)

test_PBM-1223.py:79: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f11576b8a90>, name = '2024-01-25T20:29:17Z'
kwargs = {'check_pbm_status': True}
client = MongoClient(host=['mongos:27017'], document_class=dict, tz_aware=False, connect=True)
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'time... id SAAAAAVpZAAQAAAABHUr8Oc47k8YgpGEqTiQPpkFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA-1\n', _stderr=b'')
n = <testinfra.host.Host docker://rscfg01>, timeout = 1706214644.81969

    def make_restore(self, name, **kwargs):
        if self.layout == "sharded":
            client = pymongo.MongoClient(self.connection)
            result = client.admin.command("balancerStop")
            client.close()
            Cluster.log("Stopping balancer: " + str(result))
            self.stop_mongos()
        self.stop_arbiters()
        n = testinfra.get_host("docker://" + self.pbm_cli)
        timeout = time.time() + 60
    
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                assert False, "Cannot start restore, another operation running"
            time.sleep(1)
        Cluster.log("Restore started")
        result = n.run('timeout 240 pbm restore ' + name + ' --wait')
        if result.rc == 124:
            # try to catch possible failures if timeout exceeded
            for host in self.mongod_hosts:
                try:
                    container = docker.from_env().containers.get(host)
                    get_logs = container.exec_run(
                        'cat /var/lib/mongo/pbm.restore.log', stderr=False)
                    if get_logs.exit_code == 0:
                        Cluster.log(
                            "!!!!Possible failure on {}, file pbm.restore.log was found:".format(host))
                        Cluster.log(get_logs.output.decode('utf-8'))
                except docker.errors.APIError:
                    pass
            assert False, "Timeout for restore exceeded"
        elif result.rc == 0:
            Cluster.log(result.stdout)
        else:
>           assert False, result.stdout + result.stderr
E           AssertionError: Starting restore 2024-01-25T20:29:44.995433036Z from '2024-01-25T20:29:17Z'...Started logical restore.
E           Waiting to finish....Error: operation failed with: waiting for dumpDone: cluster failed: reply oplog: replay chunk 1706214558.1706214561: apply oplog for chunk: applying a transaction entry: apply txn: {
E            "Timestamp": {
E             "T": 1706214558,
E             "I": 13
E            },
E            "Term": 2,
E            "Hash": null,
E            "Version": 2,
E            "Operation": "c",
E            "Namespace": "admin.$cmd",
E            "Object": [
E             {
E              "Key": "commitTransaction",
E              "Value": 1
E             },
E             {
E              "Key": "commitTimestamp",
E              "Value": {
E               "T": 1706214558,
E               "I": 10
E              }
E             }
E            ],
E            "Query": null,
E            "UI": null,
E            "LSID": "SAAAAAVpZAAQAAAABHUr8Oc47k8YgpGEqTiQPpkFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA",
E            "TxnNumber": 1,
E            "PrevOpTime": "HAAAABF0cwAKAAAAnsSyZRJ0AAIAAAAAAAAAAA=="
E           }: unknown transaction id SAAAAAVpZAAQAAAABHUr8Oc47k8YgpGEqTiQPpkFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA-1

cluster.py:450: AssertionError

Check failure on line 68 in psmdb-testing/pbm-functional/pytest/test_PBM-979.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_PBM-979.test_logical

AssertionError
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f115772fb90>

    @pytest.mark.testcase(test_case_key="T233", test_step_key=1)
    @pytest.mark.timeout(300,func_only=True)
    def test_logical(start_cluster,cluster):
        time.sleep(5) # wait for delayed node
>       cluster.check_pbm_status()

test_PBM-979.py:68: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f115772fb90>

    def check_pbm_status(self):
        n = testinfra.get_host("docker://" + self.pbm_cli)
        result = n.check_output('pbm status --out=json')
        parsed_result = json.loads(result)
        Cluster.log("PBM status: \n" + str(parsed_result['cluster']))
        #Cluster.log(json.dumps(parsed_result['cluster'], indent=4))
        hosts = []
        for replicaset in parsed_result['cluster']:
            for host in replicaset['nodes']:
                if host['role'] != "A":
                    hosts.append(host)
>                   assert host['ok'] == True
E                   AssertionError

cluster.py:712: AssertionError

Check failure on line 93 in psmdb-testing/pbm-functional/pytest/test_azurite.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_azurite.test_logical_pitr

AssertionError: Unexpected exit code 1 for CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'pbm delete-backup -y 2024-01-25T20:38:56Z', _stdout=b'', _stderr=b'Error: backup cannot be deleted: cannot delete the last PITR base snapshot while PITR is enabled\n')
assert 1 == 0
 +  where 1 = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'pbm ...out=b'', _stderr=b'Error: backup cannot be deleted: cannot delete the last PITR base snapshot while PITR is enabled\n').rc
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f113e050310>

    @pytest.mark.timeout(500, func_only=True)
    def test_logical_pitr(start_cluster,cluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        backup_l1=cluster.make_backup("logical")
        cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=0.5")
        time.sleep(60)
        # make several following backups and then remove them to check the continuity of PITR timeframe
        pymongo.MongoClient(cluster.connection)["test"]["test2"].insert_many(documents)
        backup_l2=cluster.make_backup("logical")
        time.sleep(60)
        pymongo.MongoClient(cluster.connection)["test"]["test3"].insert_many(documents)
        backup_l3=cluster.make_backup("logical")
        pitr = datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%S")
        backup="--time=" + pitr
        Cluster.log("Time for PITR is: " + pitr)
        time.sleep(60)
        cluster.delete_backup(backup_l2)
>       cluster.delete_backup(backup_l3)

test_azurite.py:93: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f113e050310>, name = '2024-01-25T20:38:56Z'

    def delete_backup(self, name):
        n = testinfra.get_host("docker://" + self.pbm_cli)
>       result = n.check_output('pbm delete-backup -y ' + name)
E       AssertionError: Unexpected exit code 1 for CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'pbm delete-backup -y 2024-01-25T20:38:56Z', _stdout=b'', _stderr=b'Error: backup cannot be deleted: cannot delete the last PITR base snapshot while PITR is enabled\n')
E       assert 1 == 0
E        +  where 1 = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'pbm ...out=b'', _stderr=b'Error: backup cannot be deleted: cannot delete the last PITR base snapshot while PITR is enabled\n').rc

cluster.py:798: AssertionError

Check failure on line 77 in psmdb-testing/pbm-functional/pytest/test_fresh_sharded.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_fresh_sharded.test_logical

AssertionError: Error: backup '2024-01-25T20:41:52Z' didn't finish successfully
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f114f15f6d0>
newcluster = <cluster.Cluster object at 0x7f114f15df10>

    @pytest.mark.testcase(test_case_key="T208", test_step_key=1)
    @pytest.mark.timeout(600,func_only=True)
    def test_logical(start_cluster,cluster,newcluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        backup=cluster.make_backup("logical")
        cluster.destroy()
    
        newcluster.make_resync()
>       newcluster.make_restore(backup,check_pbm_status=True)

test_fresh_sharded.py:77: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f114f15df10>, name = '2024-01-25T20:41:52Z'
kwargs = {'check_pbm_status': True}
client = MongoClient(host=['newmongos:27017'], document_class=dict, tz_aware=False, connect=True)
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f113e0f6450>, exit_status=1, command=b'time...024-01-25T20:41:52Z --wait', _stdout=b'', _stderr=b"Error: backup '2024-01-25T20:41:52Z' didn't finish successfully\n")
n = <testinfra.host.Host docker://newrscfg01>, timeout = 1706215405.5464456

    def make_restore(self, name, **kwargs):
        if self.layout == "sharded":
            client = pymongo.MongoClient(self.connection)
            result = client.admin.command("balancerStop")
            client.close()
            Cluster.log("Stopping balancer: " + str(result))
            self.stop_mongos()
        self.stop_arbiters()
        n = testinfra.get_host("docker://" + self.pbm_cli)
        timeout = time.time() + 60
    
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                assert False, "Cannot start restore, another operation running"
            time.sleep(1)
        Cluster.log("Restore started")
        result = n.run('timeout 240 pbm restore ' + name + ' --wait')
        if result.rc == 124:
            # try to catch possible failures if timeout exceeded
            for host in self.mongod_hosts:
                try:
                    container = docker.from_env().containers.get(host)
                    get_logs = container.exec_run(
                        'cat /var/lib/mongo/pbm.restore.log', stderr=False)
                    if get_logs.exit_code == 0:
                        Cluster.log(
                            "!!!!Possible failure on {}, file pbm.restore.log was found:".format(host))
                        Cluster.log(get_logs.output.decode('utf-8'))
                except docker.errors.APIError:
                    pass
            assert False, "Timeout for restore exceeded"
        elif result.rc == 0:
            Cluster.log(result.stdout)
        else:
>           assert False, result.stdout + result.stderr
E           AssertionError: Error: backup '2024-01-25T20:41:52Z' didn't finish successfully

cluster.py:450: AssertionError

Check failure on line 76 in psmdb-testing/pbm-functional/pytest/test_remap_sharded.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_remap_sharded.test_logical

AssertionError: Error: backup '2024-01-25T20:46:26Z' didn't finish successfully
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f114f1550d0>
newcluster = <cluster.Cluster object at 0x7f114f156dd0>

    @pytest.mark.testcase(test_case_key="T211", test_step_key=1)
    @pytest.mark.timeout(600,func_only=True)
    def test_logical(start_cluster,cluster,newcluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        backup=cluster.make_backup("logical")
        backup = backup + ' --replset-remapping="newrs1=rs1,newrs2=rs2,newrscfg=rscfg"'
        cluster.destroy()
    
        newcluster.make_resync()
>       newcluster.make_restore(backup,check_pbm_status=True)

test_remap_sharded.py:76: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f114f156dd0>
name = '2024-01-25T20:46:26Z --replset-remapping="newrs1=rs1,newrs2=rs2,newrscfg=rscfg"'
kwargs = {'check_pbm_status': True}
client = MongoClient(host=['newmongos:27017'], document_class=dict, tz_aware=False, connect=True)
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f113e0f6450>, exit_status=1, command=b'time...rs2,newrscfg=rscfg" --wait', _stdout=b'', _stderr=b"Error: backup '2024-01-25T20:46:26Z' didn't finish successfully\n")
n = <testinfra.host.Host docker://newrscfg01>, timeout = 1706215679.6509452

    def make_restore(self, name, **kwargs):
        if self.layout == "sharded":
            client = pymongo.MongoClient(self.connection)
            result = client.admin.command("balancerStop")
            client.close()
            Cluster.log("Stopping balancer: " + str(result))
            self.stop_mongos()
        self.stop_arbiters()
        n = testinfra.get_host("docker://" + self.pbm_cli)
        timeout = time.time() + 60
    
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                assert False, "Cannot start restore, another operation running"
            time.sleep(1)
        Cluster.log("Restore started")
        result = n.run('timeout 240 pbm restore ' + name + ' --wait')
        if result.rc == 124:
            # try to catch possible failures if timeout exceeded
            for host in self.mongod_hosts:
                try:
                    container = docker.from_env().containers.get(host)
                    get_logs = container.exec_run(
                        'cat /var/lib/mongo/pbm.restore.log', stderr=False)
                    if get_logs.exit_code == 0:
                        Cluster.log(
                            "!!!!Possible failure on {}, file pbm.restore.log was found:".format(host))
                        Cluster.log(get_logs.output.decode('utf-8'))
                except docker.errors.APIError:
                    pass
            assert False, "Timeout for restore exceeded"
        elif result.rc == 0:
            Cluster.log(result.stdout)
        else:
>           assert False, result.stdout + result.stderr
E           AssertionError: Error: backup '2024-01-25T20:46:26Z' didn't finish successfully

cluster.py:450: AssertionError

Check failure on line 50 in psmdb-testing/pbm-functional/pytest/test_replicaset.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_replicaset.test_logical

AssertionError: Error: backup '2024-01-25T20:47:44Z' didn't finish successfully
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f114f1021d0>

    @pytest.mark.timeout(300,func_only=True)
    def test_logical(start_cluster,cluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        pymongo.MongoClient(cluster.connection)["test"]["test1"].insert_many(documents)
        backup_partial=cluster.make_backup("logical --ns=test.test")
        backup_full=cluster.make_backup("logical")
        pymongo.MongoClient(cluster.connection).drop_database('test')
        cluster.make_restore(backup_partial,check_pbm_status=True)
        assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == len(documents)
        assert pymongo.MongoClient(cluster.connection)["test"]["test1"].count_documents({}) == 0
        pymongo.MongoClient(cluster.connection).drop_database('test')
>       cluster.make_restore(backup_full,check_pbm_status=True)

test_replicaset.py:50: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f114f1021d0>, name = '2024-01-25T20:47:44Z'
kwargs = {'check_pbm_status': True}
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f11579f5c90>, exit_status=1, command=b'time...024-01-25T20:47:44Z --wait', _stdout=b'', _stderr=b"Error: backup '2024-01-25T20:47:44Z' didn't finish successfully\n")
n = <testinfra.host.Host docker://rs101>, timeout = 1706215753.2365644

    def make_restore(self, name, **kwargs):
        if self.layout == "sharded":
            client = pymongo.MongoClient(self.connection)
            result = client.admin.command("balancerStop")
            client.close()
            Cluster.log("Stopping balancer: " + str(result))
            self.stop_mongos()
        self.stop_arbiters()
        n = testinfra.get_host("docker://" + self.pbm_cli)
        timeout = time.time() + 60
    
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                assert False, "Cannot start restore, another operation running"
            time.sleep(1)
        Cluster.log("Restore started")
        result = n.run('timeout 240 pbm restore ' + name + ' --wait')
        if result.rc == 124:
            # try to catch possible failures if timeout exceeded
            for host in self.mongod_hosts:
                try:
                    container = docker.from_env().containers.get(host)
                    get_logs = container.exec_run(
                        'cat /var/lib/mongo/pbm.restore.log', stderr=False)
                    if get_logs.exit_code == 0:
                        Cluster.log(
                            "!!!!Possible failure on {}, file pbm.restore.log was found:".format(host))
                        Cluster.log(get_logs.output.decode('utf-8'))
                except docker.errors.APIError:
                    pass
            assert False, "Timeout for restore exceeded"
        elif result.rc == 0:
            Cluster.log(result.stdout)
        else:
>           assert False, result.stdout + result.stderr
E           AssertionError: Error: backup '2024-01-25T20:47:44Z' didn't finish successfully

cluster.py:450: AssertionError

Check failure on line 66 in psmdb-testing/pbm-functional/pytest/test_sharded.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_sharded.test_logical

AssertionError: Error: backup '2024-01-25T20:49:08Z' didn't finish successfully
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f1157986090>

    @pytest.mark.testcase(test_case_key="T218", test_step_key=1)
    @pytest.mark.timeout(600,func_only=True)
    def test_logical(start_cluster,cluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        pymongo.MongoClient(cluster.connection)["test"]["test1"].insert_many(documents)
        backup_partial_sharded=cluster.make_backup("logical --ns=test.test")
        backup_partial_unsharded=cluster.make_backup("logical --ns=test.test1")
        backup_full=cluster.make_backup("logical")
        pymongo.MongoClient(cluster.connection).drop_database('test')
        cluster.make_restore(backup_partial_sharded,check_pbm_status=True)
        assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == len(documents)
        assert pymongo.MongoClient(cluster.connection)["test"].command("collstats", "test").get("sharded", False)
>       cluster.make_restore(backup_partial_unsharded,check_pbm_status=True)

test_sharded.py:66: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f1157986090>, name = '2024-01-25T20:49:08Z'
kwargs = {'check_pbm_status': True}
client = MongoClient(host=['mongos:27017'], document_class=dict, tz_aware=False, connect=True)
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'time...024-01-25T20:49:08Z --wait', _stdout=b'', _stderr=b"Error: backup '2024-01-25T20:49:08Z' didn't finish successfully\n")
n = <testinfra.host.Host docker://rscfg01>, timeout = 1706215857.2654288

    def make_restore(self, name, **kwargs):
        if self.layout == "sharded":
            client = pymongo.MongoClient(self.connection)
            result = client.admin.command("balancerStop")
            client.close()
            Cluster.log("Stopping balancer: " + str(result))
            self.stop_mongos()
        self.stop_arbiters()
        n = testinfra.get_host("docker://" + self.pbm_cli)
        timeout = time.time() + 60
    
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                assert False, "Cannot start restore, another operation running"
            time.sleep(1)
        Cluster.log("Restore started")
        result = n.run('timeout 240 pbm restore ' + name + ' --wait')
        if result.rc == 124:
            # try to catch possible failures if timeout exceeded
            for host in self.mongod_hosts:
                try:
                    container = docker.from_env().containers.get(host)
                    get_logs = container.exec_run(
                        'cat /var/lib/mongo/pbm.restore.log', stderr=False)
                    if get_logs.exit_code == 0:
                        Cluster.log(
                            "!!!!Possible failure on {}, file pbm.restore.log was found:".format(host))
                        Cluster.log(get_logs.output.decode('utf-8'))
                except docker.errors.APIError:
                    pass
            assert False, "Timeout for restore exceeded"
        elif result.rc == 0:
            Cluster.log(result.stdout)
        else:
>           assert False, result.stdout + result.stderr
E           AssertionError: Error: backup '2024-01-25T20:49:08Z' didn't finish successfully

cluster.py:450: AssertionError

Check failure on line 96 in psmdb-testing/pbm-functional/pytest/test_sharded.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_sharded.test_logical_pitr

AssertionError: Unexpected exit code 1 for CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'pbm delete-backup -y 2024-01-25T20:53:42Z', _stdout=b'', _stderr=b'Error: backup cannot be deleted: cannot delete the last PITR base snapshot while PITR is enabled\n')
assert 1 == 0
 +  where 1 = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'pbm ...out=b'', _stderr=b'Error: backup cannot be deleted: cannot delete the last PITR base snapshot while PITR is enabled\n').rc
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7f1157986090>

    @pytest.mark.testcase(test_case_key="T194", test_step_key=1)
    @pytest.mark.timeout(600, func_only=True)
    def test_logical_pitr(start_cluster,cluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        backup_l1=cluster.make_backup("logical")
        cluster.enable_pitr(pitr_extra_args="--set pitr.oplogSpanMin=0.5")
        time.sleep(60)
        # make several following backups and then remove them to check the continuity of PITR timeframe
        pymongo.MongoClient(cluster.connection)["test"]["test2"].insert_many(documents)
        backup_l2=cluster.make_backup("logical")
        time.sleep(60)
        pymongo.MongoClient(cluster.connection)["test"]["test3"].insert_many(documents)
        backup_l3=cluster.make_backup("logical")
        pitr = datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%S")
        backup="--time=" + pitr
        Cluster.log("Time for PITR is: " + pitr)
        time.sleep(60)
        cluster.delete_backup(backup_l2)
>       cluster.delete_backup(backup_l3)

test_sharded.py:96: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f1157986090>, name = '2024-01-25T20:53:42Z'

    def delete_backup(self, name):
        n = testinfra.get_host("docker://" + self.pbm_cli)
>       result = n.check_output('pbm delete-backup -y ' + name)
E       AssertionError: Unexpected exit code 1 for CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'pbm delete-backup -y 2024-01-25T20:53:42Z', _stdout=b'', _stderr=b'Error: backup cannot be deleted: cannot delete the last PITR base snapshot while PITR is enabled\n')
E       assert 1 == 0
E        +  where 1 = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7f1157578390>, exit_status=1, command=b'pbm ...out=b'', _stderr=b'Error: backup cannot be deleted: cannot delete the last PITR base snapshot while PITR is enabled\n').rc

cluster.py:798: AssertionError