AssertionError: Cannot start restore, another operation running: {'type': 'backup', 'opID': '66ebb5e30ec430788bc60d3b', 'name': '2024-09-19T05:25:55Z', 'startTS': 1726723555, 'status': 'copyDone'} 2024-09-19T05:25:43Z 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:25:43Z 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:25:43Z I [rs1/rs103:27017] starting PITR routine 2024-09-19T05:25:43Z I [rs1/rs102:27017] starting PITR routine 2024-09-19T05:25:43Z 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:25:43Z I [rs1/rs101:27017] starting PITR routine 2024-09-19T05:25:43Z I [rs1/rs103:27017] node: rs1/rs103:27017 2024-09-19T05:25:43Z I [rs1/rs101:27017] node: rs1/rs101:27017 2024-09-19T05:25:43Z I [rs1/rs102:27017] node: rs1/rs102:27017 2024-09-19T05:25:43Z I [rs1/rs103:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-19T05:25:43Z I [rs1/rs101:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-19T05:25:43Z I [rs1/rs102:27017] conn level ReadConcern: majority; WriteConcern: majority 2024-09-19T05:25:43Z I [rs1/rs103:27017] listening for the commands 2024-09-19T05:25:43Z I [rs1/rs101:27017] listening for the commands 2024-09-19T05:25:43Z I [rs1/rs102:27017] listening for the commands 2024-09-19T05:25:48Z W [rs1/rs103:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-19T05:25:48Z W [rs1/rs101:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-19T05:25:48Z W [rs1/rs102:27017] [agentCheckup] get current storage status: query mongo: mongo: no documents in result 2024-09-19T05:25:48Z E [rs1/rs103:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-19T05:25:48Z E [rs1/rs101:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-19T05:25:48Z E [rs1/rs102:27017] [agentCheckup] check storage connection: unable to get storage: get config: get: mongo: no documents in result 2024-09-19T05:25:50Z I [rs1/rs103:27017] got command resync <ts: 1726723550> 2024-09-19T05:25:50Z I [rs1/rs101:27017] got command resync <ts: 1726723550> 2024-09-19T05:25:50Z I [rs1/rs102:27017] got command resync <ts: 1726723550> 2024-09-19T05:25:50Z I [rs1/rs103:27017] got epoch {1726723548 12} 2024-09-19T05:25:50Z I [rs1/rs101:27017] got epoch {1726723548 12} 2024-09-19T05:25:50Z I [rs1/rs102:27017] got epoch {1726723548 12} 2024-09-19T05:25:50Z D [rs1/rs101:27017] [resync] lock not acquired 2024-09-19T05:25:50Z D [rs1/rs102:27017] [resync] lock not acquired 2024-09-19T05:25:50Z I [rs1/rs103:27017] [resync] started 2024-09-19T05:25:50Z D [rs1/rs103:27017] [resync] uploading ".pbm.init" [size hint: 5 (5.00B); part size: 10485760 (10.00MB)] 2024-09-19T05:25:50Z D [rs1/rs103:27017] [resync] got backups list: 0 2024-09-19T05:25:51Z D [rs1/rs103:27017] [resync] got physical restores list: 3 2024-09-19T05:25:51Z D [rs1/rs103:27017] [resync] epoch set to {1726723551 5} 2024-09-19T05:25:51Z I [rs1/rs103:27017] [resync] succeed 2024-09-19T05:25:55Z I [rs1/rs103:27017] got command backup [name: 2024-09-19T05:25:55Z, compression: s2 (level: default)] <ts: 1726723555> 2024-09-19T05:25:55Z I [rs1/rs102:27017] got command backup [name: 2024-09-19T05:25:55Z, compression: s2 (level: default)] <ts: 1726723555> 2024-09-19T05:25:55Z I [rs1/rs101:27017] got command backup [name: 2024-09-19T05:25:55Z, compression: s2 (level: default)] <ts: 1726723555> 2024-09-19T05:25:55Z I [rs1/rs102:27017] got epoch {1726723551 5} 2024-09-19T05:25:55Z I [rs1/rs103:27017] got epoch {1726723551 5} 2024-09-19T05:25:55Z I [rs1/rs101:27017] got epoch {1726723551 5} 2024-09-19T05:25:55Z D [rs1/rs101:27017] [backup/2024-09-19T05:25:55Z] init backup meta 2024-09-19T05:25:55Z D [rs1/rs101:27017] [backup/2024-09-19T05:25:55Z] nomination list for rs1: [[rs103:27017 rs102:27017] [rs101:27017]] 2024-09-19T05:25:55Z D [rs1/rs101:27017] [backup/2024-09-19T05:25:55Z] nomination rs1, set candidates [rs103:27017 rs102:27017] 2024-09-19T05:25:56Z D [rs1/rs103:27017] [backup/2024-09-19T05:25:55Z] skip: lock not acquired 2024-09-19T05:25:56Z I [rs1/rs102:27017] [backup/2024-09-19T05:25:55Z] backup started 2024-09-19T05:25:56Z D [rs1/rs101:27017] [backup/2024-09-19T05:25:55Z] skip after nomination, probably started by another node 2024-09-19T05:25:57Z D [rs1/rs102:27017] [backup/2024-09-19T05:25:55Z] backup cursor id: b35bf6e0-cd96-4c21-87dd-eb016ce322df 2024-09-19T05:26:00Z D [rs1/rs102:27017] [backup/2024-09-19T05:25:55Z] set journal up to {1726723557 1} 2024-09-19T05:26:00Z D [rs1/rs101:27017] [backup/2024-09-19T05:25:55Z] bcp nomination: rs1 won by rs102:27017

Process completed with exit code 1.

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

Process completed with exit code 1.

AssertionError: Starting restore 2024-09-19T05:32:03.005809078Z to point-in-time 2024-09-19T05:30:28 from '2024-09-19T05:29:05Z'...Started logical restore. Waiting to finish....Error: operation failed with: reply oplog: replay chunk 1726723749.1726723826: apply oplog for chunk: applying a transaction entry: apply txn: { "Timestamp": { "T": 1726723797, "I": 2 }, "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": "wEF/+EitTgyUeXyTcp4eyw==" } }, { "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": "wEF/+EitTgyUeXyTcp4eyw==" } }, { "Key": "o", "Value": [ { "Key": "_id", "Value": "test" }, { "Key": "primary", "Value": "rs1" }, { "Key": "partitioned", "Value": false }, { "Key": "version", "Value": [ { "Key": "uuid", "Value": { "Subtype": 4, "Data": "/ktwD2JbR0u6Shu02FZVqg==" } }, { "Key": "timestamp", "Value": { "T": 1726723796, "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": "IaXL79TtSjiYTHp0AlzKxg==" } }, { "Key": "o", "Value": [ { "Key": "_id", "Value": "66ebb6d5559087e24709aa99" }, { "Key": "nss", "Value": "test" }, { "Key": "timestamp", "Value": { "T": 1726723796, "I": 15 } }, { "Key": "shards", "Value": [ "rs1" ] } ] }, { "Key": "o2", "Value": [ { "Key": "_id", "Value": "66ebb6d5559087e24709aa99" } ] } ] ] } ], "Query": null, "UI": null, "LSID": "ZgAAAAVpZAAQAAAABMPFeVqXhU8AqoTrbMb0N1sFdWlkACAAAAAAY5mrDaxi8gv8RmdTsQ+1j7fmkr7JUsabhNmXAheU0fgFdHhuVVVJRAAQAAAABObq+jVaakmxkdA+d35pDjcA", "TxnNumber": 0, "PrevOpTime": "HAAAABF0cwAAAAAAAAAAABJ0AP//////////AA==", "MultiOpType": null }: applying transaction op: op: {"Timestamp":{"T":1726723797,"I":2},"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":"/ktwD2JbR0u6Shu02FZVqg=="}},{"Key":"timestamp","Value":{"T":1726723796,"I":15}},{"Key":"lastMod","Value":1}]}],"Query":[{"Key":"_id","Value":"test"}],"UI":{"Subtype":4,"Data":"wEF/+EitTgyUeXyTcp4eyw=="},"LSID":null,"TxnNumber":null,"PrevOpTime":null,"MultiOpType":null} | merr <nil>: applyOps: (UnknownError) applyOps had one or more errors applying ops

Process completed with exit code 1.

AssertionError: Starting restore 2024-09-19T05:32:13.858670431Z to point-in-time 2024-09-19T05:30:43 from '2024-09-19T05:29:19Z'...Started logical restore. Waiting to finish....Error: operation failed with: reply oplog: replay chunk 1726723763.1726723841: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1726723811,"I":17},"Term":1,"Hash":null,"Version":2,"Operation":"i","Namespace":"config.databases","Object":[{"Key":"_id","Value":"test"},{"Key":"primary","Value":"rs1"},{"Key":"partitioned","Value":true},{"Key":"version","Value":[{"Key":"uuid","Value":{"Subtype":4,"Data":"tWcWoS2IR5qywLjrdAbkog=="}},{"Key":"timestamp","Value":{"T":1726723811,"I":15}},{"Key":"lastMod","Value":1}]}],"Query":null,"UI":{"Subtype":4,"Data":"w9x6Gm03RomEDyGbKqhR3w=="},"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(1726723811, 17), t: 1, v: 2, op: "i", ns: "config.databases", o: { _id: "test", primary: "rs1", partitioned: true, version: { uuid: UUID("b56716a1-2d88-479a-b2c0-b8eb7406e4a2"), timestamp: Timestamp(1726723811, 15), lastMod: 1 } }, ui: UUID("c3dc7a1a-6d37-4689-840f-219b2aa851df") }

Process completed with exit code 1.

AssertionError: Starting restore 2024-09-19T05:32:30.21487378Z to point-in-time 2024-09-19T05:30:52 from '2024-09-19T05:29:29Z'...Started logical restore. Waiting to finish....Error: operation failed with: reply oplog: replay chunk 1726723772.1726723850: apply oplog for chunk: applying an entry: op: {"Timestamp":{"T":1726723821,"I":2},"Term":1,"Hash":null,"Version":2,"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":"nijjICD8SxOkG0Ki2I8ZYg=="}},{"Key":"timestamp","Value":{"T":1726723820,"I":15}},{"Key":"lastMod","Value":1}]}],"Query":[{"Key":"_id","Value":"test"}],"UI":{"Subtype":4,"Data":"oA2wK/cwRbOz75BYoiOuaw=="},"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(1726723821, 2), t: 1, v: 2, op: "i", ns: "config.databases", o: { _id: "test", primary: "rs1", partitioned: false, version: { uuid: UUID("9e28e320-20fc-4b13-a41b-42a2d88f1962"), timestamp: Timestamp(1726723820, 15), lastMod: 1 } }, o2: { _id: "test" }, ui: UUID("a00db02b-f730-45b3-b3ef-9058a223ae6b") }