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

Available sectors get upgraded to UpdateReplica sectors with no deals, when deals are ready to be added to sectors #8686

Closed
7 of 18 tasks
Tracked by #432
nonsense opened this issue May 19, 2022 · 23 comments · Fixed by #9310
Closed
7 of 18 tasks
Tracked by #432

Available sectors get upgraded to UpdateReplica sectors with no deals, when deals are ready to be added to sectors #8686

nonsense opened this issue May 19, 2022 · 23 comments · Fixed by #9310
Assignees
@TippyFlitsUK @magik6k
Labels
area/sealing kind/bug Kind: Bug need/analysis Hint: Needs Analysis P1 P1: Must be resolved SnapDeals

Comments

@nonsense
Copy link
Member

nonsense commented May 19, 2022 •
edited
Loading

Checklist

  • This is not a security-related bug/issue. If it is, please follow please follow the security policy.
  • This is not a question or a support request. If you have any lotus related questions, please ask in the lotus forum.
  • This is not a new feature request. If it is, please file a feature request instead.
  • This is not an enhancement request. If it is, please file a improvement suggestion instead.
  • I have searched on the issue tracker and the lotus forum, and there is no existing related issue or discussion.
  • 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
  • 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 aborting 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

.
@Reiers
Copy link

Reiers commented May 19, 2022

Started the reproduction here. It will take a couple of hours.

@nonsense may I get the full log of each sector that failed the upgrade?

lotus-miner sectors status --log 957

lotus-miner sectors status --log 1007

Thank you !

@Reiers
Copy link

Reiers commented May 19, 2022

Also did you have 2 SnapDealsWaitDeals already pending with smaller deals when these sectors got sent to sealing ?

@nonsense
Copy link
Member Author

nonsense commented May 19, 2022 •
edited
Loading

lotus-miner sector status --log 957

...
9.      2021-11-24 21:17:30 +0200 EET:  [event;sealing.SectorPreCommitLanded]   {"User":{"TipSet":"AXGg5AIgKgw5j3jUTx5/RTV2YWMtnd/XmRCRE2i1OEdlJ5RIblcBcaDkAiAd5LSU0qVgyUMf0jcGGPlMF7Ie1Ao2GYprZ1dbfpisiAFxoOQCIGwVEAm8iEOctPkyiLUFenVvfOHFHn/augguLDHaL5pCAXGg5AIgeYWL9gsdhULaN9/thpaNLeZoRCIkPWKBZme5i07B6kgBcaDkAiD9SfEw7hOuPAHvZR7fnhBaFz6oOQI6SGKA2bfQHkIJBwFxoOQCIAj31n/ppLIh73pNZ2BXkyzVD/p88FnnNn4RCtGBOquF"}}
10.     2021-11-24 22:32:30 +0200 EET:  [event;sealing.SectorSeedReady] {"User":{"SeedValue":"34ioQGaPif65cwS9vLKKy/jDNTiik/7gYRVYv0bVkR8=","SeedEpoch":1315979}}
11.     2021-11-24 22:47:47 +0200 EET:  [event;sealing.SectorCommitted] {"User":{"Proof":"rn5gcZ4FAvri5FtlXKrjtC5UzNgR+ldkUSwTV/+hewa0JKZD9d8N8ke9FDIaXZwaqCW/f9U8auyqLr3FiYalpRVzmHJ27E+XLA5pRok2A7Mm4KOfZf33ookHI1d+tgkYGarCU6tODTvcmW8bGuz1u4K37B8sli1JY6jnObCeLRoGQtNb1P8HrB9Y/BJgDJJljYRxjtaZxk0J1U7sBvpvUDFLNYmcRvJGhI361O1UBGYsl/bwcpdTUAT+LKddNVpepOI42Mh63o7B0pnznJurcJEq1n5dQlM3J7kOi7DhPzOeNkDhXVOdoMAJqaMMJF/NlLdeMYaXXi13LPN4nDTNrUysZ5QQGX+POqvhCvuzM4wKjxTCtcaNp+iErT5FBbs5CDptMWDFfxlbny+0m5kqo3VAhJ/x5MQ02l6A91y7FGPHPo7trGQShkx/Up0V9Y++tJxTpPmfDGlFiilPdx/EpWJ98+1xM1rWhlgbtjE+Zuzq3dK8rXUmMX2+GWw2O7dPmfV4ygDrCZMbdEks12h34mKOyv42KYSUBAGmuFIUH6BGeOG8m4tO4SLAsBrvQebyqy1u++HY993x5UWacs1pCbJmNQngFbTHBx7RayW3RQsdHkAZssmleix5Ck7LnR8LB8vcHrVLpmq0dpO9kFiuGd+ECdoj6peqjSD6+tMzm4gVDnotTBl3nPWoyPqnhgeKkwg1fE58cLaWg0f209gwgY3WfIPjjM/9vETj9wtM0BWXiD885p0VxVAvG54yUdVtsldPaR9T0nGQHR/jic1ilySehGhvtjberYDVFvWabixs0wpqJItC1duiK6T/MXq5jPobiNa/VJjsZf9f1owV2yraJdStQgyLivf5isHeQ4IhGtyuo8YnpGgF0uNiAq89DB0hp9csIudXzrpDMJnUGjSCh+5ll04e542JWzWzFsOUbwHY2j7lz5hl1TbhMNorils4HGcHNzjd+55TCl7dYiInS9UowGFJsKZCpYIGD9E5QLtGdJ4ZkXDTBDg0wPr8tlMA8NO2qql3eR6kfaE8kB1p3Ed0fIszCtayYihQhqv8qKxuGSA9D/4JrO8txWQarYs+4+NUXtJcriQq4jP6fY4AcA0YE6i6dwXf0KU+eASD8jDtYdm4VGAupLeOyb7NC2JM+/i/4cpjD77ZH/ezp5szN+Lzq6xtsd36Nqb/rOvFNeTns1HXdEZJEycEX9Fxo4+NMfbPX4Ort8+EmHTVwrBEX8ZQ2nr5V9zFDkSVTsgWp635nuPgD5L2rSFcgBsLiPHhSSN7ycfEO1O0NuDfl8IY6NKWm2xuhJO09+jjW92ObYB4Znt8q3JKuRjI6TE7gHqnbAwSzgkcGIRNG0rdzMTv5dCZ7NcXicncoqX7jBT62QlsFVGA4pSuFdSO5glxFt4LHGj0S9hfuvKx7AEbZF3T9+XzEhk9zLBGq2wW7E9EmutwsG7K6ZviWf38Tc+tq9k+Sydv1rk70am7gu7ThtQy7MlwJ+9tKQpNilJ6Qy9uwZTZZEWfMQrwgnJy2UdNryO2uZMqEQtjLk2ioWHscLC/x1ZnVV0BqUyo7F3GXyWuq1T0iPO4g0Q6OcStY9zpiPg4e6ZqyKocSxsM1mvbg+xv6phqmxDFrgM/+6ATngq/fo0cQx67UcnQpHt6roA9DmJ85L0VCpC+Mu8bN8zxcZ4GpRHpufa583FiFtAohiGjciJNxfc0JbWbgt5lRd0DgUIHmyGRI1eseB6YKwwFJTEer0onbOq1aC+dx91jUSUWr+7D/9rMekX7QDS9qW8iuY5Qa2Y+6Cl2zIU90iHQmGBN2PjX+6fzcXd6nyxK9rnBs3a1YfX7hhNLxHdoFujaqJDynRjqooLDIi3v+o2gGfCZbK6pciT0oODUkV0xJ+3GwmXYfIwyJx9qlEC2HnVtEBqRp2swkxMnlUXPo01xF3HUJKVyPJDXnLiVKXzjnTEIRP4qx0qhWXzVnrjCFPecq391HqHd/clMSTZeR8vamAXZvk/cmE/AX24rWu6gSXjgRHd+t88pi/WJq+FleTUttHXrCDr7dZln5lXZ6+Q3i2239bWH3e2l7p2qWeEKuRAPk+3TQLUcezQ7zaww2OGTozxXvM0GCiMpdlPU/vSAmUbfrwUNUGa0KhNNOft0T8xAhjsdAmb348tYwwwlY+NKEqcgWGWH9MFGvqsiwIRNaD/3jc0VHi07JNqRi5SfQyNN5M8d3sBYMzMrZsf4jiGyreUdm6lCPh6QX/5Uu//HCzfySFAnD36RsC+ewZiWGHl/Ekztz0iDYy62+Io36UfKpMFb0g91MadSUyvJKPaqSrJPOZxwBD9b3nAp2S83O1xKKFL7LtA1XjSPU0ZKLbCTge9q3DVeg5d6aYHhZc7J4QJfJzLcCIosiZAcXTRQpftY0YMTIT7VTNemYhRgwTADD2AN+L/3oG6FXqYwwfJ4Jqp5KOfLK2f4vWVkRCbx4BW/UzUeGMCJUIZM6WA1K8CSgLrCDNTQ3TucOyzF/xICc5q2/VPIRBokLTRH6z7eiaN7uePNl5QrVqDuNLe+Z4Xh"}}
12.     2021-11-24 22:47:48 +0200 EET:  [event;sealing.SectorCommitSubmitted]   {"User":{"Message":{"/":"bafy2bzaceabwly7qivu3qae6f42afwyf637s5lozvuclogi43azoe3extogig"}}}
13.     2021-11-24 22:50:59 +0200 EET:  [event;sealing.SectorProving]   {"User":{}}
14.     2021-11-24 22:51:37 +0200 EET:  [event;sealing.SectorFinalized] {"User":{}}
15.     2022-04-08 00:38:02 +0300 EEST: [event;sealing.SectorMarkForUpdate]     {"User":{}}
16.     2022-05-19 08:29:00 +0300 EEST: [event;sealing.SectorStartCCUpdate]     {"User":{}}
17.     2022-05-19 08:29:00 +0300 EEST: [event;sealing.SectorStartPacking]      {"User":{}}
18.     2022-05-19 08:30:04 +0300 EEST: [event;sealing.SectorPacked]    {"User":{"FillerPieces":[{"Size":34359738368,"PieceCID":{"/":"baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq"}}]}}
19.     2022-05-19 12:57:00 +0300 EEST: [event;sealing.SectorAbortUpgrade]      {"User":{}}
        triggered by user
20.     2022-05-19 12:57:00 +0300 EEST: [event;sealing.SectorRevertUpgradeToProving]    {"User":{}}

@nonsense
Copy link
Member Author

lotus-miner sector status --log 1007

7.      2022-01-14 16:22:07 +0200 EET:  [event;sealing.SectorPreCommit2]        {"User":{"Sealed":{"/":"bagboea4b5abcbn3cbaxrcf55lr4crh7rbl2bhm5x7bwqzjbdiyowmmcdeno7l427"},"Unsealed":{"/":"baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq"}}}
8.      2022-01-14 16:22:10 +0200 EET:  [event;sealing.SectorPreCommitted]      {"User":{"Message":{"/":"bafy2bzacedewe7tn4fjstprtnkgpwo2kyp7nfd3lxi2nbd5hdafr62o3qyux6"},"PreCommitDeposit":"13964689232056576","PreCommitInfo":{"SealProof":8,"SectorNumber":1007,"SealedCID":{"/":"bagboea4b5abcbn3cbaxrcf55lr4crh7rbl2bhm5x7bwqzjbdiyowmmcdeno7l427"},"SealRandEpoch":1460914,"DealIDs":[],"Expiration":3011564,"ReplaceCapacity":false,"ReplaceSectorDeadline":0,"ReplaceSectorPartition":0,"ReplaceSectorNumber":0}}}
9.      2022-01-14 16:25:30 +0200 EET:  [event;sealing.SectorPreCommitLanded]   {"User":{"TipSet":"AXGg5AIgxN8lpOUqmkW0jmy50PJjz4BNS5dvhWTX0imAneXVuXMBcaDkAiAbCO9U4MWJfGX1haegISe8H0Acrqzr5U3hOkXHi+RHLg=="}}
10.     2022-01-14 17:40:29 +0200 EET:  [event;sealing.SectorSeedReady] {"User":{"SeedValue":"uhm6mx6jVhClg71LRGZxZzEuwd4wTA0NUhtqNrhhGks=","SeedEpoch":1462275}}
11.     2022-01-14 17:55:41 +0200 EET:  [event;sealing.SectorCommitted] {"User":{"Proof":"tfch+PFdkowHcbflWgTfdqhMqvb+XKbf7rjrFrulSWDFcItFawis4SE7K3sQNEeyqUGFkoaY/7jKSe24dlS3yf0W1gWFcVNv7eDOJIFCMGyAv4rHYljD9NeHKZD7tly3F59nDQrpGUXS5ZU8/tdAk7dnEX2IUGq9+HLos6GMRrn/R8SqB3gO+W3i+OK8Gsz+iDQEoKm+odoW/yTUl5iFR+ctcoLA71ZHAStHoPHO8xXKxA+yehOkRY13kvhXMMKXtIfYwNojSjOaj837du0FAzaSvXk8zaZ1DfQ6DbyPK4F+1CN3HSg4Jm6A8PdAesi1jXu2gY3JC5KtKiMb6cYegX1mY3gxYgZ0lYq+ZYrChkIFNADst/Q0AFlds79KVbEnFgdW9NkSNzLTQ1FCvZ7rc47opkwSQaY3A+TEz55+PseoExZc47NhOEChvr24M9H+tkd1mYpye76x7XdCO+LsjdIT+LgVweWx7gds0DO9Akc8qZeVbQ4Wo1j4jedH3EtsjbUbk2k1mbZZlLHxIqyDLt/B5EaMWp6a+eLRHdO1wA/7FAlx31YbuSCDVfq/ML39hhp0S6r6aKnk8p1WPMFnldkHm5LRzzJrADTUoBf0NAyr5U6iOfi6kYhHIWt8UQwyBjju4e/kuiiLxnlCA6CKtTePt3jzs4j4TVz+b46s2X4p2Xhx+xufRr1XgjGkzVSxpnUQHKGG7QYojYVFK/IaW7a5glRDb0q9+OM16L6nT5VG74mExAnpmNIJdlDXwolNiwM7ZotuGzabT81Xosf01Huu5Ao+zk0ZNTtOIYSzFNMaLO0vf2s9Ub7vZByLJO06sMGle1YNV5Zj7Ahf5zyxPS/GEeeEERsGwe6l9dW1eFWrpvdlhd5ixoMNSDjte6MNBbd/TyggMu6fDB9p6p45Kh+4pL3R10S7Mr2S+/41GdHUXu8pi6PcNqHXiY1YSq10sYj30kwCFpGXMO6XJoRhGwGO6N5iwI2ZDXGbMz41M33oPfcP7YusF+rVetK0t2b1r5gcobvFF7+gJGquunohrjBq2e0kEQ71myAQbSR+j9DT3EZgDXKoDSI6HcBrECNeiXLvkKSGR5ssfwjgGqZtIlcLlVX0c6K1bR6yQoav0BfURvVUK7vRifMxeQndil5CFXttRtaooGt+BQRoA33g94FZoFpvrW9pC/YXoCPppFHu+RixuUvCmvHbOG+IBVfjqUKMWzqeylpJhFFbW3///hkYtsTikM+DvaLCO6M3syDTJAir/JSnWe7p0k8y76z6kEO1ddRS4I7udDAtrZCgvKxB7wMAb10Qug/qy9T9X/XiAnoGLSBgSZPgdf0dQjDMkCOdn03cTkwxCWD260pLYEk0XOF3EzbCbdOscbxlPT26H6K0rQPYes0rpoou7N7qE38QDk/lQaUomXpNBNz/1dj5NOSvuKl52tlu/0KhHbo56QMcOSaxQAGT6GCac7jGlHnw3aiSMofx0UDlf0SbbGUHSRBEgyPoDpaJuCixYimg+iiSPKSUqfrGC0PJKUEoqVlj86V1GXNSViUyhama8iW3dEbEUqwjZguj3Ah+WUkBEWT6BLLjOyiIfYmPdxYyo+1JNUBOTINzzywGBtKrl0QU8JyDHdwm0D0u/1NPMeVKKgBeBg0/QDRtjyqBCJW1FavETSeyHRjNimLlbcFdaYiUUzaIA5HfjcjrBj+cYhzkct88rXgLIB6dL2LcCIN0tBblPnZCWHc0EZJuaeIDutmtpNoFDc+qNQNZjEA2yHEvXo9SAJCUH8QEFIRoUfEMta0JU/l5hs1edWgAvIwZ7GICPOB5LyQjdwBjLYgsDqLcBchekqq+9eZJxTUYVo1pqCfTc179768iNEEsl8vM0OIWeW5XRK8P8Oa8rEuF4eQG1ttdQA0pyHgB5O5zDpOhEehW4zvz4BQOBcqtW5ZKc6Z/i1B8DB0ZomH2H3l8wlPGz1RqtL9trmZO8ozAXDwbjOTqFrGMyPo3dOHOCR+W1SADI0AkHi9JfqGfU538Z83LdvR+BpFUI7uVJfgiaIBwgxguYhXupvQ9hZz/8qi8SYMSLDCXkt1HKzT3x9KQfzz5BL4fKRqxaeWNyU0Xqr40oX9N5M7tPGGDkh+hsoaI8hnK7D9ae4dO8l1oU/kqxK6KvhaOaViIv1aaZVAkLOn3DFcLReX28kq/oOjeykswgCk+MMN545eglbs5rWdC4Q6zwqEfNdRiRVqH/xZqHFDRq++/Uj0JB6I2S+ou6yT+l1fN7pJhzG6c+1YJm3Vqhos9Q7JO6Yt/F9MdkK5ROeJ2oviVt9pojQMAK+XNpQg3DaaoI9Gpgwf6pSalhH0gT1viO5eq5WdV8nMUh2Qn42jChBkI/4JsMABKz8KfP5bVp85mJoSoe9r/xT99zvnB1dl9aoWdFvEplkskFxaCHcikFijEb1yx+CiYTBxJ8MSczUdI1fVs7xoM7Jw6A8i82paUjvUUV5uD/RrGRTRpySJGrPWmjYiQYs8uaQh6/lUeRvZZW/oxSn8km0MrAx/3C7f5YIPuJA42GKvnWqYGne6a"}}
12.     2022-01-14 17:55:41 +0200 EET:  [event;sealing.SectorCommitSubmitted]   {"User":{"Message":{"/":"bafy2bzacec5weowng77bvz4b4wqpqnyxinmtfmcmzbfwoqdsgkhgtfe6e7tra"}}}
13.     2022-01-14 17:59:30 +0200 EET:  [event;sealing.SectorProving]   {"User":{}}
14.     2022-01-14 18:00:06 +0200 EET:  [event;sealing.SectorFinalized] {"User":{}}
15.     2022-04-08 00:38:03 +0300 EEST: [event;sealing.SectorMarkForUpdate]     {"User":{}}
16.     2022-05-19 06:06:31 +0300 EEST: [event;sealing.SectorStartCCUpdate]     {"User":{}}
17.     2022-05-19 06:06:31 +0300 EEST: [event;sealing.SectorStartPacking]      {"User":{}}
18.     2022-05-19 06:07:34 +0300 EEST: [event;sealing.SectorPacked]    {"User":{"FillerPieces":[{"Size":34359738368,"PieceCID":{"/":"baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq"}}]}}
19.     2022-05-19 12:57:02 +0300 EEST: [event;sealing.SectorAbortUpgrade]      {"User":{}}
        triggered by user
20.     2022-05-19 12:57:02 +0300 EEST: [event;sealing.SectorRevertUpgradeToProving]    {"User":{}}

@nonsense
Copy link
Member Author

Also did you have 2 SnapDealsWaitDeals already pending with smaller deals when these sectors got sent to sealing ?

No, I don't think so.

@Reiers
Copy link

Reiers commented May 19, 2022

Thanks - nothing wrong in those sectors logs.
I will report back later with my finding !

@Reiers
Copy link

Reiers commented May 20, 2022

24/h in still not able to reproduce here - Im going to let it run over the weekend.
I need to find the cause of why the sectors got sent to sealing without deals.
Logging everything!

@nonsense
Copy link
Member Author

24/h in still not able to reproduce here - Im going to let it run over the weekend.

I've had it happen again over last night.

@Reiers
Copy link

Reiers commented May 20, 2022

Thanks for the update, that confirms that it wasnt a one time thing and its bound to happen here at some point - will keep at it and look for a cause !

@Reiers Reiers assigned TippyFlitsUK and unassigned Reiers May 23, 2022
@TippyFlitsUK
Copy link
Contributor

Tried to reproduced this using 1.15.3-rc2 with the following settings:

MaxWaitDealsSectors = 2
MaxSealingSectors = 2
MaxSealingSectorsForDeals = 2
WaitDealsDelay = "3h30m0s"
MakeCCSectorsAvailable = true
MaxUpgradingSectors = 0 (default)
PreferNewSectorsForDeals = false (default)
MakeNewSectorForDeals = true (default)

BATCHING DISABLED: Sent 10 X 14GiB unverified deals in quick succession (well within 3h30m0s) to my f08403 miner.

  • No issues identified. All deals were successfully distributed to Available CC sectors. No empty deal UpdateReplica sectors were created.

BATCHING ENABLED: Sent 10 X 14GiB unverified deals to my f08403 miner with config PublishMsgMaxDealsPerMsg = 10.

  • No issues identiofied. Only 2 sectors at a time transitioned to RU and all deals were again successfully distributed to Available CC sectors with no empty deal UpdateReplica sectors were created.

I will retain these config settings for the time being and update this thread if I encounter the same issues over the next few days.

@nonsense
Copy link
Member Author

This continues to happen on my end with 1.15.3-rc2.

Sometimes I have to abort-upgrade numerous sectors, while getting errors like:

2022-06-10T17:48:58.151+0300    WARN    stores  stores/index.go:207     sector {127896 1034} redeclared in 812f6dd3-7a51-4d5d-918a-a2a02615d7a9
2022-06-10T17:48:58.237+0300    ERROR   sectors storage-sealing/fsm.go:34       unhandled sector error (1034): checkPieces sanity check error:
    github.com/filecoin-project/lotus/extern/storage-sealing.handleErrors
        /root/lotus/extern/storage-sealing/states_replica_update.go:295
  - sector 1034 must have deals, but does not

before I get snap deals sectors with deals in them.

@TippyFlitsUK
Copy link
Contributor

Hi @nonsense, sorry to hear you are still seeing this!

This is a tough one to figure out. We haven't had any other reports of this at all and we're unable to repro the same issue at our end.

I will certainly keep the ticket active in the event we get more reports and update accordingly.

Many thanks!!

@nonsense
Copy link
Member Author

I upgraded to v1.15.3, will report back if I see the issue again.

@nonsense
Copy link
Member Author

nonsense commented Jul 7, 2022

I am afraid this is still happening on v1.16.0

@nonsense
Copy link
Member Author

nonsense commented Aug 19, 2022 •
edited
Loading

This is still happening on v1.17.0

We are still getting stuck sectors in Lotus, and it is certainly NOT because of lack of Available sectors with a long expiration date (I extended some 50 sectors yesterday with the max expiration date). Sectors get blocked in UpdateReplica or SnapDealsAddPiece or SnapDealsPacking with CC number of deals, and then one can’t even abort the upgrade of the sector without restarting lotus-miner.

Once I notice this happening, I restart lotus-miner and again abort the broken sectors, at which point another sectors from Available is allocated and AddPiece calls pass-through and deals get added to the sector.

@TippyFlitsUK
Copy link
Contributor

Many thanks for the update Anton!! 🙏

@nonsense
Copy link
Member Author

Here is a log from the last sector that got blocked and I aborted its upgrade:

11.     2021-01-24 03:15:29 +0200 EET:  [event;sealing.SectorCommitSubmitted]   {"User":{"Message":{"/":"bafy2bzacedbfz5uxkx2yjs4l77b4ek5gmbxcr7tif4j6tv4wd77hewxt4wiko"}}}
12.     2021-01-24 03:20:30 +0200 EET:  [event;sealing.SectorProving]   {"User":{}}
13.     2021-01-24 03:21:08 +0200 EET:  [event;sealing.SectorFinalized] {"User":{}}
14.     2021-01-24 20:38:14 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
15.     2021-01-25 20:24:14 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
16.     2021-01-28 19:34:13 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
17.     2021-01-29 21:21:14 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
18.     2021-02-02 16:26:04 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
19.     2021-02-04 13:25:58 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
20.     2021-02-08 14:05:36 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
21.     2021-02-09 23:16:07 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
22.     2021-02-09 23:39:36 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
23.     2021-02-09 23:47:34 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
24.     2021-02-16 15:05:41 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
25.     2021-02-24 22:53:50 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
26.     2021-02-25 22:59:23 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
27.     2021-02-25 23:21:54 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
28.     2021-02-27 08:16:20 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
29.     2021-02-28 22:08:31 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
30.     2021-03-04 10:44:44 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
31.     2021-03-05 02:25:23 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
32.     2021-03-05 02:28:31 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
33.     2021-03-11 12:48:01 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
34.     2021-03-12 16:43:44 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
35.     2021-03-13 13:38:54 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
36.     2021-03-17 09:49:28 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
37.     2021-03-17 09:51:44 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
38.     2021-03-23 12:36:57 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
39.     2021-03-24 16:09:35 +0200 EET:  [event;sealing.SectorRestart]   {"User":{}}
40.     2022-04-08 00:55:59 +0300 EEST: [event;sealing.SectorMarkForUpdate]     {"User":{}}
41.     2022-08-18 23:42:00 +0300 EEST: [event;sealing.SectorStartCCUpdate]     {"User":{}}
42.     2022-08-18 23:42:00 +0300 EEST: [event;sealing.SectorAddPiece]  {"User":{}}
43.     2022-08-19 13:29:25 +0300 EEST: [event;sealing.SectorPieceAdded]        {"User":{"NewPieces":null}}
44.     2022-08-19 13:29:25 +0300 EEST: [event;sealing.SectorStartPacking]      {"User":{}}
45.     2022-08-19 13:30:58 +0300 EEST: [event;sealing.SectorPacked]    {"User":{"FillerPieces":[{"Size":34359738368,"PieceCID":{"/":"baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq"}}]}}
46.     2022-08-19 13:31:26 +0300 EEST: [event;sealing.SectorAbortUpgrade]      {"User":{}}
        triggered by user
47.     2022-08-19 13:31:26 +0300 EEST: [event;sealing.SectorRevertUpgradeToProving]    {"User":{}}

@SBudo
Copy link

SBudo commented Aug 28, 2022

Just started to happen to me too...
Three sectors getting stuck in "UpdateReplica" after the sanity check error, although in my error, I don't see any other details but the "sanity check":

2022-08-28T11:31:27.437+1000 ERROR sectors pipeline/fsm.go:34 unhandled sector error (865): checkPieces sanity check error:

Sector status:

SectorID:       865
Status:         UpdateReplica
CIDcommD:       baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq
CIDcommR:       bagboea4b5abcah3jx546lzeiahlb5zm4o6e2nyambaun3tk5q55pnxusod2rbqzi
Ticket:         4cffc72ae1cac9b276c5243433307968a496cce2a0eca303ca736f243aebc4b9
TicketH:        2103368
Seed:           6185b427d82771eeb42a74d2778b5c7f3b22929a4152a8d0cb5f25a63832e547
SeedH:          2105025
Precommit:      bafy2bzacecpoqg24wnnnf5db3ogrdipyiadrpq6a4ducvjp6rhynw4ze2tdiq
Commit:         bafy2bzacebtwifhwk23chyzftenbslclkpb2fc73bbbqprttqbluvtjhimnoa
Deals:          [0]
Retries:        0
--------
Event Log:
0.      2022-08-25 16:58:45 +1000 AEST: [event;sealing.SectorStart]     {"User":{"ID":865,"SectorType":8}}
1.      2022-08-25 16:58:45 +1000 AEST: [event;sealing.SectorAddPiece]  {"User":{}}
2.      2022-08-25 23:09:37 +1000 AEST: [event;sealing.SectorPieceAdded]        {"User":{"NewPieces":null}}
3.      2022-08-25 23:09:37 +1000 AEST: [event;sealing.SectorStartPacking]      {"User":{}}
4.      2022-08-25 23:34:18 +1000 AEST: [event;sealing.SectorPacked]    {"User":{"FillerPieces":[{"Size":34359738368,"PieceCID":{"/":"baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq"}}]}}
5.      2022-08-25 23:34:18 +1000 AEST: [event;sealing.SectorTicket]    {"User":{"TicketValue":"TP/HKuHKybJ2xSQ0MzB5aKSWzOKg7KMDynNvJDrrxLk=","TicketEpoch":2103368}}
6.      2022-08-26 04:05:23 +1000 AEST: [event;sealing.SectorPreCommit1]        {"User":{"PreCommit1Out":"eyJfbG90dXNfU2VhbFJhbmRvbW5lc3MiOiJUUC9IS3VIS3liSjJ4U1EwTXpCNWFLU1d6T0tnN0tNRHluTnZKRHJyeExrPSIsImNvbW1fZCI6WzcsMTI2LDk1LDIyMiw1MywxOTcsMTAsMTQ3LDMsMTY1LDgwLDksMjI3LDczLDEzOCw3OCwxOTAsMjIzLDI0MywxNTYsNjYsMTgzLDE2LDE4Myw0OCwyMTYsMjM2LDEyMiwxOTksMTc1LDE2Niw2Ml0sImNvbmZpZyI6eyJpZCI6InRyZWUtZCIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoyMTQ3NDgzNjQ3fSwibGFiZWxzIjp7IlN0YWNrZWREcmczMkdpQlYxIjp7Il9oIjpudWxsLCJsYWJlbHMiOlt7ImlkIjoibGF5ZXItMSIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItMiIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItMyIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItNCIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItNSIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItNiIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItNyIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItOCIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItOSIsInBhdGgiOiIvbW50L21kMC93b3JrZXIvY2FjaGUvcy10MDE4OTY0MjItODY1Iiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItMTAiLCJwYXRoIjoiL21udC9tZDAvd29ya2VyL2NhY2hlL3MtdDAxODk2NDIyLTg2NSIsInJvd3NfdG9fZGlzY2FyZCI6Nywic2l6ZSI6MTA3Mzc0MTgyNH0seyJpZCI6ImxheWVyLTExIiwicGF0aCI6Ii9tbnQvbWQwL3dvcmtlci9jYWNoZS9zLXQwMTg5NjQyMi04NjUiLCJyb3dzX3RvX2Rpc2NhcmQiOjcsInNpemUiOjEwNzM3NDE4MjR9XX19LCJyZWdpc3RlcmVkX3Byb29mIjoiU3RhY2tlZERyZzMyR2lCVjFfMSJ9"}}
7.      2022-08-26 04:37:23 +1000 AEST: [event;sealing.SectorPreCommit2]        {"User":{"Sealed":{"/":"bagboea4b5abcah3jx546lzeiahlb5zm4o6e2nyambaun3tk5q55pnxusod2rbqzi"},"Unsealed":{"/":"baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq"}}}
8.      2022-08-26 04:37:23 +1000 AEST: [event;sealing.SectorPreCommitted]      {"User":{"Message":{"/":"bafy2bzacecpoqg24wnnnf5db3ogrdipyiadrpq6a4ducvjp6rhynw4ze2tdiq"},"PreCommitDeposit":"10317533003659421","PreCommitInfo":{"SealProof":8,"SectorNumber":865,"SealedCID":{"/":"bagboea4b5abcah3jx546lzeiahlb5zm4o6e2nyambaun3tk5q55pnxusod2rbqzi"},"SealRandEpoch":2103368,"DealIDs":[],"Expiration":3654314,"ReplaceCapacity":false,"ReplaceSectorDeadline":0,"ReplaceSectorPartition":0,"ReplaceSectorNumber":0}}}
9.      2022-08-26 04:40:30 +1000 AEST: [event;sealing.SectorPreCommitLanded]   {"User":{"TipSet":[{"/":"bafy2bzacebwtwqx3vr4pwph266bmrr3hulnsh5yccnemgjwirfg3ewwexmci4"},{"/":"bafy2bzaceafbkyjcumlgo6vqyw73u4folw4hz2cy5pwe2an6tfbtuje2ycuqq"},{"/":"bafy2bzacedavrcitvgcl4cst3uin7w2sd64yeosekcdqodrk5kziy2qlsqyzu"},{"/":"bafy2bzacebgsfifgtq4xg3qfms62vep4gzkxz64yavndvpuj6y357nrawvckg"},{"/":"bafy2bzacedes7k7ku3ost7ar65eti3ajj5guyi6ylbq55ntdoomjnz5nso43k"},{"/":"bafy2bzaceaxdtcmabkz6sm3gdydqih4tdlkj22cxe7mzohcg5cocfkai2d5pk"},{"/":"bafy2bzaceax5dglpwevy6s3vlf2zt5tksgvlnoisfcree5jzwdkcdm37fpfxk"}]}}
10.     2022-08-26 05:55:30 +1000 AEST: [event;sealing.SectorSeedReady] {"User":{"SeedValue":"YYW0J9gnce60KnTSd4tcfzsikppBUqjQy18lpjgy5Uc=","SeedEpoch":2105025}}
11.     2022-08-26 06:14:08 +1000 AEST: [event;sealing.SectorProofReady]        {"User":{"Proof":"ppj9cw9J276DQn1rx58ZF5TXvWSAfW6pRqG4rHssnYPrYO88W0W5vSzgFjyuAJF+ihgXO/yUBpDvEAMjg6wBVtihha4Qient3a9cTBdJg0tX84cVsEWxJ7BptBYLVXDbGd6DSYs4nPA2wqth62zVndxxD+x6Vs9uRbRT8NqsmLTq2XP6UZ1YQnOxyGDoYWPJj8CZX8jCoAtpwYzexKm+GX+IpaXZvjsxvjEa0Diw3FnIG0cP2HEqA1VB9jMQI16eghGN7iM88vySc/jAGPr3OG/KBQfTPBvp3kLhzjWpWt/csQ12CW8Xh18i4cJJA4b8kX0KO5saciXFf8rI6z+D3c6+m2XPXetMOXrj7fWcJ6Q4vrBIYZeNlX+fLR1rwG51FtB2ugq1Ju7mRrEukKB8YlECwCOeDns6NlaiNXdhW5jicKp1QYYYfcsKrML/dYeKq3icYsGq8Dy5X/ghuzWT141SOZLMhS3x1C535P04oWDwc0BIJ7NPoLPc5H7kTlTBraCyvjBYaAMOfA6I96RQ/nAabxY6XPE1PWpfstAc+8lgRMII9r+zKJrU1od/pZ/DmgEHp3hE6SSLzfmrEdF2C3nnRoxS36WAuzmHe7/iv5uWmzHM7yqVMShOkEePqpL4FpK+Qx/6xRD9jL1nPZcZAVfa5DrBnhqUZ/l/W4o5vNjBFhuRXwy4TT2shh6Qd+QKo/aJlIupJ1nPpO49/2lVqRhPBqoP/ucWqK/EOfL7uEJDFYPafvKz7eWEXROMvvSiiOfVmSDODftolGnJY1dKRkFcs+w6l0UI1oaby94+TS2FzfMchPhMEkVDHLIh0obFsxPNzHMHh0Xg8fDGf9rescDra4Z/SvxK2IoS/kt7/P8Hffc69UuGpzpa3xePnDRKCqXoMfD0/AqzTn3JxBt7i3MTMCOPIY53VgzKMQIav8gNI8k3R1btwZVxPErYnaR7mKRb43htt4tLtQFBQPA5A1adETh3EUf9bH0vYNu5VQg8bAf2o2M5fnODga4kcVUchn4fsnJGKfctdv0qm0qbOoDMPtKn5xdA6yCdlpu8Z6lgK68nerlgiWsVBOQvpLw/hDjcSG6g/h2YocU3epQfztTRwA4Q0SDkTBLH+w6EuqxJ8j1VrKgBpsFeVeo6ToygFPAHbZRT/sYSTkme8gXxgv3FG+aRvNvamPdDK+bmxKqvi8Yle2+q38lKzVcivo+9qAADJwLgP3+/URjaDviujbCc50zVAKE1puGcR55W2A3Dy5nvBZ3vSfzHxIGTCjVvrrT8uWKyEfNNQZYo80c0/8Q4hYRh9OiL9KUIgmt6umm5nFDaLH5eYoXUFfYRABNHuaOiIso83NQarBTNf73ZS7GSoB2XSw59EB3G2eZMhg6GJC1QQaYdDGQtVIoaZYr6A+bYlvomlHgf4IG7GqcCvRWjX+oyRiijZ/nXfep3KT1vvsXoZAw24ftwz7T70dyBgNxrD1dVAKn8SOnIhCOcb1S6ppO//39plBR6684GJ6cH2rD+CNM/zGh2XB52J03IuTsxN81liJXWLLn6Yac6O9RQervThTsF7FMP/uDWby8A7MbXCpqlry6eVHq11xsLitgmtuQYak1Rh4arspqebbav4kY2ZUbJQFz4Fb1d2qTZ7DA0gJUp+GRd0NQiFmN7D+OLTa63LwyDcZ/cIZaBU2QHxzRqMYpOU7G0BSlRkTqO/Pep1j1UVnn9WVqt/2UviNRphWLYvIOD2bmyevsX7cCwvPuY7D4LoVq5vTo9my2LfY+M+3alHa/0tPFXo27Gs2WgYe8ybKkiyO8dAMH5YYSaPycG2z4f+zSZ9GfGwLf5Z+ozaWR3N5XztzvWnvejtvJvTeZIjOberLuODxAz26wo1jPaKRKJFpyRQ0nkiLo2/sU6P69p7xuwEjYb3JrYETCpCaBRZzTvzDI8ZPIkjprMsiphcjKKc0+S3Mq93aTSKEKQvt2f/PUNfgXoweDbrkCNn02tKVyY/bEuLu81lrpV0pTvZgUkz994iXa8yL5hX6y8qjdwt9isRZfcOaHMroImV7AP8TLGA0edMqn1gjby+z/l5P3Rw+8BigDyKopTvdqm9bTi1emWXaZX/k7lgrqFAQKA3DPNVYGbryFNL94CmhEWm+k2TfdBd+wcR+u2x83h0VTdfKUZoqXM+k4CDUPtkDEcgmnF3ILq3LGJA/2ieY/+qgoW+h7CaCU/dSyb92O1wsAN6OFw5rLCPhuYk9L0qMvsy3f2swOYoq1Shs/dA/t3ZJR3v6eGjqEMDaHVFeR5jKD46k1/pxCo13h2p1PyjSqkmIdRHWTe6GJPE7ufQAJTUtSu9cTXot3+vthj2PM6xlUvJIYyPLSq4qJuqkNUz90dsKpRe7X5TbwfwamBI0J7VCX8HYaaroep+uysZpcqXisjYdqDx5xsyjbfE2PJQwHfKCC/Xuexytpcbe3e2a2VaRx7rSfrZhbc/qqxDek1AO3MfsVCQxdzNUvOhrx6uMeVDWp61HjZ5pG8EbR/DCmmiXKIcfqaCGhjy/RtoyWG2ZX0qN9B8XFjIl5r"}}
12.     2022-08-26 06:16:40 +1000 AEST: [event;sealing.SectorFinalized] {"User":{}}
13.     2022-08-26 06:16:40 +1000 AEST: [event;sealing.SectorSubmitCommitAggregate]     {"User":{}}
14.     2022-08-26 14:57:38 +1000 AEST: [event;sealing.SectorCommitAggregateSent]       {"User":{"Message":{"/":"bafy2bzacebtwifhwk23chyzftenbslclkpb2fc73bbbqprttqbluvtjhimnoa"}}}
15.     2022-08-26 15:01:30 +1000 AEST: [event;sealing.SectorProving]   {"User":{}}
16.     2022-08-26 15:01:30 +1000 AEST: [event;sealing.SectorFinalized] {"User":{}}
17.     2022-08-28 08:03:47 +1000 AEST: [event;sealing.SectorMarkForUpdate]     {"User":{}}
18.     2022-08-28 11:26:00 +1000 AEST: [event;sealing.SectorStartCCUpdate]     {"User":{}}
19.     2022-08-28 11:26:00 +1000 AEST: [event;sealing.SectorStartPacking]      {"User":{}}
20.     2022-08-28 11:31:27 +1000 AEST: [event;sealing.SectorPacked]    {"User":{"FillerPieces":[{"Size":34359738368,"PieceCID":{"/":"baga6ea4seaqao7s73y24kcutaosvacpdjgfe5pw76ooefnyqw4ynr3d2y6x2mpq"}}]}}

@TippyFlitsUK TippyFlitsUK added the P1 P1: Must be resolved label Sep 2, 2022
@donkabat
Copy link

donkabat commented Sep 2, 2022

lotus v1.17.1-rc3
After ~3 days of more intensive snap deals than before:
SnapDealsWaitDeals: 19
:(

@magik6k magik6k self-assigned this Sep 2, 2022
@TippyFlitsUK
Copy link
Contributor

Hey @nonsense, @SBudo, @donkabat thank you for your patience and for continuing to update this thread!!

Magik will be investigating this over the next few days!! Watch this space!! 🙏

@donkabat
Copy link

donkabat commented Sep 3, 2022 •
edited
Loading

@magik6k one more thing. Some sectors stuck in SnapDealsWaitDeals because of not enough experation time. Maybe we could add variable for time buffor and not assign sectors for deals which expire in less than: deal time + buffor time? Or maybe it's implemented already and I dont know about it?

@jhookersyd
Copy link

@magik6k When will this bug get sorted?
It's killing our performance. We have 12PiB to snap and currently, it's not possible due to this bug.

@nonsense
Copy link
Member Author

nonsense commented Sep 6, 2022

@donkabat

Some sectors stuck in SnapDealsWaitDeals because of not enough experation time.

Yes, this is indeed happening... a workaround is to have a cron job that extends sectors automatically... here is what I use: https://gist.github.com/nonsense/e0b3d2424a094f4c9ab43d8f4f2ac5d3 -- hope it is helpful.

@magik6k magik6k mentioned this issue Sep 14, 2022
Merged
@Fatman13 Fatman13 mentioned this issue Sep 19, 2022
Closed
2 tasks
@TippyFlitsUK TippyFlitsUK reopened this Oct 10, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@TippyFlitsUK TippyFlitsUK

@magik6k magik6k

Labels
area/sealing kind/bug Kind: Bug need/analysis Hint: Needs Analysis P1 P1: Must be resolved SnapDeals
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix: sealing: Abort upgrades in sectors with no deals filecoin-project/lotus
8 participants
@nonsense @TippyFlitsUK @magik6k @SBudo @Reiers @jhookersyd @donkabat and others