PBM-CUSTOM #46
GitHub Actions / JUnit Test Report
failed
Sep 18, 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
github-actions / JUnit Test Report
test_PBM-979.test_external_PBM_T240
AssertionError: Cannot start restore, another operation running: {'type': 'backup', 'opID': '66eab75b646a52ea7cf777db', 'name': '2024-09-18T11:19:55Z', 'startTS': 1726658395, 'status': 'copyDone'}
2024-09-18T11:19:33Z I [rs1/rs101:27017] pbm-agent:
Version: 2.6.0
Platform: linux/amd64
GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
GitBranch: dev
BuildTime: 2024-09-18_11:18_UTC
GoVersion: go1.23.1
2024-09-18T11:19:33Z I [rs1/rs102:27017] pbm-agent:
Version: 2.6.0
Platform: linux/amd64
GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
GitBranch: dev
BuildTime: 2024-09-18_11:18_UTC
GoVersion: go1.23.1
2024-09-18T11:19:33Z I [rs1/rs102:27017] starting PITR routine
2024-09-18T11:19:33Z I [rs1/rs101:27017] starting PITR routine
2024-09-18T11:19:33Z I [rs1/rs103:27017] pbm-agent:
Version: 2.6.0
Platform: linux/amd64
GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
GitBranch: dev
BuildTime: 2024-09-18_11:18_UTC
GoVersion: go1.23.1
2024-09-18T11:19:33Z I [rs1/rs103:27017] starting PITR routine
2024-09-18T11:19:33Z I [rs1/rs102:27017] node: rs1/rs102:27017
2024-09-18T11:19:33Z I [rs1/rs101:27017] node: rs1/rs101:27017
2024-09-18T11:19:33Z I [rs1/rs103:27017] node: rs1/rs103:27017
2024-09-18T11:19:33Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-18T11:19:33Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-18T11:19:33Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-18T11:19:33Z I [rs1/rs102:27017] listening for the commands
2024-09-18T11:19:33Z I [rs1/rs101:27017] listening for the commands
2024-09-18T11:19:33Z I [rs1/rs103:27017] listening for the commands
2024-09-18T11:19:35Z I [rs1/rs104:27017] pbm-agent:
Version: 2.6.0
Platform: linux/amd64
GitCommit: 4e467842b7e52c2892ff69bd24dac19a231db215
GitBranch: dev
BuildTime: 2024-09-18_11:18_UTC
GoVersion: go1.23.1
2024-09-18T11:19:35Z I [rs1/rs104:27017] node: rs1/rs104:27017
2024-09-18T11:19:35Z I [rs1/rs104:27017] conn level ReadConcern: majority; WriteConcern: majority
2024-09-18T11:19:35Z I [rs1/rs104:27017] listening for the commands
2024-09-18T11:19:38Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-18T11:19:38Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-18T11:19:38Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-18T11:19:38Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-18T11:19:38Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-18T11:19:38Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-18T11:19:40Z W [rs1/rs104:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
2024-09-18T11:19:40Z E [rs1/rs104:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-18T11:19:43Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-18T11:19:43Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-18T11:19:43Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
2024-09-18T11:19:45Z W [rs1/rs104:27017] [agentCheckup] storage is not initialized
2024-09-18T11:19:45Z I [rs1/rs104:27017] got command resync <ts: 1726658385>
2024-09-18T11:19:45Z I [rs1/rs104:27017] got epoch {1726658383 6}
2024-09-18T11:19:45Z I [rs1/rs104:27017] [resync] started
2024-09-18T11:19:45Z D [rs1/rs104:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
2024-09-18T11:19:45Z D [rs1/rs104:27017] [resync] got backups list: 0
2024-09-18T11:19:45Z D [rs1/rs104:27017] [resync] got physical restores list: 0
2024-09-18T11:19:45Z D [rs1/rs104:27017] [resync] epoch set to {1726658385 13}
2024-09-18T11:19:45Z I [rs1/rs104:27017] [resync] succeed
2024-09-18T11:19:45Z I [rs1/rs101:27017] got command resync <ts: 1726658385>
2024-09-18T11:19:45Z I [rs1/rs102:27017] got command resync <ts: 1726658385>
2024-09-18T11:19:45Z I [rs1/rs103:27017] got command resync <ts: 1726658385>
2024-09-18T11:19:45Z I [rs1/rs101:27017] got epoch {1726658385 13}
2024-09-18T11:19:45Z I [rs1/rs102:27017] got epoch {1726658385 13}
2024-09-18T11:19:45Z I [rs1/rs103:27017] got epoch {1726658385 13}
2024-09-18T11:19:45Z D [rs1/rs103:27017] [resync] lock not acquired
2024-09-18T11:19:45Z D [rs1/rs102:27017] [resync] lock not acquired
2024-09-18T11:19:45Z D [rs1/rs101:27017] [resync] get lock: duplicate operation: 66eab7511e1a63eb1d70a5fe [Resync storage]
2024-09-18T11:19:45Z D [rs1/rs101:27017] [resync] lock not acquired
2024-09-18T11:19:55Z I [rs1/rs104:27017] got command backup [name: 2024-09-18T11:19:55Z, compression: s2 (level: default)] <ts: 1726658395>
2024-09-18T11:19:55Z I [rs1/rs104:27017] got epoch {1726658385 13}
2024-09-18T11:19:55Z I [rs1/rs102:27017] got command backup [name: 2024-09-18T11:19:55Z, compression: s2 (level: default)] <ts: 1726658395>
2024-09-18T11:19:55Z I [rs1/rs101:27017] got command backup [name: 2024-09-18T11:19:55Z, compression: s2 (level: default)] <ts: 1726658395>
2024-09-18T11:19:55Z I [rs1/rs103:27017] got command backup [name: 2024-09-18T11:19:55Z, compression: s2 (level: default)] <ts: 1726658395>
2024-09-18T11:19:55Z I [rs1/rs101:27017] got epoch {1726658385 13}
2024-09-18T11:19:55Z I [rs1/rs102:27017] got epoch {1726658385 13}
2024-09-18T11:19:55Z I [rs1/rs103:27017] got epoch {1726658385 13}
2024-09-18T11:19:55Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] init backup meta
2024-09-18T11:19:55Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] nomination list for rs1: [[rs103:27017] [rs102:27017] [rs101:27017]]
2024-09-18T11:19:55Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] nomination rs1, set candidates [rs103:27017]
2024-09-18T11:19:56Z I [rs1/rs103:27017] [backup/2024-09-18T11:19:55Z] backup started
2024-09-18T11:19:56Z D [rs1/rs104:27017] [backup/2024-09-18T11:19:55Z] skip after nomination, probably started by another node
2024-09-18T11:19:56Z D [rs1/rs102:27017] [backup/2024-09-18T11:19:55Z] skip after nomination, probably started by another node
2024-09-18T11:19:56Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] skip after nomination, probably started by another node
2024-09-18T11:19:57Z D [rs1/rs103:27017] [backup/2024-09-18T11:19:55Z] backup cursor id: d2184388-25e4-4225-ad1c-e3bc28e315c3
2024-09-18T11:20:00Z D [rs1/rs103:27017] [backup/2024-09-18T11:19:55Z] set journal up to {1726658397 1}
2024-09-18T11:20:00Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] bcp nomination: rs1 won by rs103:27017
Raw output
start_cluster = True, cluster = <cluster.Cluster object at 0x7ff765d7ef50>
@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 0x7ff765d7ef50>
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': '66eab75b646a52ea7cf777db', 'name': '2024-09-18T11:19:55Z', 'startTS': 1726658395, 'status': 'copyDone'}
E 2024-09-18T11:19:33Z 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-18_11:18_UTC
E GoVersion: go1.23.1
E 2024-09-18T11:19:33Z 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-18_11:18_UTC
E GoVersion: go1.23.1
E 2024-09-18T11:19:33Z I [rs1/rs102:27017] starting PITR routine
E 2024-09-18T11:19:33Z I [rs1/rs101:27017] starting PITR routine
E 2024-09-18T11:19:33Z 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-18_11:18_UTC
E GoVersion: go1.23.1
E 2024-09-18T11:19:33Z I [rs1/rs103:27017] starting PITR routine
E 2024-09-18T11:19:33Z I [rs1/rs102:27017] node: rs1/rs102:27017
E 2024-09-18T11:19:33Z I [rs1/rs101:27017] node: rs1/rs101:27017
E 2024-09-18T11:19:33Z I [rs1/rs103:27017] node: rs1/rs103:27017
E 2024-09-18T11:19:33Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority
E 2024-09-18T11:19:33Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority
E 2024-09-18T11:19:33Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority
E 2024-09-18T11:19:33Z I [rs1/rs102:27017] listening for the commands
E 2024-09-18T11:19:33Z I [rs1/rs101:27017] listening for the commands
E 2024-09-18T11:19:33Z I [rs1/rs103:27017] listening for the commands
E 2024-09-18T11:19:35Z 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-18_11:18_UTC
E GoVersion: go1.23.1
E 2024-09-18T11:19:35Z I [rs1/rs104:27017] node: rs1/rs104:27017
E 2024-09-18T11:19:35Z I [rs1/rs104:27017] conn level ReadConcern: majority; WriteConcern: majority
E 2024-09-18T11:19:35Z I [rs1/rs104:27017] listening for the commands
E 2024-09-18T11:19:38Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E 2024-09-18T11:19:38Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E 2024-09-18T11:19:38Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E 2024-09-18T11:19:38Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E 2024-09-18T11:19:38Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E 2024-09-18T11:19:38Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E 2024-09-18T11:19:40Z W [rs1/rs104:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result
E 2024-09-18T11:19:40Z E [rs1/rs104:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E 2024-09-18T11:19:43Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E 2024-09-18T11:19:43Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E 2024-09-18T11:19:43Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result
E 2024-09-18T11:19:45Z W [rs1/rs104:27017] [agentCheckup] storage is not initialized
E 2024-09-18T11:19:45Z I [rs1/rs104:27017] got command resync <ts: 1726658385>
E 2024-09-18T11:19:45Z I [rs1/rs104:27017] got epoch {1726658383 6}
E 2024-09-18T11:19:45Z I [rs1/rs104:27017] [resync] started
E 2024-09-18T11:19:45Z D [rs1/rs104:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)]
E 2024-09-18T11:19:45Z D [rs1/rs104:27017] [resync] got backups list: 0
E 2024-09-18T11:19:45Z D [rs1/rs104:27017] [resync] got physical restores list: 0
E 2024-09-18T11:19:45Z D [rs1/rs104:27017] [resync] epoch set to {1726658385 13}
E 2024-09-18T11:19:45Z I [rs1/rs104:27017] [resync] succeed
E 2024-09-18T11:19:45Z I [rs1/rs101:27017] got command resync <ts: 1726658385>
E 2024-09-18T11:19:45Z I [rs1/rs102:27017] got command resync <ts: 1726658385>
E 2024-09-18T11:19:45Z I [rs1/rs103:27017] got command resync <ts: 1726658385>
E 2024-09-18T11:19:45Z I [rs1/rs101:27017] got epoch {1726658385 13}
E 2024-09-18T11:19:45Z I [rs1/rs102:27017] got epoch {1726658385 13}
E 2024-09-18T11:19:45Z I [rs1/rs103:27017] got epoch {1726658385 13}
E 2024-09-18T11:19:45Z D [rs1/rs103:27017] [resync] lock not acquired
E 2024-09-18T11:19:45Z D [rs1/rs102:27017] [resync] lock not acquired
E 2024-09-18T11:19:45Z D [rs1/rs101:27017] [resync] get lock: duplicate operation: 66eab7511e1a63eb1d70a5fe [Resync storage]
E 2024-09-18T11:19:45Z D [rs1/rs101:27017] [resync] lock not acquired
E 2024-09-18T11:19:55Z I [rs1/rs104:27017] got command backup [name: 2024-09-18T11:19:55Z, compression: s2 (level: default)] <ts: 1726658395>
E 2024-09-18T11:19:55Z I [rs1/rs104:27017] got epoch {1726658385 13}
E 2024-09-18T11:19:55Z I [rs1/rs102:27017] got command backup [name: 2024-09-18T11:19:55Z, compression: s2 (level: default)] <ts: 1726658395>
E 2024-09-18T11:19:55Z I [rs1/rs101:27017] got command backup [name: 2024-09-18T11:19:55Z, compression: s2 (level: default)] <ts: 1726658395>
E 2024-09-18T11:19:55Z I [rs1/rs103:27017] got command backup [name: 2024-09-18T11:19:55Z, compression: s2 (level: default)] <ts: 1726658395>
E 2024-09-18T11:19:55Z I [rs1/rs101:27017] got epoch {1726658385 13}
E 2024-09-18T11:19:55Z I [rs1/rs102:27017] got epoch {1726658385 13}
E 2024-09-18T11:19:55Z I [rs1/rs103:27017] got epoch {1726658385 13}
E 2024-09-18T11:19:55Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] init backup meta
E 2024-09-18T11:19:55Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] nomination list for rs1: [[rs103:27017] [rs102:27017] [rs101:27017]]
E 2024-09-18T11:19:55Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] nomination rs1, set candidates [rs103:27017]
E 2024-09-18T11:19:56Z I [rs1/rs103:27017] [backup/2024-09-18T11:19:55Z] backup started
E 2024-09-18T11:19:56Z D [rs1/rs104:27017] [backup/2024-09-18T11:19:55Z] skip after nomination, probably started by another node
E 2024-09-18T11:19:56Z D [rs1/rs102:27017] [backup/2024-09-18T11:19:55Z] skip after nomination, probably started by another node
E 2024-09-18T11:19:56Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] skip after nomination, probably started by another node
E 2024-09-18T11:19:57Z D [rs1/rs103:27017] [backup/2024-09-18T11:19:55Z] backup cursor id: d2184388-25e4-4225-ad1c-e3bc28e315c3
E 2024-09-18T11:20:00Z D [rs1/rs103:27017] [backup/2024-09-18T11:19:55Z] set journal up to {1726658397 1}
E 2024-09-18T11:20:00Z D [rs1/rs101:27017] [backup/2024-09-18T11:19:55Z] bcp nomination: rs1 won by rs103:27017
cluster.py:866: AssertionError
Loading