Skip to content

PBM-1297 re-enable the test #168

PBM-1297 re-enable the test

PBM-1297 re-enable the test #168

Triggered via pull request September 18, 2024 06:50
Status Failure
Total duration 1h 32m 46s
Artifacts

PBM-FULL.yml

on: pull_request
Matrix: test
Fit to window
Zoom out
Zoom in

Annotations

11 errors
test_PBM-1297.test_logical_pitr_PBM_T253: pbm-functional/pytest/test_PBM-1297.py#L86
AssertionError: Starting restore 2024-09-18T07:20:36.590279187Z to point-in-time 2024-09-18T07:19:02 from '2024-09-18T07:17:39Z'...Started logical restore. Waiting to finish...Error: operation failed with: reply oplog: replay chunk 1726643862.1726643940: apply oplog for chunk: applying a transaction entry: apply txn: { "Timestamp": { "T": 1726643910, "I": 17 }, "Term": 1, "Hash": null, "Version": 2, "Operation": "c", "Namespace": "admin.$cmd", "Object": [ { "Key": "applyOps", "Value": [ [ { "Key": "op", "Value": "c" }, { "Key": "ns", "Value": "config.$cmd" }, { "Key": "ui", "Value": { "Subtype": 4, "Data": "jeKyRlc1RCaHnUSqd6SBUQ==" } }, { "Key": "o", "Value": [ { "Key": "create", "Value": "databases" }, { "Key": "idIndex", "Value": [ { "Key": "v", "Value": 2 }, { "Key": "key", "Value": [ { "Key": "_id", "Value": 1 } ] }, { "Key": "name", "Value": "_id_" } ] } ] } ], [ { "Key": "op", "Value": "i" }, { "Key": "ns", "Value": "config.databases" }, { "Key": "ui", "Value": { "Subtype": 4, "Data": "jeKyRlc1RCaHnUSqd6SBUQ==" } }, { "Key": "o", "Value": [ { "Key": "_id", "Value": "test" }, { "Key": "primary", "Value": "rs1" }, { "Key": "partitioned", "Value": false }, { "Key": "version", "Value": [ { "Key": "uuid", "Value": { "Subtype": 4, "Data": "4VgubaQlTwaMTwyX/+iq7w==" } }, { "Key": "timestamp", "Value": { "T": 1726643910, "I": 15 } }, { "Key": "lastMod", "Value": 1 } ] } ] }, { "Key": "o2", "Value": [ { "Key": "_id", "Value": "test" } ] } ], [ { "Key": "op", "Value": "i" }, { "Key": "ns", "Value": "config.placementHistory" }, { "Key": "ui", "Value": { "Subtype": 4, "Data": "mgcohM5dQomoqaIytF72tw==" } }, { "Key": "o", "Value": [ { "Key": "_id", "Value": "66ea7ec6868555e615df2594" }, { "Key": "nss", "Value": "test" }, { "Key": "timestamp", "Value": { "T": 1726643910, "I": 15 } }, { "Key": "shards", "Value": [ "rs1" ] } ] }, { "Key": "o2", "Value": [ { "Key": "_id", "Value": "66ea7ec6868555e615df2594" } ] } ] ] } ], "Query": null, "UI": null, "LSID": "ZgAAAAVpZAAQAAAABFWX/jd4uUGMoepLZLjgPPMFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgFdHhuVVVJRAAQAAAABLJgUEQEwUO7p8zQ37w0UpgA", "TxnNumber": 0, "PrevOpTime": "HAAAABF0cwAAAAAAAAAAABJ0AP//////////AA==", "MultiOpType": null }: applying transaction op: op: {"Timestamp":{"T":1726643910,"I":17},"Term":1,"Hash":null,"Version":0,"Operation":"i","Namespace":"config.databases","Object":[{"Key":"_id","Value":"test"},{"Key":"primary","Value":"rs1"},{"Key":"partitioned","Value":false},{"Key":"version","Value":[{"Key":"uuid","Value":{"Subtype":4,"Data":"4VgubaQlTwaMTwyX/+iq7w=="}},{"Key":"timestamp","Value":{"T":1726643910,"I":15}},{"Key":"lastMod","Value":1}]}],"Query":[{"Key":"_id","Value":"test"}],"UI":{"Subtype":4,"Data":"jeKyRlc1RCaHnUSqd6SBUQ=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (UnknownError) applyOps had one or more errors applying ops
test_replicaset.test_logical_timeseries_PBM_T224: pbm-functional/pytest/test_replicaset.py#L110
AssertionError: Starting restore 2024-09-18T07:49:01.147420247Z to point-in-time 2024-09-18T07:48:30 from '2024-09-18T07:47:19Z'...Started logical restore. Waiting to finish....Error: operation failed with: reply oplog: replay chunk 1726645703.1726645733: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1726645704,"I":3},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"test.system.views","Object":[{"Key":"_id","Value":"test.test2"},{"Key":"viewOn","Value":"system.buckets.test2"},{"Key":"pipeline","Value":[[{"Key":"$_internalUnpackBucket","Value":[{"Key":"timeField","Value":"timestamp"},{"Key":"metaField","Value":"data"},{"Key":"bucketMaxSpanSeconds","Value":3600}]}]]}],"Query":[{"Key":"_id","Value":"test.test2"}],"UI":{"Subtype":4,"Data":"xMuHWwa/SAGHjlcpVXPRaQ=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (UnknownError) applyOps had one or more errors applying ops
test (7.0, logical)
Process completed with exit code 1.
test_PBM-1297.test_logical_pitr_PBM_T253: pbm-functional/pytest/test_PBM-1297.py#L86
AssertionError: Starting restore 2024-09-18T07:20:59.32762455Z to point-in-time 2024-09-18T07:19:25 from '2024-09-18T07:18:02Z'...Started logical restore. Waiting to finish...Error: operation failed with: reply oplog: replay chunk 1726643886.1726643963: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1726643933,"I":18},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"config.databases","Object":[{"Key":"_id","Value":"test"},{"Key":"primary","Value":"rs2"},{"Key":"partitioned","Value":true},{"Key":"version","Value":[{"Key":"uuid","Value":{"Subtype":4,"Data":"D2vDP84lRjKwepSxAuPPOg=="}},{"Key":"timestamp","Value":{"T":1726643933,"I":16}},{"Key":"lastMod","Value":1}]}],"Query":null,"UI":{"Subtype":4,"Data":"IjC/7yERRkq/zPnYK7PMQQ=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (NamespaceNotFound) cannot apply insert or update operation on a non-existent namespace config.databases: { ts: Timestamp(1726643933, 18), t: 1, v: 2, op: "i", ns: "config.databases", o: { _id: "test", primary: "rs2", partitioned: true, version: { uuid: UUID("0f6bc33f-ce25-4632-b07a-94b102e3cf3a"), timestamp: Timestamp(1726643933, 16), lastMod: 1 } }, ui: UUID("2230bfef-2111-464a-bfcc-f9d82bb3cc41") }
test_replicaset.test_logical_timeseries_PBM_T224: pbm-functional/pytest/test_replicaset.py#L110
AssertionError: Starting restore 2024-09-18T07:49:56.878759423Z to point-in-time 2024-09-18T07:49:26 from '2024-09-18T07:48:14Z'...Started logical restore. Waiting to finish...Error: operation failed with: reply oplog: replay chunk 1726645759.1726645789: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1726645760,"I":2},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"test.system.views","Object":[{"Key":"_id","Value":"test.test2"},{"Key":"viewOn","Value":"system.buckets.test2"},{"Key":"pipeline","Value":[[{"Key":"$_internalUnpackBucket","Value":[{"Key":"timeField","Value":"timestamp"},{"Key":"metaField","Value":"data"},{"Key":"bucketMaxSpanSeconds","Value":3600},{"Key":"exclude","Value":[]}]}]]}],"Query":null,"UI":{"Subtype":4,"Data":"9R22xpviSk22JfuNmJw4kw=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (NamespaceNotFound) Failed to apply operation due to missing collection (f51db6c6-9be2-4a4d-b625-fb8d989c3893): { ts: Timestamp(1726645760, 2), t: 1, v: 2, op: "i", ns: "test.system.views", o: { _id: "test.test2", viewOn: "system.buckets.test2", pipeline: [ { $_internalUnpackBucket: { timeField: "timestamp", metaField: "data", bucketMaxSpanSeconds: 3600, exclude: [] } } ] }, ui: UUID("f51db6c6-9be2-4a4d-b625-fb8d989c3893"), h: 0, wall: new Date(0) }
test (5.0, logical)
Process completed with exit code 1.
test_PBM-1297.test_logical_pitr_PBM_T253: pbm-functional/pytest/test_PBM-1297.py#L86
AssertionError: Starting restore 2024-09-18T07:21:17.969503978Z to point-in-time 2024-09-18T07:19:42 from '2024-09-18T07:18:19Z'....Started logical restore. Waiting to finish...Error: operation failed with: reply oplog: replay chunk 1726643903.1726643981: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1726643951,"I":17},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"config.databases","Object":[{"Key":"_id","Value":"test"},{"Key":"primary","Value":"rs2"},{"Key":"partitioned","Value":false},{"Key":"version","Value":[{"Key":"uuid","Value":{"Subtype":4,"Data":"S/ZxH+7BRRmY+Tt7skQ3Gg=="}},{"Key":"timestamp","Value":{"T":1726643951,"I":15}},{"Key":"lastMod","Value":1}]}],"Query":[{"Key":"_id","Value":"test"}],"UI":{"Subtype":4,"Data":"1EkyHPXaT4ipjVGSZjAWUg=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (NamespaceNotFound) cannot apply insert or update operation on a non-existent namespace config.databases: { ts: Timestamp(1726643951, 17), t: 1, v: 2, op: "i", ns: "config.databases", o: { _id: "test", primary: "rs2", partitioned: false, version: { uuid: UUID("4bf6711f-eec1-4519-98f9-3b7bb244371a"), timestamp: Timestamp(1726643951, 15), lastMod: 1 } }, o2: { _id: "test" }, ui: UUID("d449321c-f5da-4f88-a98d-519266301652") }
test_PBM-773.test_logical_PBM_T221: pbm-functional/pytest/test_PBM-773.py#L102
UnboundLocalError: cannot access local variable 'index' where it is not associated with a value
test_azurite.test_logical: pbm-functional/pytest/test_azurite.py#L69
AssertionError: Backup failed{"Error":"get backup metadata: get: context deadline exceeded"} 2024-09-18T07:30:48Z I [rs2/rs201:27017] pbm-agent: Version: 2.6.0 Platform: linux/amd64 GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47 GitBranch: dev BuildTime: 2024-09-18_06:52_UTC GoVersion: go1.23.1 2024-09-18T07:30:48Z I [rs1/rs102:27017] pbm-agent: Version: 2.6.0 Platform: linux/amd64 GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47 GitBranch: dev BuildTime: 2024-09-18_06:52_UTC GoVersion: go1.23.1 2024-09-18T07:30:48Z I [rs2/rs201:27017] starting PITR routine 2024-09-18T07:30:48Z I [rs1/rs102:27017] starting PITR routine 2024-09-18T07:30:48Z I [rs1/rs101:27017] starting PITR routine 2024-09-18T07:30:48Z I [rs1/rs101:27017] pbm-agent: Version: 2.6.0 Platform: linux/amd64 GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47 GitBranch: dev BuildTime: 2024-09-18_06:52_UTC GoVersion: go1.23.1 2024-09-18T07:30:48Z I [rs1/rs103:27017] pbm-agent: Version: 2.6.0 Platform: linux/amd64 GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47 GitBranch: dev BuildTime: 2024-09-18_06:52_UTC GoVersion: go1.23.1 2024-09-18T07:30:48Z I [rs1/rs103:27017] starting PITR routine 2024-09-18T07:30:48Z I [rs1/rs102:27017] node: rs1/rs102:27017 2024-09-18T07:30:48Z I [rs1/rs101:27017] node: rs1/rs101:27017 2024-09-18T07:30:48Z I [rs2/rs201:27017] node: rs2/rs201:27017 2024-09-18T07:30:48Z I [rs1/rs103:27017] node: rs1/rs103:27017 2024-09-18T07:30:48Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-18T07:30:48Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-18T07:30:48Z I [rs2/rs201:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-18T07:30:48Z I [rs1/rs102:27017] listening for the commands 2024-09-18T07:30:48Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-18T07:30:48Z I [rs2/rs201:27017] listening for the commands 2024-09-18T07:30:48Z I [rs1/rs101:27017] listening for the commands 2024-09-18T07:30:48Z I [rs1/rs103:27017] listening for the commands 2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] pbm-agent: Version: 2.6.0 Platform: linux/amd64 GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47 GitBranch: dev BuildTime: 2024-09-18_06:52_UTC GoVersion: go1.23.1 2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] starting PITR routine 2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] node: rscfg/rscfg01:27017 2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-18T07:30:50Z I [rscfg/rscfg01:27017] listening for the commands 2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] pbm-agent: Version: 2.6.0 Platform: linux/amd64 GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47 GitBranch: dev BuildTime: 2024-09-18_06:52_UTC GoVersion: go1.23.1 2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] starting PITR routine 2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] node: rscfg/rscfg02:27017 2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-18T07:30:50Z I [rs2/rs203:27017] pbm-agent: Version: 2.6.0 Platform: linux/amd64 GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47 GitBranch: dev BuildTime: 2024-09-18_06:52_UTC GoVersion: go1.23.1 2024-09-18T07:30:50Z I [rs2/rs203:27017] starting PITR routine 2024-09-18T07:30:50Z I [rscfg/rscfg02:27017] listening for the commands 2024-09-18T07:30:50Z I [rs2/rs203:27017] node: rs2/rs203:27017 2024-09-18T07:30:50Z I [rs2/rs203:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-18T07:30:50Z I [rs2/rs203:27017] listening for the commands 2024-09-18T07:30:50Z I [rs2/rs202:27017] pbm-agent: Version: 2.6.0 Platform: linux/amd64 GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47 GitBranch: dev BuildTime: 2024-09-18_06:52_UTC GoVersion: go1.23.1 2024-09-18T07:30:50Z I [rs2/rs202:27017] starting PITR routine 2024-09-18T07:30:50Z I [rs2/rs202:27017] node: rs2/rs202:27017 2024-09-18T07:30:50Z I [rs2/rs202:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-18T07:30:50Z I [rs2/rs202:27017] listening for the commands 2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] pbm-agent: Version: 2.6.0 Platform: linux/amd64 GitCommit: d7bf446a6a1d772f92a3990a23932932abb8dc47 GitBranch: dev BuildTime: 2024-09-18_06:52_UTC GoVersion: go1.23.1 2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] starting PITR routine 2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] node: rscfg/rscfg03:27017 2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-18T07:30:51Z I [rscfg/rscfg03:27017] listening for the commands 2024-09-18T07:30:53Z W [rs2/rs201:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-18T07:30:53Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-18T07:30:53Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-18T07:30:53Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-18T07:30:53Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-18T07:30:53Z E [rs2/rs201:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-18T07:30:53Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-18T07:30:53Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-18T07:30:55Z W [rscfg/rscfg01:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-18T07:30:55Z E [rscfg/rscfg01:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-18T07:30:55Z W [rscfg/rscfg02:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-18T07:30:55Z E [rscfg/rscfg02:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-18T07:30:55Z W [rs2/rs203:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-18T07:30:55Z E [rs2/rs203:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-18T07:30:55Z W [rs2/rs202:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-18T07:30:55Z E [rs2/rs202:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-18T07:30:56Z W [rscfg/rscfg03:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-18T07:30:56Z E [rscfg/rscfg03:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-18T07:30:58Z I [rscfg/rscfg01:27017] got command resync <ts: 1726644657> 2024-09-18T07:30:58Z I [rscfg/rscfg01:27017] got epoch {1726644656 3} 2024-09-18T07:30:58Z I [rscfg/rscfg02:27017] got command resync <ts: 1726644657> 2024-09-18T07:30:58Z I [rscfg/rscfg01:27017] [resync] started 2024-09-18T07:30:58Z I [rscfg/rscfg02:27017] got epoch {1726644656 3} 2024-09-18T07:30:58Z I [rs2/rs203:27017] got command resync <ts: 1726644657> 2024-09-18T07:30:58Z I [rs2/rs203:27017] got epoch {1726644656 3} 2024-09-18T07:30:58Z D [rscfg/rscfg02:27017] [resync] lock not acquired 2024-09-18T07:30:58Z I [rs2/rs203:27017] [resync] not a member of the leader rs 2024-09-18T07:30:58Z D [rscfg/rscfg01:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)] 2024-09-18T07:30:58Z I [rs2/rs202:27017] got command resync <ts: 1726644657> 2024-09-18T07:30:58Z I [rs2/rs202:27017] got epoch {1726644656 3} 2024-09-18T07:30:58Z I [rs2/rs202:27017] [resync] not a member of the leader rs 2024-09-18T07:30:58Z D [rscfg/rscfg01:27017] [resync] got backups list: 0 2024-09-18T07:30:58Z D [rscfg/rscfg01:27017] [resync] got physical restores list: 0 2024-09-18T07:30:58Z D [rscfg/rscfg01:27017] [resync] epoch set to {1726644658 18} 2024-09-18T07:30:58Z I [rscfg/rscfg01:27017] [resync] succeed 2024-09-18T07:30:58Z I [rs1/rs101:27017] got command resync <ts: 1726644657> 2024-09-18T07:30:58Z I [rs2/rs201:27017] got command resync <ts: 1726644657> 2024-09-18T07:30:58Z I [rs1/rs102:27017] got command resync <ts: 1726644657> 2024-09-18T07:30:58Z I [rs1/rs103:27017] got command resync <ts: 1726644657> 2024-09-18T07:30:58Z I [rs1/rs101:27017] got epoch {1726644658 18} 2024-09-18T07:30:58Z I [rs1/rs102:27017] got epoch {1726644658 18} 2024-09-18T07:30:58Z I [rs2/rs201:27017] got epoch {1726644658 18} 2024-09-18T07:30:58Z I [rs1/rs101:27017] [resync] not a member of the leader rs 2024-09-18T07:30:58Z I [rs1/rs102:27017] [resync] not a member of the leader rs 2024-09-18T07:30:58Z I [rs1/rs103:27017] got epoch {1726644658 18} 2024-09-18T07:30:58Z I [rs2/rs201:27017] [resync] not a member of the leader rs 2024-09-18T07:30:58Z I [rs1/rs103:27017] [resync] not a member of the leader rs 2024-09-18T07:30:58Z I [rscfg/rscfg03:27017] got command resync <ts: 1726644657> 2024-09-18T07:30:58Z I [rscfg/rscfg03:27017] got epoch {1726644658 18} 2024-09-18T07:30:58Z D [rscfg/rscfg03:27017] [resync] get lock: duplicate operation: 66ea81b15d7ce290e76422b1 [Resync storage] 2024-09-18T07:30:58Z D [rscfg/rscfg03:27017] [resync] lock not acquired 2024-09-18T07:31:03Z I [rs2/rs201:27017] got command resync <ts: 1726644663> 2024-09-18T07:31:03Z I [rs1/rs101:27017] got command resync <ts: 1726644663> 2024-09-18T07:31:03Z I [rs1/rs103:27017] got command resync <ts: 1726644663> 2024-09-18T07:31:03Z I [rs1/rs102:27017] got command resync <ts: 1726644663> 2024-09-18T07:31:03Z I [rs2/rs201:27017] got epoch {1726644658 18} 2024-09-18T07:31:03Z I [rs1/rs103:27017] got epoch {1726644658 18} 2024-09-18T07:31:03Z I [rs1/rs101:27017] got epoch {1726644658 18} 2024-09-18T07:31:03Z I [rs1/rs103:27017] [resync] not a member of the leader rs 2024-09-18T07:31:03Z I [rs2/rs201:27017] [resync] not a member of the leader rs 2024-09-18T07:31:03Z I [rs1/rs102:27017] got epoch {1726644658 18} 2024-09-18T07:31:03Z I [rs1/rs102:27017] [resync] not a member of the leader rs 2024-09-18T07:31:03Z I [rs1/rs101:27017] [resync] not a member of the leader rs 2024-09-18T07:31:03Z I [rscfg/rscfg03:27017] got command resync <ts: 1726644663> 2024-09-18T07:31:03Z I [rscfg/rscfg03:27017] got epoch {1726644658 18} 2024-09-18T07:31:03Z I [rscfg/rscfg03:27017] [resync] started 2024-09-18T07:31:03Z D [rscfg/rscfg03:27017] [resync] BufferSize is set to 10485760 (~10Mb) | 5 2024-09-18T07:31:03Z D [rscfg/rscfg03:27017] [resync] got backups list: 0 2024-09-18T07:31:03Z D [rscfg/rscfg03:27017] [resync] got physical restores list: 0 2024-09-18T07:31:03Z D [rscfg/rscfg03:27017] [resync] epoch set to {1726644663 154} 2024-09-18T07:31:03Z I [rscfg/rscfg03:27017] [resync] succeed 2024-09-18T07:31:04Z I [rscfg/rscfg01:27017] got command resync <ts: 1726644663> 2024-09-18T07:31:04Z I [rscfg/rscfg01:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rscfg/rscfg02:27017] got command resync <ts: 1726644663> 2024-09-18T07:31:04Z D [rscfg/rscfg01:27017] [resync] get lock: duplicate operation: 66ea81b7f3c13e681043f6a6 [Resync storage] 2024-09-18T07:31:04Z D [rscfg/rscfg01:27017] [resync] lock not acquired 2024-09-18T07:31:04Z I [rscfg/rscfg02:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rscfg/rscfg01:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664> 2024-09-18T07:31:04Z I [rs2/rs203:27017] got command resync <ts: 1726644663> 2024-09-18T07:31:04Z I [rscfg/rscfg01:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rs2/rs203:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rs2/rs203:27017] [resync] not a member of the leader rs 2024-09-18T07:31:04Z E [rscfg/rscfg01:27017] [backup/2024-09-18T07:31:04Z] unable to proceed with the backup, active lock is present 2024-09-18T07:31:04Z D [rscfg/rscfg02:27017] [resync] get lock: duplicate operation: 66ea81b7f3c13e681043f6a6 [Resync storage] 2024-09-18T07:31:04Z I [rs2/rs203:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664> 2024-09-18T07:31:04Z I [rs2/rs202:27017] got command resync <ts: 1726644663> 2024-09-18T07:31:04Z D [rscfg/rscfg02:27017] [resync] lock not acquired 2024-09-18T07:31:04Z I [rs2/rs202:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rs2/rs203:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rscfg/rscfg02:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664> 2024-09-18T07:31:04Z I [rs2/rs202:27017] [resync] not a member of the leader rs 2024-09-18T07:31:04Z I [rscfg/rscfg02:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rs2/rs202:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664> 2024-09-18T07:31:04Z I [rs2/rs202:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rs1/rs101:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664> 2024-09-18T07:31:04Z I [rs2/rs201:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664> 2024-09-18T07:31:04Z I [rs1/rs103:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664> 2024-09-18T07:31:04Z I [rs1/rs102:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664> 2024-09-18T07:31:04Z I [rs2/rs201:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rs1/rs101:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rs1/rs103:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rs1/rs102:27017] got epoch {1726644663 154} 2024-09-18T07:31:04Z I [rscfg/rscfg03:27017] got command backup [name: 2024-09-18T07:31:04Z, compression: s2 (level: default)] <ts: 1726644664> 2024-09-18T07:31:04Z I [rscfg/rscfg03:27017] got epoch {1726644663 154} 2024-09-18T07:31:19Z D [rs2/rs203:27017] [backup/2024-09-18T07:31:04Z] nomination timeout 2024-09-18T07:31:19Z D [rs2/rs203:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node 2024-09-18T07:31:19Z D [rscfg/rscfg02:27017] [backup/2024-09-18T07:31:04Z] nomination timeout 2024-09-18T07:31:19Z D [rscfg/rscfg02:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node 2024-09-18T07:31:19Z D [rs2/rs202:27017] [backup/2024-09-18T07:31:04Z] nomination timeout 2024-09-18T07:31:19Z D [rs2/rs202:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node 2024-09-18T07:31:19Z D [rs1/rs102:27017] [backup/2024-09-18T07:31:04Z] nomination timeout 2024-09-18T07:31:19Z D [rs1/rs103:27017] [backup/2024-09-18T07:31:04Z] nomination timeout 2024-09-18T07:31:19Z D [rs2/rs201:27017] [backup/2024-09-18T07:31:04Z] nomination timeout 2024-09-18T07:31:19Z D [rs1/rs101:27017] [backup/2024-09-18T07:31:04Z] nomination timeout 2024-09-18T07:31:19Z D [rs1/rs103:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node 2024-09-18T07:31:19Z D [rs1/rs101:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node 2024-09-18T07:31:19Z D [rs1/rs102:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node 2024-09-18T07:31:19Z D [rs2/rs201:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node 2024-09-18T07:31:19Z D [rscfg/rscfg03:27017] [backup/2024-09-18T07:31:04Z] nomination timeout 2024-09-18T07:31:19Z D [rscfg/rscfg03:27017] [backup/2024-09-18T07:31:04Z] skip after nomination, probably started by another node
test_replicaset.test_logical_timeseries_PBM_T224: pbm-functional/pytest/test_replicaset.py#L110
AssertionError: Starting restore 2024-09-18T07:49:41.210305672Z to point-in-time 2024-09-18T07:49:10 from '2024-09-18T07:47:59Z'...Started logical restore. Waiting to finish...Error: operation failed with: reply oplog: replay chunk 1726645744.1726645774: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1726645744,"I":6},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"test.system.views","Object":[{"Key":"_id","Value":"test.test2"},{"Key":"viewOn","Value":"system.buckets.test2"},{"Key":"pipeline","Value":[[{"Key":"$_internalUnpackBucket","Value":[{"Key":"timeField","Value":"timestamp"},{"Key":"metaField","Value":"data"},{"Key":"bucketMaxSpanSeconds","Value":3600}]}]]}],"Query":[{"Key":"_id","Value":"test.test2"}],"UI":{"Subtype":4,"Data":"cJFn/N6yTJupXu5BhbnowA=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (NamespaceNotFound) Failed to apply operation due to missing collection (709167fc-deb2-4c9b-a95e-ee4185b9e8c0): { ts: Timestamp(1726645744, 6), t: 1, v: 2, op: "i", ns: "test.system.views", o: { _id: "test.test2", viewOn: "system.buckets.test2", pipeline: [ { $_internalUnpackBucket: { timeField: "timestamp", metaField: "data", bucketMaxSpanSeconds: 3600 } } ] }, o2: { _id: "test.test2" }, ui: UUID("709167fc-deb2-4c9b-a95e-ee4185b9e8c0"), h: 0, wall: new Date(0) }
test (6.0, logical)
Process completed with exit code 1.