[PBM-907] slice oplog during logical backup #703
GitHub Actions / JUnit Test Report
failed
Jan 25, 2024 in 0s
15 tests run, 9 passed, 0 skipped, 6 failed.
Annotations
Check failure on line 79 in psmdb-testing/pbm-functional/pytest/test_PBM-1223.py
github-actions / JUnit Test Report
test_PBM-1223.test_logical
AssertionError: Starting restore 2024-01-25T20:29:36.116808249Z from '2024-01-25T20:29:15Z'...Started logical restore.
Waiting to finish...Error: operation failed with: waiting for dumpDone: cluster failed: reply oplog: replay chunk 1706214556.1706214559: apply oplog for chunk: applying a transaction entry: apply txn: {
"Timestamp": {
"T": 1706214556,
"I": 13
},
"Term": 1,
"Hash": null,
"Version": 2,
"Operation": "c",
"Namespace": "admin.$cmd",
"Object": [
{
"Key": "commitTransaction",
"Value": 1
},
{
"Key": "commitTimestamp",
"Value": {
"T": 1706214556,
"I": 10
}
}
],
"Query": null,
"UI": null,
"LSID": "SAAAAAVpZAAQAAAABHjwb9lhq0U9kenxXUbbLKQFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA",
"TxnNumber": 1,
"PrevOpTime": "HAAAABF0cwAKAAAAnMSyZRJ0AAEAAAAAAAAAAA=="
}: unknown transaction id SAAAAAVpZAAQAAAABHjwb9lhq0U9kenxXUbbLKQFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA-1Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7fb00bf03a90>
@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 0x7fb00bf03a90>, name = '2024-01-25T20:29:15Z'
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 0x7fb00b422150>, exit_status=1, command=b'time... id SAAAAAVpZAAQAAAABHjwb9lhq0U9kenxXUbbLKQFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA-1\n', _stderr=b'')
n = <testinfra.host.Host docker://rscfg01>, timeout = 1706214634.81804
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:36.116808249Z from '2024-01-25T20:29:15Z'...Started logical restore.
E Waiting to finish...Error: operation failed with: waiting for dumpDone: cluster failed: reply oplog: replay chunk 1706214556.1706214559: apply oplog for chunk: applying a transaction entry: apply txn: {
E "Timestamp": {
E "T": 1706214556,
E "I": 13
E },
E "Term": 1,
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": 1706214556,
E "I": 10
E }
E }
E ],
E "Query": null,
E "UI": null,
E "LSID": "SAAAAAVpZAAQAAAABHjwb9lhq0U9kenxXUbbLKQFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA",
E "TxnNumber": 1,
E "PrevOpTime": "HAAAABF0cwAKAAAAnMSyZRJ0AAEAAAAAAAAAAA=="
E }: unknown transaction id SAAAAAVpZAAQAAAABHjwb9lhq0U9kenxXUbbLKQFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA-1
cluster.py:450: AssertionError
Check failure on line 93 in psmdb-testing/pbm-functional/pytest/test_azurite.py
github-actions / JUnit Test Report
test_azurite.test_logical_pitr
AssertionError: Unexpected exit code 1 for CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7fb00b422150>, exit_status=1, command=b'pbm delete-backup -y 2024-01-25T20:38:57Z', _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 0x7fb00b422150>, 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 0x7fb000e33050>
@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 0x7fb000e33050>, name = '2024-01-25T20:38:57Z'
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 0x7fb00b422150>, exit_status=1, command=b'pbm delete-backup -y 2024-01-25T20:38:57Z', _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 0x7fb00b422150>, 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
github-actions / JUnit Test Report
test_fresh_sharded.test_logical
AssertionError: Error: backup '2024-01-25T20:41:49Z' didn't finish successfully
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7fb000dac150>
newcluster = <cluster.Cluster object at 0x7fb000dac910>
@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 0x7fb000dac910>, name = '2024-01-25T20:41:49Z'
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 0x7fb000dadb50>, exit_status=1, command=b'time...024-01-25T20:41:49Z --wait', _stdout=b'', _stderr=b"Error: backup '2024-01-25T20:41:49Z' didn't finish successfully\n")
n = <testinfra.host.Host docker://newrscfg01>, timeout = 1706215407.2472947
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:49Z' didn't finish successfully
cluster.py:450: AssertionError
Check failure on line 76 in psmdb-testing/pbm-functional/pytest/test_remap_sharded.py
github-actions / JUnit Test Report
test_remap_sharded.test_logical
AssertionError: Error: backup '2024-01-25T20:46:22Z' didn't finish successfully
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7fb000dddc10>
newcluster = <cluster.Cluster object at 0x7fb000ddc810>
@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 0x7fb000ddc810>
name = '2024-01-25T20:46:22Z --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 0x7fb000dadb50>, exit_status=1, command=b'time...rs2,newrscfg=rscfg" --wait', _stdout=b'', _stderr=b"Error: backup '2024-01-25T20:46:22Z' didn't finish successfully\n")
n = <testinfra.host.Host docker://newrscfg01>, timeout = 1706215680.8409007
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:22Z' didn't finish successfully
cluster.py:450: AssertionError
Check failure on line 50 in psmdb-testing/pbm-functional/pytest/test_replicaset.py
github-actions / JUnit Test Report
test_replicaset.test_logical
AssertionError: Error: backup '2024-01-25T20:47:46Z' didn't finish successfully
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7fb00b387690>
@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 0x7fb00b387690>, name = '2024-01-25T20:47:46Z'
kwargs = {'check_pbm_status': True}
result = CommandResult(backend=<testinfra.backend.docker.DockerBackend object at 0x7fb00b4d4750>, exit_status=1, command=b'time...024-01-25T20:47:46Z --wait', _stdout=b'', _stderr=b"Error: backup '2024-01-25T20:47:46Z' didn't finish successfully\n")
n = <testinfra.host.Host docker://rs101>, timeout = 1706215753.1065116
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:46Z' didn't finish successfully
cluster.py:450: AssertionError
Check failure on line 66 in psmdb-testing/pbm-functional/pytest/test_sharded.py
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 0x7fb000dc7990>
@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 0x7fb000dc7990>, 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 0x7fb00b422150>, 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 = 1706215859.5788288
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
Loading