Skip to content

Commit

Permalink
PBM-1223 check logical backup when distributed txn was started before…
Browse files Browse the repository at this point in the history 
… backup
  • Loading branch information
@olexandr-havryliak
olexandr-havryliak committed Dec 15, 2023
1 parent 5bd9250 commit 5942c08
Show file tree
Hide file tree
Showing 2 changed files with 83 additions and 0 deletions.
82 changes: 82 additions & 0 deletions pbm-functional/pytest/test_PBM-1223.py
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,82 @@
import pytest
import pymongo
import bson
import testinfra
import time
import os
import docker
import threading
import concurrent.futures

from datetime import datetime
from cluster import Cluster

documents=[{"a": 1}, {"b": 2}, {"c": 3}, {"d": 4}]

@pytest.fixture(scope="package")
def docker_client():
return docker.from_env()

@pytest.fixture(scope="package")
def config():
return { "mongos": "mongos",
"configserver":
{"_id": "rscfg", "members": [{"host":"rscfg01"},{"host": "rscfg02"},{"host": "rscfg03" }]},
"shards":[
{"_id": "rs1", "members": [{"host":"rs101"},{"host": "rs102"},{"host": "rs103" }]},
{"_id": "rs2", "members": [{"host":"rs201"},{"host": "rs202"},{"host": "rs203" }]}
]}

@pytest.fixture(scope="package")
def cluster(config):
return Cluster(config)

@pytest.fixture(scope="function")
def start_cluster(cluster,request):
try:
cluster.destroy()
cluster.create()
cluster.setup_pbm()
os.chmod("/backups",0o777)
os.system("rm -rf /backups/*")
result = cluster.exec_pbm_cli("config --set storage.type=filesystem --set storage.filesystem.path=/backups --set backup.compression=none --out json")
assert result.rc == 0
Cluster.log("Setup PBM with fs storage:\n" + result.stdout)
client=pymongo.MongoClient(cluster.connection)
client.admin.command("enableSharding", "test")
client.admin.command("shardCollection", "test.test", key={"_id": "hashed"})
yield True

finally:
if request.config.getoption("--verbose"):
cluster.get_logs()
cluster.destroy(cleanup_backups=True)

@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)

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

View workflow job for this annotation

GitHub Actions / JUnit Test Report

test_PBM-1223.test_logical 

AssertionError: Starting restore 2023-12-15T09:10:47.697704262Z from '2023-12-15T09:10:26Z'...Started logical restore.
Waiting to finish...Error: operation failed with: reply oplog: replay chunk 1702631427.1702631431: apply oplog for chunk: applying a transaction entry: apply txn: {
 "Timestamp": {
  "T": 1702631427,
  "I": 9
 },
 "Term": 1,
 "Hash": null,
 "Version": 2,
 "Operation": "c",
 "Namespace": "admin.$cmd",
 "Object": [
  {
   "Key": "commitTransaction",
   "Value": 1
  },
  {
   "Key": "commitTimestamp",
   "Value": {
    "T": 1702631427,
    "I": 7
   }
  }
 ],
 "Query": null,
 "UI": null,
 "LSID": "SAAAAAVpZAAQAAAABIAdyWrJw0oegMaGMCt0+t4FdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA",
 "TxnNumber": 1,
 "PrevOpTime": "HAAAABF0cwAHAAAAAxh8ZRJ0AAEAAAAAAAAAAA=="
}: unknown transaction id SAAAAAVpZAAQAAAABIAdyWrJw0oegMaGMCt0+t4FdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA-1
Raw output 
start_cluster = True, cluster = <cluster.Cluster object at 0x7fbaefef0d90>

    @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 0x7fbaefef0d90>, name = '2023-12-15T09:10:26Z'
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 0x7fbaf1243410>, exit_status=1, command=b'time... id SAAAAAVpZAAQAAAABIAdyWrJw0oegMaGMCt0+t4FdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA-1\n', _stderr=b'')
n = <testinfra.host.Host docker://rscfg01>, timeout = 1702631507.5398917

    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 2023-12-15T09:10:47.697704262Z from '2023-12-15T09:10:26Z'...Started logical restore.
E           Waiting to finish...Error: operation failed with: reply oplog: replay chunk 1702631427.1702631431: apply oplog for chunk: applying a transaction entry: apply txn: {
E            "Timestamp": {
E             "T": 1702631427,
E             "I": 9
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": 1702631427,
E               "I": 7
E              }
E             }
E            ],
E            "Query": null,
E            "UI": null,
E            "LSID": "SAAAAAVpZAAQAAAABIAdyWrJw0oegMaGMCt0+t4FdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA",
E            "TxnNumber": 1,
E            "PrevOpTime": "HAAAABF0cwAHAAAAAxh8ZRJ0AAEAAAAAAAAAAA=="
E           }: unknown transaction id SAAAAAVpZAAQAAAABIAdyWrJw0oegMaGMCt0+t4FdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgA-1

cluster.py:450: AssertionError
assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == 8
assert pymongo.MongoClient(cluster.connection)["test"].command("collstats", "test").get("sharded", False)
Cluster.log("Finished successfully\n")
1 change: 1 addition & 0 deletions pbm-functional/pytest/test_PBM-773.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -110,3 +110,4 @@ def test_logical(start_cluster,cluster):
assert pymongo.MongoClient(cluster.connection)["test"]["test"].count_documents({}) == len(documents) + 8
assert pymongo.MongoClient(cluster.connection)["test"].command("collstats", "test").get("sharded", False)
Cluster.log("Finished successfully\n")

0 comments on commit 5942c08

Please sign in to comment.