Checklist
- [X] This is not a security-related bug/issue. If it is, please follow please follow the security policy.
- [X] This is not a question or a support request. If you have any lotus related questions, please ask in the lotus forum.
- [X] This is not a new feature request. If it is, please file a feature request instead.
- [X] This is not an enhancement request. If it is, please file a improvement suggestion instead.
- [X] I have searched on the issue tracker and the lotus forum, and there is no existing related issue or discussion.
- [X] I am running the
Latest release
, or the most recent RC(release canadiate) for the upcoming release or the dev branch(master), or have an issue updating to any of these.
- [ ] I did not make any code changes to lotus.
Lotus component
- [ ] lotus daemon - chain sync
- [ ] lotus miner - mining and block production
- [X] lotus miner/worker - sealing
- [ ] lotus miner - proving(WindowPoSt)
- [ ] lotus miner/market - storage deal
- [ ] lotus miner/market - retrieval deal
- [ ] lotus miner/market - data transfer
- [ ] lotus client
- [ ] lotus JSON-RPC API
- [ ] lotus message management (mpool)
- [ ] Other
Lotus Version
lotus v1.15.2
Describe the Bug
Our sofiaminer
has been configured with:
MaxWaitDealsSectors = 2
MaxSealingSectors = 2
MaxSealingSectorsForDeals = 2
Today we noticed that 4 deals (each ~14GiB) were blocked in Adding to sector
state, and sealing pipeline was blocked with 2 sectors:
957 UpdateReplica YES YES 3374050 (in 1 year 24 weeks) CC
1007 UpdateReplica YES YES 3374170 (in 1 year 24 weeks) CC
Those two sectors got created from Available
sectors and their expiration epochs
are after the 4 deals end epochs (i.e. the deals fit in these 2 sectors).
It is not clear why the sectors got into UpdateReplica
states without the deals inside them.
After abort
ing the upgrade on these 2 sectors, 2 new sectors (from Available
state) got upgraded, and successfully added the 4 deals to them and sealed properly into UpdateActivating
state.
Logging Information
Broken UpdateReplica
sectors with no deals:
2022-05-19T06:06:30.646+0300 INFO sectors storage-sealing/input.go:278 Adding piece for deal 6328251 (publish msg: bafy2bzaceaajmdwdoik4u3gjmtfqhdoqpo57e5el6ac7akt4bupxclskcxkzs)
2022-05-19T06:06:30.650+0300 ERROR sectors storage-sealing/input.go:514 we are trying to create a new sector with open sectors map[]
2022-05-19T06:06:30.651+0300 INFO sectors storage-sealing/input.go:674 new deal sector decision {"sealing": 0, "maxSeal": 2, "maxUpgrade": 2, "preferNew": false, "canCreate": true, "canUpgrade": true, "shouldUpgrade": true}
2022-05-19T06:06:30.665+0300 INFO sectors storage-sealing/input.go:278 Adding piece for deal 6328250 (publish msg: bafy2bzaceaajmdwdoik4u3gjmtfqhdoqpo57e5el6ac7akt4bupxclskcxkzs)
2022-05-19T06:06:31.185+0300 INFO sectors storage-sealing/input.go:620 Upgrading sector {"number": "1007", "type": "deal", "proofType": 8, "expiration": "3374170", "pledge": "0.149331217034391605 FIL"}
2022-05-19T06:06:31.185+0300 ERROR sectors storage-sealing/input.go:514 we are trying to create a new sector with open sectors map[]
2022-05-19T06:06:31.191+0300 INFO sectors storage-sealing/input.go:144 starting to seal deal sector {"sector": "1007", "trigger": "wait-timeout"}
2022-05-19T06:06:31.197+0300 INFO sectors storage-sealing/states_sealing.go:48 performing filling up rest of the sector... {"sector": "1007"}
2022-05-19T06:06:31.198+0300 WARN sectors storage-sealing/states_sealing.go:72 Creating 1 filler pieces for sector 1007
2022-05-19T06:06:31.198+0300 INFO sectors storage-sealing/states_sealing.go:88 Pledge {{127896 1007} 8}, contains []
2022-05-19T06:06:31.198+0300 DEBUG advmgr sector-storage/sched.go:361 SCHED 1 queued; 4 open windows
2022-05-19T06:06:31.200+0300 DEBUG advmgr sector-storage/sched.go:457 SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]}]
2022-05-19T06:06:31.200+0300 DEBUG advmgr sector-storage/sched.go:458 SCHED Acceptable win: [[0 1]]
2022-05-19T06:06:31.200+0300 DEBUG advmgr sector-storage/sched.go:480 SCHED try assign sqi:0 sector 1007 to window 0 (awi:0)
2022-05-19T06:06:31.200+0300 DEBUG advmgr sector-storage/sched.go:480 SCHED try assign sqi:0 sector 1007 to window 1 (awi:1)
2022-05-19T06:06:31.200+0300 DEBUG advmgr sector-storage/sched.go:521 SCHED ASSIGNED {"sqi": 0, "sector": "1007", "task": "seal/v0/addpiece", "window": 0, "worker": "80b730ae-31c9-4830-b176-b828a0df9dbe", "utilization": 0.2852374219200975}
2022-05-19T06:06:31.200+0300 DEBUG advmgr sector-storage/sched_worker.go:369 assign worker sector 1007
2022-05-19T06:06:31.200+0300 DEBUG advmgr sector-storage/sched.go:361 SCHED 0 queued; 4 open windows
2022-05-19T06:06:31.201+0300 DEBUG advmgr sector-storage/sched_worker.go:274 task done {"workerid": "80b730ae-31c9-4830-b176-b828a0df9dbe"}
2022-05-19T06:06:31.201+0300 DEBUG advmgr sector-storage/sched.go:361 SCHED 0 queued; 4 open windows
2022-05-19T06:07:34.664+0300 ERROR sectors storage-sealing/fsm.go:34 unhandled sector error (1007): checkPieces sanity check error:
github.com/filecoin-project/lotus/extern/storage-sealing.handleErrors
/root/lotus/extern/storage-sealing/states_replica_update.go:295
- sector 1007 must have deals, but does not
2022-05-19T08:28:59.970+0300 INFO sectors storage-sealing/input.go:278 Adding piece for deal 6333497 (publish msg: bafy2bzaceawz6tlxavlwdjiynfhsp2lrdnfeo66phthy42jaorhc5tbctalog)
2022-05-19T08:28:59.972+0300 ERROR sectors storage-sealing/input.go:514 we are trying to create a new sector with open sectors map[]
2022-05-19T08:28:59.973+0300 INFO sectors storage-sealing/input.go:674 new deal sector decision {"sealing": 1, "maxSeal": 2, "maxUpgrade": 2, "preferNew": false, "canCreate": true, "canUpgrade": true, "shouldUpgrade": true}
2022-05-19T08:28:59.995+0300 INFO sectors storage-sealing/input.go:278 Adding piece for deal 6333498 (publish msg: bafy2bzaceawz6tlxavlwdjiynfhsp2lrdnfeo66phthy42jaorhc5tbctalog)
2022-05-19T08:29:00.567+0300 INFO sectors storage-sealing/input.go:620 Upgrading sector {"number": "957", "type": "deal", "proofType": 8, "expiration": "3374050", "pledge": "0.14650541070944655 FIL"}
2022-05-19T08:29:00.568+0300 ERROR sectors storage-sealing/input.go:514 we are trying to create a new sector with open sectors map[]
2022-05-19T08:29:00.573+0300 INFO sectors storage-sealing/input.go:144 starting to seal deal sector {"sector": "957", "trigger": "wait-timeout"}
2022-05-19T08:29:00.579+0300 INFO sectors storage-sealing/states_sealing.go:48 performing filling up rest of the sector... {"sector": "957"}
2022-05-19T08:29:00.579+0300 WARN sectors storage-sealing/states_sealing.go:72 Creating 1 filler pieces for sector 957
2022-05-19T08:29:00.579+0300 INFO sectors storage-sealing/states_sealing.go:88 Pledge {{127896 957} 8}, contains []
2022-05-19T08:29:00.579+0300 DEBUG advmgr sector-storage/sched.go:361 SCHED 1 queued; 4 open windows
2022-05-19T08:29:00.582+0300 DEBUG advmgr sector-storage/sched.go:457 SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]}]
2022-05-19T08:29:00.582+0300 DEBUG advmgr sector-storage/sched.go:458 SCHED Acceptable win: [[0 3]]
2022-05-19T08:29:00.582+0300 DEBUG advmgr sector-storage/sched.go:480 SCHED try assign sqi:0 sector 957 to window 0 (awi:0)
2022-05-19T08:29:00.582+0300 DEBUG advmgr sector-storage/sched.go:480 SCHED try assign sqi:0 sector 957 to window 3 (awi:1)
2022-05-19T08:29:00.582+0300 DEBUG advmgr sector-storage/sched.go:521 SCHED ASSIGNED {"sqi": 0, "sector": "957", "task": "seal/v0/addpiece", "window": 0, "worker": "80b730ae-31c9-4830-b176-b828a0df9dbe", "utilization": 0.2852374219200975}
2022-05-19T08:29:00.582+0300 DEBUG advmgr sector-storage/sched_worker.go:369 assign worker sector 957
2022-05-19T08:29:00.582+0300 DEBUG advmgr sector-storage/sched.go:361 SCHED 0 queued; 4 open windows
2022-05-19T08:29:00.582+0300 DEBUG advmgr sector-storage/sched_worker.go:274 task done {"workerid": "80b730ae-31c9-4830-b176-b828a0df9dbe"}
2022-05-19T08:29:00.582+0300 DEBUG advmgr sector-storage/sched.go:361 SCHED 0 queued; 4 open windows
2022-05-19T08:29:06.011+0300 INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 7, "forRound": 1821059, "baseEpoch": 1821058, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1916903, "lookbackEpochs": 900, "networkPowerAtLookback": "19312307760272900096", "minerPowerAtLookback": "63971695689728", "isEligible": true, "isWinner": false, "error": null}
2022-05-19T08:30:04.770+0300 ERROR sectors storage-sealing/fsm.go:34 unhandled sector error (957): checkPieces sanity check error:
github.com/filecoin-project/lotus/extern/storage-sealing.handleErrors
/root/lotus/extern/storage-sealing/states_replica_update.go:295
- sector 957 must have deals, but does not
I trigger abort upgrade on the 2 sectors from above, and the deals got added to the new sectors (around 13:00 timestamp):
2022-05-19T12:57:00.015+0300 INFO sectors storage-sealing/input.go:726 aborting upgrade of sector {"sector": "957", "trigger": "user"}
2022-05-19T12:57:00.015+0300 WARN sectors storage-sealing/fsm.go:763 sector 957 got error event sealing.SectorAbortUpgrade: triggered by user
2022-05-19T12:57:00.021+0300 ERROR sectors storage-sealing/input.go:514 we are trying to create a new sector with open sectors map[]
2022-05-19T12:57:00.022+0300 INFO sectors storage-sealing/input.go:674 new deal sector decision {"sealing": 1, "maxSeal": 2, "maxUpgrade": 2, "preferNew": false, "canCreate": true, "canUpgrade": true, "shouldUpgrade": true}
2022-05-19T12:57:00.592+0300 INFO sectors storage-sealing/input.go:620 Upgrading sector {"number": "978", "type": "deal", "proofType": 8, "expiration": "3374050", "pledge": "0.146720918263824136 FIL"}
2022-05-19T12:57:00.599+0300 ERROR sectors storage-sealing/input.go:514 we are trying to create a new sector with open sectors map[{127896 978}:0xc01d2c3520]
2022-05-19T12:57:00.600+0300 INFO sectors storage-sealing/input.go:674 new deal sector decision {"sealing": 2, "maxSeal": 2, "maxUpgrade": 2, "preferNew": false, "canCreate": false, "canUpgrade": false, "shouldUpgrade": false}
2022-05-19T12:57:00.600+0300 DEBUG advmgr sector-storage/sched.go:361 SCHED 1 queued; 4 open windows
2022-05-19T12:57:00.602+0300 DEBUG advmgr sector-storage/sched.go:457 SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]}]
2022-05-19T12:57:00.602+0300 DEBUG advmgr sector-storage/sched.go:458 SCHED Acceptable win: [[2 3]]
2022-05-19T12:57:00.602+0300 DEBUG advmgr sector-storage/sched.go:480 SCHED try assign sqi:0 sector 978 to window 2 (awi:0)
2022-05-19T12:57:00.603+0300 DEBUG advmgr sector-storage/sched.go:480 SCHED try assign sqi:0 sector 978 to window 3 (awi:1)
2022-05-19T12:57:00.603+0300 DEBUG advmgr sector-storage/sched.go:521 SCHED ASSIGNED {"sqi": 0, "sector": "978", "task": "seal/v0/addpiece", "window": 2, "worker": "80b730ae-31c9-4830-b176-b828a0df9dbe", "utilization": 0.2852374219200975}
2022-05-19T12:57:00.603+0300 DEBUG advmgr sector-storage/sched_worker.go:369 assign worker sector 978
2022-05-19T12:57:00.603+0300 DEBUG advmgr sector-storage/sched.go:361 SCHED 0 queued; 4 open windows
2022-05-19T12:57:00.603+0300 DEBUG advmgr sector-storage/sched_worker.go:274 task done {"workerid": "80b730ae-31c9-4830-b176-b828a0df9dbe"}
2022-05-19T12:57:00.603+0300 DEBUG advmgr sector-storage/sched.go:361 SCHED 0 queued; 4 open windows
2022-05-19T12:57:02.688+0300 INFO sectors storage-sealing/input.go:726 aborting upgrade of sector {"sector": "1007", "trigger": "user"}
2022-05-19T12:57:02.688+0300 WARN sectors storage-sealing/fsm.go:763 sector 1007 got error event sealing.SectorAbortUpgrade: triggered by user
2022-05-19T12:57:02.696+0300 ERROR sectors storage-sealing/input.go:514 we are trying to create a new sector with open sectors map[{127896 978}:0xc01d2c3520]
2022-05-19T12:57:02.697+0300 INFO sectors storage-sealing/input.go:674 new deal sector decision {"sealing": 1, "maxSeal": 2, "maxUpgrade": 2, "preferNew": false, "canCreate": true, "canUpgrade": true, "shouldUpgrade": true}
2022-05-19T12:57:03.201+0300 INFO sectors storage-sealing/input.go:620 Upgrading sector {"number": "875", "type": "deal", "proofType": 8, "expiration": "3374050", "pledge": "0.146775113865666972 FIL"}
Logs from lotus-worker
2022-05-19T06:06:31.211+0300 DEBUG advmgr sector-storage/worker_local.go:158 acquired sector {{127896 1007} 8} (e:0; a:1): {{0 0} /root/.lotusworker/unsealed/s-t0127896-1007 }
2022-05-19T06:06:34.205+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -12288
2022-05-19T06:06:44.206+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -12288
2022-05-19T06:06:54.208+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -12288
2022-05-19T06:07:04.209+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -32768
2022-05-19T06:07:14.218+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -36864
2022-05-19T06:07:24.220+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -36864
2022-05-19T06:07:34.221+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -40960
2022-05-19T08:29:00.587+0300 DEBUG advmgr sector-storage/worker_local.go:158 acquired sector {{127896 957} 8} (e:0; a:1): {{0 0} /root/.lotusworker/unsealed/s-t0127896-957 }
2022-05-19T08:29:05.281+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -16384
2022-05-19T08:29:15.282+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -16384
2022-05-19T08:29:25.283+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -16384
2022-05-19T08:29:35.283+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -32768
2022-05-19T08:29:45.298+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -49152
2022-05-19T08:29:55.302+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -49152
2022-05-19T12:57:00.609+0300 DEBUG advmgr sector-storage/worker_local.go:158 acquired sector {{127896 978} 8} (e:0; a:1): {{0 0} /root/.lotusworker/unsealed/s-t0127896-978 }
2022-05-19T12:57:03.221+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -28672
2022-05-19T12:57:03.221+0300 DEBUG advmgr sector-storage/worker_local.go:158 acquired sector {{127896 875} 8} (e:0; a:1): {{0 0} /root/.lotusworker/unsealed/s-t0127896-875 }
2022-05-19T12:57:07.218+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -73728
2022-05-19T12:57:17.219+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -77824
2022-05-19T12:57:27.221+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -86016
2022-05-19T12:57:37.222+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -86016
2022-05-19T12:57:47.223+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -86016 2022-05-19T12:57:57.224+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -86016
2022-05-19T12:58:07.226+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -86016
2022-05-19T12:58:17.227+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -86016 2022-05-19T12:58:27.228+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -86016
2022-05-19T12:58:37.229+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -94208
2022-05-19T12:58:47.230+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -106496
2022-05-19T12:58:57.231+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -106496
2022-05-19T12:59:07.232+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -106496
2022-05-19T12:59:17.233+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -110592
2022-05-19T12:59:27.237+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -110592
2022-05-19T12:59:37.238+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -110592
2022-05-19T12:59:47.239+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -110592
2022-05-19T12:59:57.240+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -110592
2022-05-19T13:00:07.241+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -110592 2022-05-19T13:00:17.245+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -110592
2022-05-19T13:00:27.246+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=68719476736, reserved: -110592
2022-05-19T13:00:31.235+0300 DEBUG advmgr sector-storage/worker_local.go:158 acquired sector {{127896 978} 8} (e:1; a:0): {{0 0} /root/.lotusworker/unsealed/s-t0127896-978 } 2022-05-19T13:00:37.247+0300 WARN stores stores/local.go:130 negative reserved storage: p.reserved=34359738368, reserved: -53248
2022-05-19T13:00:45.312+0300 DEBUG advmgr sector-storage/worker_local.go:158 acquired sector {{127896 875} 8} (e:1; a:0): {{0 0} /root/.lotusworker/unsealed/s-t0127896-875 }
2022-05-19T13:04:18.534+0300 INFO stores stores/http_handler.go:189 SERVE Alloc check /remote/unsealed/s-t0127896-978/8/allocated/0/17045651456
2022-05-19T13:04:18.535+0300 DEBUG stores stores/http_handler.go:283 returning ok: worker has unsealed file with unsealed piece, sector:{Miner:127896 Number:978}, offset:0, size:17045651456
2022-05-19T13:04:18.539+0300 INFO stores stores/http_handler.go:189 SERVE Alloc check /remote/unsealed/s-t0127896-978/8/allocated/0/17045651456
2022-05-19T13:04:18.540+0300 DEBUG stores stores/http_handler.go:283 returning ok: worker has unsealed file with unsealed piece, sector:{Miner:127896 Number:978}, offset:0, size:17045651456
2022-05-19T13:04:18.606+0300 DEBUG stores stores/http_handler.go:157 served sector file/dir, sectorID={Miner:127896 Number:978}, fileType=unsealed, path=/root/.lotusworker/unsealed/s-t0127896-978
2022-05-19T13:04:19.409+0300 INFO stores stores/http_handler.go:189 SERVE Alloc check /remote/unsealed/s-t0127896-978/8/allocated/17045651456/17045651456
2022-05-19T13:04:19.410+0300 DEBUG stores stores/http_handler.go:283 returning ok: worker has unsealed file with unsealed piece, sector:{Miner:127896 Number:978}, offset:17045651456,
Repo Steps
.