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 fix link for CE #225

Merged
merged 1 commit into from
Sep 19, 2024

PBM fix link for CE

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

PBM fix link for CE #225

PBM fix link for CE
4e2d56c
Select commit
Loading
Failed to load commit list.
GitHub Actions / JUnit Test Report failed Sep 19, 2024 in 0s

5 tests run, 4 passed, 0 skipped, 1 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': '66ebb0fc21b5158f3a17349b', 'name': '2024-09-19T05:05:00Z', 'startTS': 1726722301, 'status': 'copyDone'}
2024-09-19T05:04:38Z I [rs1/rs103:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
GitBranch: dev
BuildTime: 2024-09-19_05:03_UTC
GoVersion: go1.23.1
2024-09-19T05:04:38Z I [rs1/rs102:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
GitBranch: dev
BuildTime: 2024-09-19_05:03_UTC
GoVersion: go1.23.1
2024-09-19T05:04:38Z I [rs1/rs102:27017] starting PITR routine
2024-09-19T05:04:38Z I [rs1/rs103:27017] starting PITR routine
2024-09-19T05:04:38Z I [rs1/rs101:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
GitBranch: dev
BuildTime: 2024-09-19_05:03_UTC
GoVersion: go1.23.1
2024-09-19T05:04:38Z I [rs1/rs101:27017] starting PITR routine
2024-09-19T05:04:38Z I [rs1/rs102:27017] node: rs1/rs102:27017
2024-09-19T05:04:38Z I [rs1/rs101:27017] node: rs1/rs101:27017
2024-09-19T05:04:38Z I [rs1/rs103:27017] node: rs1/rs103:27017
2024-09-19T05:04:38Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T05:04:38Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T05:04:38Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T05:04:38Z I [rs1/rs103:27017] listening for the commands
2024-09-19T05:04:38Z I [rs1/rs102:27017] listening for the commands
2024-09-19T05:04:38Z I [rs1/rs101:27017] listening for the commands
2024-09-19T05:04:40Z I [rs1/rs104:27017] pbm-agent:
Version:   2.6.0
Platform:  linux/amd64
GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
GitBranch: dev
BuildTime: 2024-09-19_05:03_UTC
GoVersion: go1.23.1
2024-09-19T05:04:40Z I [rs1/rs104:27017] node: rs1/rs104:27017
2024-09-19T05:04:40Z I [rs1/rs104:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-19T05:04:40Z I [rs1/rs104:27017] listening for the commands
2024-09-19T05:04:43Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T05:04:43Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T05:04:43Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T05:04:43Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T05:04:43Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T05:04:43Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T05:04:45Z W [rs1/rs104:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-19T05:04:45Z E [rs1/rs104:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T05:04:48Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T05:04:48Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T05:04:48Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-19T05:04:50Z W [rs1/rs104:27017] [agentCheckup] storage is not initialized
2024-09-19T05:04:50Z I [rs1/rs104:27017] got command resync <ts: 1726722290>
2024-09-19T05:04:50Z I [rs1/rs104:27017] got epoch {1726722288 6}
2024-09-19T05:04:50Z I [rs1/rs104:27017] [resync] started
2024-09-19T05:04:50Z D [rs1/rs104:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
2024-09-19T05:04:50Z D [rs1/rs104:27017] [resync] got backups list: 0
2024-09-19T05:04:50Z D [rs1/rs104:27017] [resync] got physical restores list: 0
2024-09-19T05:04:50Z D [rs1/rs104:27017] [resync] epoch set to {1726722290 13}
2024-09-19T05:04:50Z I [rs1/rs104:27017] [resync] succeed
2024-09-19T05:04:51Z I [rs1/rs103:27017] got command resync <ts: 1726722290>
2024-09-19T05:04:51Z I [rs1/rs102:27017] got command resync <ts: 1726722290>
2024-09-19T05:04:51Z I [rs1/rs101:27017] got command resync <ts: 1726722290>
2024-09-19T05:04:51Z I [rs1/rs103:27017] got epoch {1726722290 13}
2024-09-19T05:04:51Z I [rs1/rs102:27017] got epoch {1726722290 13}
2024-09-19T05:04:51Z I [rs1/rs101:27017] got epoch {1726722290 13}
2024-09-19T05:04:51Z D [rs1/rs102:27017] [resync] lock not acquired
2024-09-19T05:04:51Z D [rs1/rs101:27017] [resync] lock not acquired
2024-09-19T05:04:51Z D [rs1/rs103:27017] [resync] get lock: duplicate operation: 66ebb0f20ade0ead2097d9f5 [Resync storage]
2024-09-19T05:04:51Z D [rs1/rs103:27017] [resync] lock not acquired
2024-09-19T05:05:00Z I [rs1/rs104:27017] got command backup [name: 2024-09-19T05:05:00Z, compression: s2 (level: default)] <ts: 1726722300>
2024-09-19T05:05:00Z I [rs1/rs104:27017] got epoch {1726722290 13}
2024-09-19T05:05:01Z I [rs1/rs102:27017] got command backup [name: 2024-09-19T05:05:00Z, compression: s2 (level: default)] <ts: 1726722300>
2024-09-19T05:05:01Z I [rs1/rs103:27017] got command backup [name: 2024-09-19T05:05:00Z, compression: s2 (level: default)] <ts: 1726722300>
2024-09-19T05:05:01Z I [rs1/rs101:27017] got command backup [name: 2024-09-19T05:05:00Z, compression: s2 (level: default)] <ts: 1726722300>
2024-09-19T05:05:01Z I [rs1/rs102:27017] got epoch {1726722290 13}
2024-09-19T05:05:01Z I [rs1/rs103:27017] got epoch {1726722290 13}
2024-09-19T05:05:01Z I [rs1/rs101:27017] got epoch {1726722290 13}
2024-09-19T05:05:01Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] init backup meta
2024-09-19T05:05:01Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] nomination list for rs1: [[rs103:27017] [rs102:27017] [rs101:27017]]
2024-09-19T05:05:01Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] nomination rs1, set candidates [rs103:27017]
2024-09-19T05:05:01Z I [rs1/rs103:27017] [backup/2024-09-19T05:05:00Z] backup started
2024-09-19T05:05:01Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] skip after nomination, probably started by another node
2024-09-19T05:05:01Z D [rs1/rs104:27017] [backup/2024-09-19T05:05:00Z] skip after nomination, probably started by another node
2024-09-19T05:05:02Z D [rs1/rs102:27017] [backup/2024-09-19T05:05:00Z] skip after nomination, probably started by another node
2024-09-19T05:05:02Z D [rs1/rs103:27017] [backup/2024-09-19T05:05:00Z] backup cursor id: eab8c2b7-5670-46fe-8140-c033911729fa
2024-09-19T05:05:05Z D [rs1/rs103:27017] [backup/2024-09-19T05:05:00Z] set journal up to {1726722302 2}
2024-09-19T05:05:06Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] bcp nomination: rs1 won by rs103:27017
Raw output 
start_cluster = True, cluster = <cluster.Cluster object at 0x7f12ccfb3290>

    @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 0x7f12ccfb3290>

    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': '66ebb0fc21b5158f3a17349b', 'name': '2024-09-19T05:05:00Z', 'startTS': 1726722301, 'status': 'copyDone'}
E               2024-09-19T05:04:38Z I [rs1/rs103:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
E               GitBranch: dev
E               BuildTime: 2024-09-19_05:03_UTC
E               GoVersion: go1.23.1
E               2024-09-19T05:04:38Z I [rs1/rs102:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
E               GitBranch: dev
E               BuildTime: 2024-09-19_05:03_UTC
E               GoVersion: go1.23.1
E               2024-09-19T05:04:38Z I [rs1/rs102:27017] starting PITR routine
E               2024-09-19T05:04:38Z I [rs1/rs103:27017] starting PITR routine
E               2024-09-19T05:04:38Z I [rs1/rs101:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
E               GitBranch: dev
E               BuildTime: 2024-09-19_05:03_UTC
E               GoVersion: go1.23.1
E               2024-09-19T05:04:38Z I [rs1/rs101:27017] starting PITR routine
E               2024-09-19T05:04:38Z I [rs1/rs102:27017] node: rs1/rs102:27017
E               2024-09-19T05:04:38Z I [rs1/rs101:27017] node: rs1/rs101:27017
E               2024-09-19T05:04:38Z I [rs1/rs103:27017] node: rs1/rs103:27017
E               2024-09-19T05:04:38Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T05:04:38Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T05:04:38Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T05:04:38Z I [rs1/rs103:27017] listening for the commands
E               2024-09-19T05:04:38Z I [rs1/rs102:27017] listening for the commands
E               2024-09-19T05:04:38Z I [rs1/rs101:27017] listening for the commands
E               2024-09-19T05:04:40Z I [rs1/rs104:27017] pbm-agent:
E               Version:   2.6.0
E               Platform:  linux/amd64
E               GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
E               GitBranch: dev
E               BuildTime: 2024-09-19_05:03_UTC
E               GoVersion: go1.23.1
E               2024-09-19T05:04:40Z I [rs1/rs104:27017] node: rs1/rs104:27017
E               2024-09-19T05:04:40Z I [rs1/rs104:27017] conn level ReadConcern: majority; WriteConcern: majority
E               2024-09-19T05:04:40Z I [rs1/rs104:27017] listening for the commands
E               2024-09-19T05:04:43Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T05:04:43Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T05:04:43Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T05:04:43Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T05:04:43Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T05:04:43Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T05:04:45Z W [rs1/rs104:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E               2024-09-19T05:04:45Z E [rs1/rs104:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T05:04:48Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T05:04:48Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T05:04:48Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E               2024-09-19T05:04:50Z W [rs1/rs104:27017] [agentCheckup] storage is not initialized
E               2024-09-19T05:04:50Z I [rs1/rs104:27017] got command resync <ts: 1726722290>
E               2024-09-19T05:04:50Z I [rs1/rs104:27017] got epoch {1726722288 6}
E               2024-09-19T05:04:50Z I [rs1/rs104:27017] [resync] started
E               2024-09-19T05:04:50Z D [rs1/rs104:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E               2024-09-19T05:04:50Z D [rs1/rs104:27017] [resync] got backups list: 0
E               2024-09-19T05:04:50Z D [rs1/rs104:27017] [resync] got physical restores list: 0
E               2024-09-19T05:04:50Z D [rs1/rs104:27017] [resync] epoch set to {1726722290 13}
E               2024-09-19T05:04:50Z I [rs1/rs104:27017] [resync] succeed
E               2024-09-19T05:04:51Z I [rs1/rs103:27017] got command resync <ts: 1726722290>
E               2024-09-19T05:04:51Z I [rs1/rs102:27017] got command resync <ts: 1726722290>
E               2024-09-19T05:04:51Z I [rs1/rs101:27017] got command resync <ts: 1726722290>
E               2024-09-19T05:04:51Z I [rs1/rs103:27017] got epoch {1726722290 13}
E               2024-09-19T05:04:51Z I [rs1/rs102:27017] got epoch {1726722290 13}
E               2024-09-19T05:04:51Z I [rs1/rs101:27017] got epoch {1726722290 13}
E               2024-09-19T05:04:51Z D [rs1/rs102:27017] [resync] lock not acquired
E               2024-09-19T05:04:51Z D [rs1/rs101:27017] [resync] lock not acquired
E               2024-09-19T05:04:51Z D [rs1/rs103:27017] [resync] get lock: duplicate operation: 66ebb0f20ade0ead2097d9f5 [Resync storage]
E               2024-09-19T05:04:51Z D [rs1/rs103:27017] [resync] lock not acquired
E               2024-09-19T05:05:00Z I [rs1/rs104:27017] got command backup [name: 2024-09-19T05:05:00Z, compression: s2 (level: default)] <ts: 1726722300>
E               2024-09-19T05:05:00Z I [rs1/rs104:27017] got epoch {1726722290 13}
E               2024-09-19T05:05:01Z I [rs1/rs102:27017] got command backup [name: 2024-09-19T05:05:00Z, compression: s2 (level: default)] <ts: 1726722300>
E               2024-09-19T05:05:01Z I [rs1/rs103:27017] got command backup [name: 2024-09-19T05:05:00Z, compression: s2 (level: default)] <ts: 1726722300>
E               2024-09-19T05:05:01Z I [rs1/rs101:27017] got command backup [name: 2024-09-19T05:05:00Z, compression: s2 (level: default)] <ts: 1726722300>
E               2024-09-19T05:05:01Z I [rs1/rs102:27017] got epoch {1726722290 13}
E               2024-09-19T05:05:01Z I [rs1/rs103:27017] got epoch {1726722290 13}
E               2024-09-19T05:05:01Z I [rs1/rs101:27017] got epoch {1726722290 13}
E               2024-09-19T05:05:01Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] init backup meta
E               2024-09-19T05:05:01Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] nomination list for rs1: [[rs103:27017] [rs102:27017] [rs101:27017]]
E               2024-09-19T05:05:01Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] nomination rs1, set candidates [rs103:27017]
E               2024-09-19T05:05:01Z I [rs1/rs103:27017] [backup/2024-09-19T05:05:00Z] backup started
E               2024-09-19T05:05:01Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] skip after nomination, probably started by another node
E               2024-09-19T05:05:01Z D [rs1/rs104:27017] [backup/2024-09-19T05:05:00Z] skip after nomination, probably started by another node
E               2024-09-19T05:05:02Z D [rs1/rs102:27017] [backup/2024-09-19T05:05:00Z] skip after nomination, probably started by another node
E               2024-09-19T05:05:02Z D [rs1/rs103:27017] [backup/2024-09-19T05:05:00Z] backup cursor id: eab8c2b7-5670-46fe-8140-c033911729fa
E               2024-09-19T05:05:05Z D [rs1/rs103:27017] [backup/2024-09-19T05:05:00Z] set journal up to {1726722302 2}
E               2024-09-19T05:05:06Z D [rs1/rs101:27017] [backup/2024-09-19T05:05:00Z] bcp nomination: rs1 won by rs103:27017

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