Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

PBM-1389 disallow performing selective backup #226

Merged
merged 1 commit into from
Sep 19, 2024

PBM-1389 disallow performing selective backup

bc27086
Select commit
Loading
Failed to load commit list.
Refresh
Sign in for the full log view
Merged

PBM-1389 disallow performing selective backup #226

PBM-1389 disallow performing selective backup
bc27086
Select commit
Loading
Failed to load commit list.
GitHub Actions / JUnit Test Report failed Sep 19, 2024 in 0s

5 tests run, 3 passed, 0 skipped, 2 failed.

Annotations

Check failure on line 181 in 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_external_PBM_T240 

AssertionError: Cannot start restore, another operation running: {'type': 'backup', 'opID': '66ec2372687dbda9936a5031', 'name': '2024-09-19T13:13:22Z', 'startTS': 1726751602, 'status': 'copyDone'}
2024-09-19T13:13:00Z I [rs1/rs103:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
GitBranch: dev
BuildTime: 2024-09-19_13:12_UTC
GoVersion: go1.23.1
2024-09-19T13:13:00Z I [rs1/rs103:27017] starting PITR routine
2024-09-19T13:13:00Z I [rs1/rs102:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
GitBranch: dev
BuildTime: 2024-09-19_13:12_UTC
GoVersion: go1.23.1
2024-09-19T13:13:00Z I [rs1/rs102:27017] starting PITR routine
2024-09-19T13:13:00Z I [rs1/rs103:27017] node: rs1/rs103:27017
2024-09-19T13:13:00Z I [rs1/rs101:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
GitBranch: dev
BuildTime: 2024-09-19_13:12_UTC
GoVersion: go1.23.1
2024-09-19T13:13:00Z I [rs1/rs101:27017] starting PITR routine
2024-09-19T13:13:00Z I [rs1/rs102:27017] node: rs1/rs102:27017
2024-09-19T13:13:00Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T13:13:00Z I [rs1/rs101:27017] node: rs1/rs101:27017
2024-09-19T13:13:00Z I [rs1/rs103:27017] listening for the commands
2024-09-19T13:13:00Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T13:13:00Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T13:13:00Z I [rs1/rs102:27017] listening for the commands
2024-09-19T13:13:00Z I [rs1/rs101:27017] listening for the commands
2024-09-19T13:13:02Z I [rs1/rs104:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
GitBranch: dev
BuildTime: 2024-09-19_13:12_UTC
GoVersion: go1.23.1
2024-09-19T13:13:02Z I [rs1/rs104:27017] node: rs1/rs104:27017
2024-09-19T13:13:02Z I [rs1/rs104:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T13:13:02Z I [rs1/rs104:27017] listening for the commands
2024-09-19T13:13:05Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T13:13:05Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T13:13:05Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:13:05Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:13:05Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T13:13:05Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:13:07Z W [rs1/rs104:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T13:13:07Z E [rs1/rs104:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:13:10Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:13:10Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:13:10Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:13:12Z W [rs1/rs104:27017] [agentCheckup] storage is not initialized
2024-09-19T13:13:12Z I [rs1/rs104:27017] got command resync <ts: 1726751591>
2024-09-19T13:13:12Z I [rs1/rs104:27017] got epoch {1726751590 6}
2024-09-19T13:13:12Z I [rs1/rs104:27017] [resync] started
2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] got backups list: 0
2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] got physical restores list: 0
2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] epoch set to {1726751592 10}
2024-09-19T13:13:12Z I [rs1/rs104:27017] [resync] succeed
2024-09-19T13:13:12Z I [rs1/rs103:27017] got command resync <ts: 1726751591>
2024-09-19T13:13:12Z I [rs1/rs102:27017] got command resync <ts: 1726751591>
2024-09-19T13:13:12Z I [rs1/rs101:27017] got command resync <ts: 1726751591>
2024-09-19T13:13:12Z I [rs1/rs103:27017] got epoch {1726751592 10}
2024-09-19T13:13:12Z I [rs1/rs102:27017] got epoch {1726751592 10}
2024-09-19T13:13:12Z I [rs1/rs101:27017] got epoch {1726751592 10}
2024-09-19T13:13:12Z D [rs1/rs101:27017] [resync] lock not acquired
2024-09-19T13:13:12Z D [rs1/rs102:27017] [resync] lock not acquired
2024-09-19T13:13:12Z D [rs1/rs103:27017] [resync] get lock: duplicate operation: 66ec236782f7d809ca024cc6 [Resync storage]
2024-09-19T13:13:12Z D [rs1/rs103:27017] [resync] lock not acquired
2024-09-19T13:13:22Z I [rs1/rs103:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
2024-09-19T13:13:22Z I [rs1/rs102:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
2024-09-19T13:13:22Z I [rs1/rs103:27017] got epoch {1726751592 10}
2024-09-19T13:13:22Z I [rs1/rs101:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
2024-09-19T13:13:22Z I [rs1/rs102:27017] got epoch {1726751592 10}
2024-09-19T13:13:22Z I [rs1/rs101:27017] got epoch {1726751592 10}
2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] init backup meta
2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] nomination list for rs1: [[rs103:27017] [rs102:27017] [rs101:27017]]
2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] nomination rs1, set candidates [rs103:27017]
2024-09-19T13:13:22Z I [rs1/rs103:27017] [backup/2024-09-19T13:13:22Z] backup started
2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] skip after nomination, probably started by another node
2024-09-19T13:13:23Z I [rs1/rs104:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
2024-09-19T13:13:23Z I [rs1/rs104:27017] got epoch {1726751592 10}
2024-09-19T13:13:23Z D [rs1/rs102:27017] [backup/2024-09-19T13:13:22Z] skip after nomination, probably started by another node
2024-09-19T13:13:23Z D [rs1/rs104:27017] [backup/2024-09-19T13:13:22Z] skip after nomination, probably started by another node
2024-09-19T13:13:23Z D [rs1/rs103:27017] [backup/2024-09-19T13:13:22Z] backup cursor id: de4f11d4-840b-44fb-9cce-13cce6ad75c3
2024-09-19T13:13:26Z D [rs1/rs103:27017] [backup/2024-09-19T13:13:22Z] set journal up to {1726751603 5}
2024-09-19T13:13:27Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] bcp nomination: rs1 won by rs103:27017
Raw output 
start_cluster = True, cluster = <cluster.Cluster object at 0x7f36ed49b4d0>

    @pytest.mark.timeout(600,func_only=True)
    def test_external_PBM_T240(start_cluster,cluster):
        time.sleep(5)
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        backup = cluster.external_backup_start()
        result=pymongo.MongoClient(cluster.connection)["test"]["test"].delete_many({})
        assert int(result.deleted_count) == len(documents)
        cluster.external_backup_copy(backup)
        cluster.external_backup_finish(backup)
        time.sleep(10)
>       restore=cluster.external_restore_start()

test_PBM-979.py:181: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f36ed49b4d0>

    def external_restore_start(self):
        timeout = time.time() + 60
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                n = testinfra.get_host("docker://" + self.pbm_cli)
                logs = n.check_output("pbm logs -sD -t0")
>               assert False, "Cannot start restore, another operation running: " + str(self.get_status()['running']) + "\n" + logs
E               AssertionError: Cannot start restore, another operation running: {'type': 'backup', 'opID': '66ec2372687dbda9936a5031', 'name': '2024-09-19T13:13:22Z', 'startTS': 1726751602, 'status': 'copyDone'}
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] starting PITR routine
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] starting PITR routine
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] node: rs1/rs103:27017
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] starting PITR routine
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] node: rs1/rs102:27017
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] node: rs1/rs101:27017
E               2024-09-19T13:13:00Z I [rs1/rs103:27017] listening for the commands
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:13:00Z I [rs1/rs102:27017] listening for the commands
E               2024-09-19T13:13:00Z I [rs1/rs101:27017] listening for the commands
E               2024-09-19T13:13:02Z I [rs1/rs104:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:13:02Z I [rs1/rs104:27017] node: rs1/rs104:27017
E               2024-09-19T13:13:02Z I [rs1/rs104:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:13:02Z I [rs1/rs104:27017] listening for the commands
E               2024-09-19T13:13:05Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:13:05Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:13:05Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:05Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:05Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:13:05Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:07Z W [rs1/rs104:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:13:07Z E [rs1/rs104:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:10Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:10Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:10Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:13:12Z W [rs1/rs104:27017] [agentCheckup] storage is not initialized
E               2024-09-19T13:13:12Z I [rs1/rs104:27017] got command resync <ts: 1726751591>
E               2024-09-19T13:13:12Z I [rs1/rs104:27017] got epoch {1726751590 6}
E               2024-09-19T13:13:12Z I [rs1/rs104:27017] [resync] started
E               2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E               2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] got backups list: 0
E               2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] got physical restores list: 0
E               2024-09-19T13:13:12Z D [rs1/rs104:27017] [resync] epoch set to {1726751592 10}
E               2024-09-19T13:13:12Z I [rs1/rs104:27017] [resync] succeed
E               2024-09-19T13:13:12Z I [rs1/rs103:27017] got command resync <ts: 1726751591>
E               2024-09-19T13:13:12Z I [rs1/rs102:27017] got command resync <ts: 1726751591>
E               2024-09-19T13:13:12Z I [rs1/rs101:27017] got command resync <ts: 1726751591>
E               2024-09-19T13:13:12Z I [rs1/rs103:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:12Z I [rs1/rs102:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:12Z I [rs1/rs101:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:12Z D [rs1/rs101:27017] [resync] lock not acquired
E               2024-09-19T13:13:12Z D [rs1/rs102:27017] [resync] lock not acquired
E               2024-09-19T13:13:12Z D [rs1/rs103:27017] [resync] get lock: duplicate operation: 66ec236782f7d809ca024cc6 [Resync storage]
E               2024-09-19T13:13:12Z D [rs1/rs103:27017] [resync] lock not acquired
E               2024-09-19T13:13:22Z I [rs1/rs103:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
E               2024-09-19T13:13:22Z I [rs1/rs102:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
E               2024-09-19T13:13:22Z I [rs1/rs103:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:22Z I [rs1/rs101:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
E               2024-09-19T13:13:22Z I [rs1/rs102:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:22Z I [rs1/rs101:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] init backup meta
E               2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] nomination list for rs1: [[rs103:27017] [rs102:27017] [rs101:27017]]
E               2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] nomination rs1, set candidates [rs103:27017]
E               2024-09-19T13:13:22Z I [rs1/rs103:27017] [backup/2024-09-19T13:13:22Z] backup started
E               2024-09-19T13:13:22Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] skip after nomination, probably started by another node
E               2024-09-19T13:13:23Z I [rs1/rs104:27017] got command backup [name: 2024-09-19T13:13:22Z, compression: s2 (level: default)] <ts: 1726751602>
E               2024-09-19T13:13:23Z I [rs1/rs104:27017] got epoch {1726751592 10}
E               2024-09-19T13:13:23Z D [rs1/rs102:27017] [backup/2024-09-19T13:13:22Z] skip after nomination, probably started by another node
E               2024-09-19T13:13:23Z D [rs1/rs104:27017] [backup/2024-09-19T13:13:22Z] skip after nomination, probably started by another node
E               2024-09-19T13:13:23Z D [rs1/rs103:27017] [backup/2024-09-19T13:13:22Z] backup cursor id: de4f11d4-840b-44fb-9cce-13cce6ad75c3
E               2024-09-19T13:13:26Z D [rs1/rs103:27017] [backup/2024-09-19T13:13:22Z] set journal up to {1726751603 5}
E               2024-09-19T13:13:27Z D [rs1/rs101:27017] [backup/2024-09-19T13:13:22Z] bcp nomination: rs1 won by rs103:27017

cluster.py:866: AssertionError

Check failure on line 74 in pbm-functional/pytest/test_vault.py

See this annotation in the file changed.

@github-actions github-actions / JUnit Test Report

test_vault.test_external_PBM_T239 

AssertionError: Cannot start restore, another operation running: {'type': 'backup', 'opID': '66ec27e444069529e3dbeaae', 'name': '2024-09-19T13:32:20Z', 'startTS': 1726752740, 'status': 'copyDone'}
2024-09-19T13:32:08Z I [rs1/rs102:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
GitBranch: dev
BuildTime: 2024-09-19_13:12_UTC
GoVersion: go1.23.1
2024-09-19T13:32:08Z I [rs1/rs102:27017] starting PITR routine
2024-09-19T13:32:08Z I [rs1/rs101:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
GitBranch: dev
BuildTime: 2024-09-19_13:12_UTC
GoVersion: go1.23.1
2024-09-19T13:32:08Z I [rs1/rs101:27017] starting PITR routine
2024-09-19T13:32:08Z I [rs1/rs102:27017] node: rs1/rs102:27017
2024-09-19T13:32:08Z I [rs1/rs103:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
GitBranch: dev
BuildTime: 2024-09-19_13:12_UTC
GoVersion: go1.23.1
2024-09-19T13:32:08Z I [rs1/rs103:27017] starting PITR routine
2024-09-19T13:32:08Z I [rs1/rs101:27017] node: rs1/rs101:27017
2024-09-19T13:32:08Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T13:32:08Z I [rs1/rs102:27017] listening for the commands
2024-09-19T13:32:08Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T13:32:08Z I [rs1/rs103:27017] node: rs1/rs103:27017
2024-09-19T13:32:08Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T13:32:08Z I [rs1/rs101:27017] listening for the commands
2024-09-19T13:32:08Z I [rs1/rs103:27017] listening for the commands
2024-09-19T13:32:13Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T13:32:13Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:32:13Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T13:32:13Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:32:13Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T13:32:13Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T13:32:15Z I [rs1/rs102:27017] got command resync <ts: 1726752734>
2024-09-19T13:32:15Z I [rs1/rs101:27017] got command resync <ts: 1726752734>
2024-09-19T13:32:15Z I [rs1/rs102:27017] got epoch {1726752733 11}
2024-09-19T13:32:15Z I [rs1/rs101:27017] got epoch {1726752733 11}
2024-09-19T13:32:15Z I [rs1/rs103:27017] got command resync <ts: 1726752734>
2024-09-19T13:32:15Z I [rs1/rs103:27017] got epoch {1726752733 11}
2024-09-19T13:32:15Z I [rs1/rs102:27017] [resync] started
2024-09-19T13:32:15Z D [rs1/rs101:27017] [resync] lock not acquired
2024-09-19T13:32:15Z D [rs1/rs103:27017] [resync] lock not acquired
2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] got backups list: 0
2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] got physical restores list: 2
2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] epoch set to {1726752735 16}
2024-09-19T13:32:15Z I [rs1/rs102:27017] [resync] succeed
2024-09-19T13:32:20Z I [rs1/rs101:27017] got command backup [name: 2024-09-19T13:32:20Z, compression: s2 (level: default)] <ts: 1726752740>
2024-09-19T13:32:20Z I [rs1/rs102:27017] got command backup [name: 2024-09-19T13:32:20Z, compression: s2 (level: default)] <ts: 1726752740>
2024-09-19T13:32:20Z I [rs1/rs101:27017] got epoch {1726752735 16}
2024-09-19T13:32:20Z I [rs1/rs102:27017] got epoch {1726752735 16}
2024-09-19T13:32:20Z I [rs1/rs103:27017] got command backup [name: 2024-09-19T13:32:20Z, compression: s2 (level: default)] <ts: 1726752740>
2024-09-19T13:32:20Z I [rs1/rs103:27017] got epoch {1726752735 16}
2024-09-19T13:32:20Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] init backup meta
2024-09-19T13:32:20Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] nomination list for rs1: [[rs102:27017 rs103:27017] [rs101:27017]]
2024-09-19T13:32:20Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] nomination rs1, set candidates [rs102:27017 rs103:27017]
2024-09-19T13:32:21Z I [rs1/rs102:27017] [backup/2024-09-19T13:32:20Z] backup started
2024-09-19T13:32:21Z D [rs1/rs103:27017] [backup/2024-09-19T13:32:20Z] skip: lock not acquired
2024-09-19T13:32:21Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] skip after nomination, probably started by another node
2024-09-19T13:32:22Z D [rs1/rs102:27017] [backup/2024-09-19T13:32:20Z] backup cursor id: 35edf6ca-27ff-406d-a5e0-c1eb502a819e
2024-09-19T13:32:25Z D [rs1/rs102:27017] [backup/2024-09-19T13:32:20Z] set journal up to {1726752741 6}
2024-09-19T13:32:25Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] bcp nomination: rs1 won by rs102:27017
Raw output 
start_cluster = True, cluster = <cluster.Cluster object at 0x7f36ebe4f410>

    @pytest.mark.timeout(600,func_only=True)
    def test_external_PBM_T239(start_cluster,cluster):
        cluster.check_pbm_status()
        pymongo.MongoClient(cluster.connection)["test"]["test"].insert_many(documents)
        backup = cluster.external_backup_start()
        result=pymongo.MongoClient(cluster.connection)["test"]["test"].delete_many({})
        assert int(result.deleted_count) == len(documents)
        cluster.external_backup_copy(backup)
        cluster.external_backup_finish(backup)
        time.sleep(10)
    
>       restore=cluster.external_restore_start()

test_vault.py:74: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cluster.Cluster object at 0x7f36ebe4f410>

    def external_restore_start(self):
        timeout = time.time() + 60
        while True:
            if not self.get_status()['running']:
                break
            if time.time() > timeout:
                n = testinfra.get_host("docker://" + self.pbm_cli)
                logs = n.check_output("pbm logs -sD -t0")
>               assert False, "Cannot start restore, another operation running: " + str(self.get_status()['running']) + "\n" + logs
E               AssertionError: Cannot start restore, another operation running: {'type': 'backup', 'opID': '66ec27e444069529e3dbeaae', 'name': '2024-09-19T13:32:20Z', 'startTS': 1726752740, 'status': 'copyDone'}
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] starting PITR routine
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] starting PITR routine
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] node: rs1/rs102:27017
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: d556a6dc87585a4af72174e2a57970ea9e6ab5cb
E               GitBranch: dev
E               BuildTime: 2024-09-19_13:12_UTC
E               GoVersion: go1.23.1
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] starting PITR routine
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] node: rs1/rs101:27017
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:32:08Z I [rs1/rs102:27017] listening for the commands
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] node: rs1/rs103:27017
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T13:32:08Z I [rs1/rs101:27017] listening for the commands
E               2024-09-19T13:32:08Z I [rs1/rs103:27017] listening for the commands
E               2024-09-19T13:32:13Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:32:13Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:32:13Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:32:13Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:32:13Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T13:32:13Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T13:32:15Z I [rs1/rs102:27017] got command resync <ts: 1726752734>
E               2024-09-19T13:32:15Z I [rs1/rs101:27017] got command resync <ts: 1726752734>
E               2024-09-19T13:32:15Z I [rs1/rs102:27017] got epoch {1726752733 11}
E               2024-09-19T13:32:15Z I [rs1/rs101:27017] got epoch {1726752733 11}
E               2024-09-19T13:32:15Z I [rs1/rs103:27017] got command resync <ts: 1726752734>
E               2024-09-19T13:32:15Z I [rs1/rs103:27017] got epoch {1726752733 11}
E               2024-09-19T13:32:15Z I [rs1/rs102:27017] [resync] started
E               2024-09-19T13:32:15Z D [rs1/rs101:27017] [resync] lock not acquired
E               2024-09-19T13:32:15Z D [rs1/rs103:27017] [resync] lock not acquired
E               2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E               2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] got backups list: 0
E               2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] got physical restores list: 2
E               2024-09-19T13:32:15Z D [rs1/rs102:27017] [resync] epoch set to {1726752735 16}
E               2024-09-19T13:32:15Z I [rs1/rs102:27017] [resync] succeed
E               2024-09-19T13:32:20Z I [rs1/rs101:27017] got command backup [name: 2024-09-19T13:32:20Z, compression: s2 (level: default)] <ts: 1726752740>
E               2024-09-19T13:32:20Z I [rs1/rs102:27017] got command backup [name: 2024-09-19T13:32:20Z, compression: s2 (level: default)] <ts: 1726752740>
E               2024-09-19T13:32:20Z I [rs1/rs101:27017] got epoch {1726752735 16}
E               2024-09-19T13:32:20Z I [rs1/rs102:27017] got epoch {1726752735 16}
E               2024-09-19T13:32:20Z I [rs1/rs103:27017] got command backup [name: 2024-09-19T13:32:20Z, compression: s2 (level: default)] <ts: 1726752740>
E               2024-09-19T13:32:20Z I [rs1/rs103:27017] got epoch {1726752735 16}
E               2024-09-19T13:32:20Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] init backup meta
E               2024-09-19T13:32:20Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] nomination list for rs1: [[rs102:27017 rs103:27017] [rs101:27017]]
E               2024-09-19T13:32:20Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] nomination rs1, set candidates [rs102:27017 rs103:27017]
E               2024-09-19T13:32:21Z I [rs1/rs102:27017] [backup/2024-09-19T13:32:20Z] backup started
E               2024-09-19T13:32:21Z D [rs1/rs103:27017] [backup/2024-09-19T13:32:20Z] skip: lock not acquired
E               2024-09-19T13:32:21Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] skip after nomination, probably started by another node
E               2024-09-19T13:32:22Z D [rs1/rs102:27017] [backup/2024-09-19T13:32:20Z] backup cursor id: 35edf6ca-27ff-406d-a5e0-c1eb502a819e
E               2024-09-19T13:32:25Z D [rs1/rs102:27017] [backup/2024-09-19T13:32:20Z] set journal up to {1726752741 6}
E               2024-09-19T13:32:25Z D [rs1/rs101:27017] [backup/2024-09-19T13:32:20Z] bcp nomination: rs1 won by rs102:27017

cluster.py:866: AssertionError
View more details on GitHub Actions