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

Restart the lotus market subsystem will mess up the raw data #7577

Closed
9 of 18 tasks
Araquiel opened this issue Oct 28, 2021 · 15 comments · Fixed by #7812
Closed
9 of 18 tasks

Restart the lotus market subsystem will mess up the raw data #7577

Araquiel opened this issue Oct 28, 2021 · 15 comments · Fixed by #7812
Labels
area/markets/storage kind/bug Kind: Bug P1 P1: Must be resolved team/ignite Issues and PRs being tracked by Team Ignite at Protocol Labs
Milestone
v1.15.0

Comments

@Araquiel
Copy link

Araquiel commented Oct 28, 2021 •
edited by jennijuju
Loading

Edited by @jennijuju

Restart the lotus market subsystem will mess up the raw data that has been transferred, which will create a mismatch in commP and leads to publishing, precommiting and provecommiting to fail.

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

miner/worker 1.13.0

Describe the Bug

after ever restart the lotus-miner have a problem with sealing deals in sectors
got unexpected deal CID
all data-transfers close and disable deals before resart.
happaned every restart.

Logging Information

0.      2021-10-28 11:05:31 +0500 +05:  [event;sealing.SectorStart]     {"User":{"ID":1101,"SectorType":8}}
1.      2021-10-28 11:05:31 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
2.      2021-10-28 11:06:04 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
3.      2021-10-28 11:06:04 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
4.      2021-10-28 11:06:04 +0500 +05:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqcq7npercyqcob2d3efqzxfhcyrxeabirli7xjwwphpxeoobqamcq, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai
5.      2021-10-28 11:06:04 +0500 +05:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}
6.      2021-10-28 12:33:51 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
7.      2021-10-28 12:38:48 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
8.      2021-10-28 12:38:48 +0500 +05:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqc44hh3zdirdxjavtmt7plfkuxg6pa23op3yafoooblfayi33fokq, got:baga6ea4seaqg2nsld34emra2ljfgrbrdcswmbjdpaftrpzjuipudt3w7qpbikpa
9.      2021-10-28 12:38:48 +0500 +05:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}
10.     2021-10-28 12:38:48 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
11.     2021-10-28 12:40:16 +0500 +05:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqihialc3c42ydcbqkxau25gmbv4olkwafhv3m7x3fbyo7rr343cba, got:baga6ea4seaqg2nsld34emra2ljfgrbrdcswmbjdpaftrpzjuipudt3w7qpbikpa
12.     2021-10-28 12:40:16 +0500 +05:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}

Repo Steps

  1. take a deal and wait to publish
  2. wait when lotus create sector
  3. deal can't work and sectors going to state "wait deals" when have a lot of deals in system
@Araquiel
Copy link
Author

create backup, delete <.lotusminer> folder and do clear install. then import backup and config.toml, storage.json
lost deals from lotus-miner info, but new deals work correctly.

@Shekelme
Copy link

I doubt that this issue can be closed. In my case I did not emergency restart the miner. I just restarted the miner process for deals in "Staged" state to go further (#7258).
Now I have absolutely empty sealing queue, single "WaitDeals" (but still CC) sector and the following entries in the log:

2021-10-29T07:55:02.344+0300^IERROR^Istorageadapter^Istorageadapter/provider.go:112^Ifailed to addPiece for deal 2681187, err: got unexpected piece CID: expected:baga6ea4seaqc6adbauj2k33cnxkuvnszsxklhudbtyveyytmvumn26dtxidveiq, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai$
2021-10-29T07:55:02.344+0300^IINFO^Imarkets^Iloggers/loggers.go:20^Istorage provider event^I{"name": "ProviderEventDealHandoffFailed", "proposal CID": "bafyreia5u7kmoaxkhmnn3hm7oaoabdzh4i33cots6s3blc3jkwvyb2du4q", "state": "StorageDealFailing", "message": "handing off deal to node: packing piece <nil>: AddPiece failed: got unexpected piece CID: expected:baga6ea4seaqc6adbauj2k33cnxkuvnszsxklhudbtyveyytmvumn26dtxidveiq, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai"}$
2021-10-29T07:55:02.344+0300^IWARN^Iproviderstates^Iproviderstates/provider_states.go:555^Ideal bafyreia5u7kmoaxkhmnn3hm7oaoabdzh4i33cots6s3blc3jkwvyb2du4q failed: handing off deal to node: packing piece <nil>: AddPiece failed: got unexpected piece CID: expected:baga6ea4seaqc6adbauj2k33cnxkuvnszsxklhudbtyveyytmvumn26dtxidveiq, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai$
2021-10-29T07:55:02.378+0300^IINFO^Imarkets^Iloggers/loggers.go:20^Istorage provider event^I{"name": "ProviderEventFailed", "proposal CID": "bafyreia5u7kmoaxkhmnn3hm7oaoabdzh4i33cots6s3blc3jkwvyb2du4q", "state": "StorageDealError", "message": "handing off deal to node: packing piece <nil>: AddPiece failed: got unexpected piece CID: expected:baga6ea4seaqc6adbauj2k33cnxkuvnszsxklhudbtyveyytmvumn26dtxidveiq, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai"}$

...vyb2du4q 2681187 StorageDealError f3soaazrjuc4os4mtov5miqkqtozzeemvhugamp3och7yuhk6jjndibfdmudtwblsxzjh4cgua4g3aoatqiuxa 8GiB 0.004618936 FIL 1154734

lotus-miner sectors list | tail -n 5
8123  Proving        YES      NO      2788137 (in 1 year 24 weeks)  CC
8124  Proving        YES      NO      2788145 (in 1 year 24 weeks)  CC
8125  Proving        YES      NO      2788153 (in 1 year 24 weeks)  CC
8126  Proving        YES      NO      2788181 (in 1 year 24 weeks)  CC
8127  WaitDeals      NO       NO      n/a                           CC

The sealing of the remaining deals in "Staged" state does not begin.

@RobQuistNL
Copy link
Contributor

2 fun facts;
I'm having similar issues but somehow the given CID is always got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai (so maybe thats just an empty file ending up with the same hash every time?)

3.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
4.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
5.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqd7cykp6wxk5th4m2l5wcofhnnfx7a4spq3vvplqiiaox6oh4eejy, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai
6.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}
7.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
8.      2021-11-02 16:42:31 +0000 UTC:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqfrgrxwjus5qybaandfvl33pqwtcr5evu2xisyxvglxojnyyiogoa, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai
9.      2021-11-02 16:42:31 +0000 UTC:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}
10.     2021-11-02 17:05:30 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}

Second fun fact: f3soaazrjuc4os4mtov5miqkqtozzeemvhugamp3och7yuhk6jjndibfdmudtwblsxzjh4cgua4g3aoatqiuxa is me, so if you need any client debugging, let me know

@RobQuistNL
Copy link
Contributor

This one is now stuck in PreCommit1 because there's a value mismatch. I don't think the sector should ever have started to seal in the first place;

lotus-miner sectors status --log 12105
SectorID:       12105
Status:         PreCommit1
CIDcommD:       <nil>
CIDcommR:       <nil>
Ticket:         93212fb107ddbe1a5f8aa188ae3d67fed71a23cc28f23601b0bbedcc5445eae9
TicketH:        1251381
Seed:
SeedH:          0
Precommit:      <nil>
Commit:         <nil>
Deals:          [2700760 2700761 2700762 0]
Retries:        0
--------
Event Log:
0.      2021-11-02 16:38:42 +0000 UTC:  [event;sealing.SectorStart]     {"User":{"ID":12105,"SectorType":8}}
1.      2021-11-02 16:38:42 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
2.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
3.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
4.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
5.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqd7cykp6wxk5th4m2l5wcofhnnfx7a4spq3vvplqiiaox6oh4eejy, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai
6.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}
7.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
8.      2021-11-02 16:42:31 +0000 UTC:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqfrgrxwjus5qybaandfvl33pqwtcr5evu2xisyxvglxojnyyiogoa, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai
9.      2021-11-02 16:42:31 +0000 UTC:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}
10.     2021-11-02 17:05:30 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
11.     2021-11-02 17:06:14 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
12.     2021-11-02 17:06:14 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
13.     2021-11-02 17:06:14 +0000 UTC:  [event;sealing.SectorPieceAdded]        {"User":{"NewPieces":[{"Piece":{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqocsc4uk6uhsdohd22drjrjifuufueop4is5qkopjavv7g23womoy"}},"DealInfo":{"PublishCid":{"/":"bafy2bzacecleryk6mhmt354f4r47tzxl4dxdr32zuqhcdylmpvj4icguqibhy"},"DealID":2700760,"DealProposal":{"PieceCID":{"/":"baga6ea4seaqocsc4uk6uhsdohd22drjrjifuufueop4is5qkopjavv7g23womoy"},"PieceSize":8589934592,"VerifiedDeal":true,"Client":"f3vnq2cmwig3qjisnx5hobxvsd4drn4f54xfxnv4tciw6vnjdsf5xipgafreprh5riwmgtcirpcdmi3urbg36a","Provider":"f01392893","Label":"mAXASIDeTe3V7+9lOAlffPZBjmcFJbw6CBom2rQ0HzDUaSXo8","StartEpoch":1271294,"EndEpoch":2766014,"StoragePricePerEpoch":"0","ProviderCollateral":"1324145278887388","ClientCollateral":"0"},"DealSchedule":{"StartEpoch":1271294,"EndEpoch":2766014},"KeepUnsealed":true}},{"Piece":{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqek4i4owt2cgebal6fs52y7evko36gj3h7eg5lw4ibhzh55q5i4kq"}},"DealInfo":{"PublishCid":{"/":"bafy2bzacecleryk6mhmt354f4r47tzxl4dxdr32zuqhcdylmpvj4icguqibhy"},"DealID":2700761,"DealProposal":{"PieceCID":{"/":"baga6ea4seaqek4i4owt2cgebal6fs52y7evko36gj3h7eg5lw4ibhzh55q5i4kq"},"PieceSize":8589934592,"VerifiedDeal":true,"Client":"f3vnq2cmwig3qjisnx5hobxvsd4drn4f54xfxnv4tciw6vnjdsf5xipgafreprh5riwmgtcirpcdmi3urbg36a","Provider":"f01392893","Label":"mAXASIMGLfy8IRmgJL+QJUmvTmki7sknR8gdV5qUatWG54hpN","StartEpoch":1271113,"EndEpoch":2765833,"StoragePricePerEpoch":"0","ProviderCollateral":"1324213814266270","ClientCollateral":"0"},"DealSchedule":{"StartEpoch":1271113,"EndEpoch":2765833},"KeepUnsealed":true}}]}}
14.     2021-11-02 17:06:14 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
15.     2021-11-02 17:06:38 +0000 UTC:  [event;sealing.SectorPieceAdded]        {"User":{"NewPieces":[{"Piece":{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqns4rkuwwso2vvjnqcdcgd6bqzqshfxsyxc7thejmlyn6gvyx54kq"}},"DealInfo":{"PublishCid":{"/":"bafy2bzacecleryk6mhmt354f4r47tzxl4dxdr32zuqhcdylmpvj4icguqibhy"},"DealID":2700762,"DealProposal":{"PieceCID":{"/":"baga6ea4seaqns4rkuwwso2vvjnqcdcgd6bqzqshfxsyxc7thejmlyn6gvyx54kq"},"PieceSize":8589934592,"VerifiedDeal":true,"Client":"f3vnq2cmwig3qjisnx5hobxvsd4drn4f54xfxnv4tciw6vnjdsf5xipgafreprh5riwmgtcirpcdmi3urbg36a","Provider":"f01392893","Label":"mAXASIGqbUtrtPm1H8lnfaWIvaVx+lUwb4Zr7gAerJ3y+n0Bo","StartEpoch":1271133,"EndEpoch":2765853,"StoragePricePerEpoch":"0","ProviderCollateral":"1324213348192705","ClientCollateral":"0"},"DealSchedule":{"StartEpoch":1271133,"EndEpoch":2765853},"KeepUnsealed":true}}]}}
16.     2021-11-02 17:38:42 +0000 UTC:  [event;sealing.SectorStartPacking]      {"User":{}}
17.     2021-11-02 17:40:54 +0000 UTC:  [event;sealing.SectorPacked]    {"User":{"FillerPieces":[{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai"}}]}}
18.     2021-11-02 17:40:54 +0000 UTC:  [event;sealing.SectorTicket]    {"User":{"TicketValue":"kyEvsQfdvhpfiqGIrj1n/tcaI8wo8jYBsLvtzFRF6uk=","TicketEpoch":1251381}}
19.     2021-11-02 17:44:17 +0000 UTC:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
        seal pre commit(1) failed: storage call error 0: presealing sector 12105 (/storage2/unsealed/s-t01392893-12105): pieces and comm_d do not match

Stack backtrace:
   0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
20.     2021-11-02 17:45:17 +0000 UTC:  [event;sealing.SectorRetrySealPreCommit1]       {"User":{}}
21.     2021-11-02 17:47:59 +0000 UTC:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
        seal pre commit(1) failed: storage call error 0: presealing sector 12105 (/storage2/unsealed/s-t01392893-12105): pieces and comm_d do not match

Stack backtrace:
   0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
22.     2021-11-02 17:48:59 +0000 UTC:  [event;sealing.SectorRetrySealPreCommit1]       {"User":{}}
23.     2021-11-02 17:51:44 +0000 UTC:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
        seal pre commit(1) failed: storage call error 0: presealing sector 12105 (/storage2/unsealed/s-t01392893-12105): pieces and comm_d do not match
(..........)
230.    2021-11-02 22:33:28 +0000 UTC:  [event;sealing.SectorRetrySealPreCommit1]       {"User":{}}
231.    2021-11-02 22:35:12 +0000 UTC:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
        seal pre commit(1) failed: storage call error 0: presealing sector 12105 (/storage1/unsealed/s-t01392893-12105): pieces and comm_d do not match

Stack backtrace:
   0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
232.    2021-11-02 22:36:12 +0000 UTC:  [event;sealing.SectorRetrySealPreCommit1]       {"User":{}}
233.    2021-11-02 22:37:54 +0000 UTC:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
        seal pre commit(1) failed: storage call error 0: presealing sector 12105 (/storage1/unsealed/s-t01392893-12105): pieces and comm_d do not match

Stack backtrace:
   0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
234.    2021-11-02 22:38:54 +0000 UTC:  [event;sealing.SectorRetrySealPreCommit1]       {"User":{}}
235.    2021-11-02 22:40:38 +0000 UTC:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
        seal pre commit(1) failed: storage call error 0: presealing sector 12105 (/storage1/unsealed/s-t01392893-12105): pieces and comm_d do not match

Stack backtrace:
   0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
236.    2021-11-02 22:41:38 +0000 UTC:  [event;sealing.SectorRetrySealPreCommit1]       {"User":{}}

@RobQuistNL
Copy link
Contributor

@Araquiel can you reopen this issue?

@Araquiel
Copy link
Author

Araquiel commented Nov 3, 2021 •
edited
Loading

the error reappeared after changing the sector status (changing sector and error sectors are different). 3 new sectors have "unexpected deals cid" ERROR.
cleaned all deal data and restart. after it new sectors work fine, but this is not a solution to the problem

@Araquiel Araquiel reopened this Nov 3, 2021
@Araquiel
Copy link
Author

Araquiel commented Nov 3, 2021

have 3 sectors stucked on "precommitting". remove it and restart lotus-miner. and have problem again. all new sectors have error ob log
" got unexpected piece CID:" and set "wait deals" automatically.
what is that?
after any manipulations with scheduler have that error:
after restart, after -update-state and after remove sectors.
seems like lotus-miner bug.

@Araquiel
Copy link
Author

Araquiel commented Nov 5, 2021

got stuck sectors on "wait seed" for the hours. restart miner and worker and have "unexpected deals cid" on new sector again.
have any solution of it?

@RobQuistNL
Copy link
Contributor

Just had another one, this one has no empty pieces in the middle;

~$ lotus-miner sectors status --log 14784
SectorID:       14784
Status:         PreCommit1
CIDcommD:       <nil>
CIDcommR:       <nil>
Ticket:         45b97d8e19ab40247794a325a002e9c751516f87934edecb8d8ce96c958b67d0
TicketH:        1257526
Seed:
SeedH:          0
Precommit:      <nil>
Commit:         <nil>
Deals:          [2710684 2710685 2710687 2710688]
Retries:        0
--------
Event Log:
0.      2021-11-04 20:38:30 +0000 UTC:  [event;sealing.SectorStart]     {"User":{"ID":14784,"SectorType":8}}
1.      2021-11-04 20:38:30 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
2.      2021-11-04 20:40:41 +0000 UTC:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqhhdgpo5prisz4gieiqpkfylcl72uchxwzgq3dpvz27se3gvdaeni, got:baga6ea4seaqg2nsld34emra2ljfgrbrdcswmbjdpaftrpzjuipudt3w7qpbikpa
3.      2021-11-04 20:40:41 +0000 UTC:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}
4.      2021-11-04 20:48:30 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
5.      2021-11-04 20:50:07 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
6.      2021-11-04 20:50:07 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
7.      2021-11-04 20:50:07 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
8.      2021-11-04 20:50:07 +0000 UTC:  [event;sealing.SectorPieceAdded]        {"User":{"NewPieces":[{"Piece":{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqggwi7cflqsk67s6wssqbury3ocbgydm6s6vaxk5f7m6i62cimwgq"}},"DealInfo":{"PublishCid":{"/":"bafy2bzaced3veriwjraxqmawyih7cjjtozucexovvh45xoqhomznasklumsv6"},"DealID":2710684,"DealProposal":{"PieceCID":{"/":"baga6ea4seaqggwi7cflqsk67s6wssqbury3ocbgydm6s6vaxk5f7m6i62cimwgq"},"PieceSize":8589934592,"VerifiedDeal":true,"Client":"f3vnq2cmwig3qjisnx5hobxvsd4drn4f54xfxnv4tciw6vnjdsf5xipgafreprh5riwmgtcirpcdmi3urbg36a","Provider":"f01392893","Label":"mAXASILqBsiYoiq77K5LIPdf0FQj9MHUtXG6EMSDn+1BBylG7","StartEpoch":1278150,"EndEpoch":2772870,"StoragePricePerEpoch":"0","ProviderCollateral":"1321966793030647","ClientCollateral":"0"},"DealSchedule":{"StartEpoch":1278150,"EndEpoch":2772870},"KeepUnsealed":true}}]}}
9.      2021-11-04 20:50:07 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
10.     2021-11-04 20:53:23 +0000 UTC:  [event;sealing.SectorPieceAdded]        {"User":{"NewPieces":[{"Piece":{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqbgz7kbil5ndugd6sy4km42s54cba2t4e6emcshlllrwsymesoibi"}},"DealInfo":{"PublishCid":{"/":"bafy2bzaced3veriwjraxqmawyih7cjjtozucexovvh45xoqhomznasklumsv6"},"DealID":2710685,"DealProposal":{"PieceCID":{"/":"baga6ea4seaqbgz7kbil5ndugd6sy4km42s54cba2t4e6emcshlllrwsymesoibi"},"PieceSize":8589934592,"VerifiedDeal":true,"Client":"f3vnq2cmwig3qjisnx5hobxvsd4drn4f54xfxnv4tciw6vnjdsf5xipgafreprh5riwmgtcirpcdmi3urbg36a","Provider":"f01392893","Label":"mAXASIAE3nk5sag71+t6O+XVny0+P4HuJ2q33zOMuOQ1t4yLT","StartEpoch":1278150,"EndEpoch":2772870,"StoragePricePerEpoch":"0","ProviderCollateral":"1321966793030647","ClientCollateral":"0"},"DealSchedule":{"StartEpoch":1278150,"EndEpoch":2772870},"KeepUnsealed":true}},{"Piece":{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqfiala3ocjayxq4lbkxpd6rli2rylpwhlbef5qay6x3zi6x6qbodi"}},"DealInfo":{"PublishCid":{"/":"bafy2bzaced3veriwjraxqmawyih7cjjtozucexovvh45xoqhomznasklumsv6"},"DealID":2710687,"DealProposal":{"PieceCID":{"/":"baga6ea4seaqfiala3ocjayxq4lbkxpd6rli2rylpwhlbef5qay6x3zi6x6qbodi"},"PieceSize":8589934592,"VerifiedDeal":true,"Client":"f3vnq2cmwig3qjisnx5hobxvsd4drn4f54xfxnv4tciw6vnjdsf5xipgafreprh5riwmgtcirpcdmi3urbg36a","Provider":"f01392893","Label":"mAXASIJjTOZJGFCiAerUDAhQzIWoz7NMudt/vtmrzgvczugYA","StartEpoch":1278150,"EndEpoch":2772870,"StoragePricePerEpoch":"0","ProviderCollateral":"1321966793030647","ClientCollateral":"0"},"DealSchedule":{"StartEpoch":1278150,"EndEpoch":2772870},"KeepUnsealed":true}},{"Piece":{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqfflffkut56kctytqabyles74pdfo2ssffyhfgztw7bahy4gvbkpy"}},"DealInfo":{"PublishCid":{"/":"bafy2bzaced3veriwjraxqmawyih7cjjtozucexovvh45xoqhomznasklumsv6"},"DealID":2710688,"DealProposal":{"PieceCID":{"/":"baga6ea4seaqfflffkut56kctytqabyles74pdfo2ssffyhfgztw7bahy4gvbkpy"},"PieceSize":8589934592,"VerifiedDeal":true,"Client":"f3vnq2cmwig3qjisnx5hobxvsd4drn4f54xfxnv4tciw6vnjdsf5xipgafreprh5riwmgtcirpcdmi3urbg36a","Provider":"f01392893","Label":"mAXASIMPWQ09sqBDDkLk6xvGVl1Cx6aeHmq6oMVgCdcRrklD5","StartEpoch":1278150,"EndEpoch":2772870,"StoragePricePerEpoch":"0","ProviderCollateral":"1321966793030647","ClientCollateral":"0"},"DealSchedule":{"StartEpoch":1278150,"EndEpoch":2772870},"KeepUnsealed":true}}]}}
11.     2021-11-04 20:53:23 +0000 UTC:  [event;sealing.SectorStartPacking]      {"User":{}}
12.     2021-11-04 20:53:23 +0000 UTC:  [event;sealing.SectorPacked]    {"User":{"FillerPieces":null}}
13.     2021-11-04 20:53:23 +0000 UTC:  [event;sealing.SectorTicket]    {"User":{"TicketValue":"Rbl9jhmrQCR3lKMloALpx1FRb4eTTt7LjYzpbJWLZ9A=","TicketEpoch":1257526}}
14.     2021-11-04 20:56:27 +0000 UTC:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
        seal pre commit(1) failed: storage call error 0: presealing sector 14784 (/storage2/unsealed/s-t01392893-14784): pieces and comm_d do not match

Stack backtrace:
   0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
15.     2021-11-04 20:57:27 +0000 UTC:  [event;sealing.SectorRetrySealPreCommit1]       {"User":{}}
16.     2021-11-04 21:03:05 +0000 UTC:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
        seal pre commit(1) failed: storage call error 0: presealing sector 14784 (/storage3/unsealed/s-t01392893-14784): pieces and comm_d do not match

Stack backtrace:
   0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
17.     2021-11-04 21:04:05 +0000 UTC:  [event;sealing.SectorRetrySealPreCommit1]       {"User":{}}
18.     2021-11-04 21:07:44 +0000 UTC:  [event;sealing.SectorSealPreCommit1Failed]      {"User":{}}
        seal pre commit(1) failed: storage call error 0: presealing sector 14784 (/storage2/unsealed/s-t01392893-14784): pieces and comm_d do not match

@Araquiel
Copy link
Author

Araquiel commented Nov 6, 2021 •
edited
Loading

2 fun facts; I'm having similar issues but somehow the given CID is always got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai (so maybe thats just an empty file ending up with the same hash every time?)

3.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
4.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
5.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqd7cykp6wxk5th4m2l5wcofhnnfx7a4spq3vvplqiiaox6oh4eejy, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai
6.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}
7.      2021-11-02 16:41:40 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
8.      2021-11-02 16:42:31 +0000 UTC:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqfrgrxwjus5qybaandfvl33pqwtcr5evu2xisyxvglxojnyyiogoa, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai
9.      2021-11-02 16:42:31 +0000 UTC:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}
10.     2021-11-02 17:05:30 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}

Second fun fact: f3soaazrjuc4os4mtov5miqkqtozzeemvhugamp3och7yuhk6jjndibfdmudtwblsxzjh4cgua4g3aoatqiuxa is me, so if you need any client debugging, let me know

Event Log:
0.      2021-11-06 17:27:19 +0500 +05:  [event;sealing.SectorStart]     {"User":{"ID":1269,"SectorType":8}}
1.      2021-11-06 17:27:19 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
2.      2021-11-06 17:37:28 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
3.      2021-11-06 17:37:28 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
4.      2021-11-06 17:37:28 +0500 +05:  [event;sealing.SectorAddPiece]  {"User":{}}
5.      2021-11-06 17:37:28 +0500 +05:  [event;sealing.SectorAddPieceFailed]    {"User":{}}
        got unexpected piece CID: expected:baga6ea4seaqd7ovwpgukxknl4hoa44xkfxe3pwrib4ktuhe4zjphzqqukukjala, got:baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai
6.      2021-11-06 17:37:28 +0500 +05:  [event;sealing.SectorRetryWaitDeals]    {"User":{}}

what are doing with it? have some sulution?
image

image

@stuberman
Copy link

Running v1.13.2-rc2 and sometimes see this issue as well, particularly after a Market node crash
Result is that a sector goes to WaitDeals as a CC sector after the deal is published.

From lotus-miner logs

2021-12-09T13:40:00.654Z INFO sectors storage-sealing/input.go:256 Adding piece for deal 2855857 (publish msg: bafy2bzaceahldlakuy7jkyu42ta3yq7dfy5dqoheb2urp5hnjfdjbpufclzk6)
2021-12-09T13:40:00.735Z WARN advmgr sector-storage/manager.go:274 stub NewSector
2021-12-09T13:40:00.735Z INFO sectors storage-sealing/input.go:454 Creating sector {"number": "2881", "type": "deal", "proofType": 8}
2021-12-09T13:40:00.844Z DEBUG advmgr sector-storage/sched.go:356 SCHED 1 queued; 4 open windows
2021-12-09T13:40:00.850Z DEBUG advmgr sector-storage/sched.go:452 SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]}]
2021-12-09T13:40:00.850Z DEBUG advmgr sector-storage/sched.go:453 SCHED Acceptable win: [[2 3]]
2021-12-09T13:40:00.850Z DEBUG advmgr sector-storage/sched.go:467 SCHED try assign sqi:0 sector 2881 to window 2
2021-12-09T13:40:00.850Z DEBUG advmgr sector-storage/sched.go:476 SCHED ASSIGNED sqi:0 sector 2881 task seal/v0/addpiece to window 2
2021-12-09T13:40:00.850Z DEBUG advmgr sector-storage/sched_worker.go:375 assign worker sector 2881
2021-12-09T13:40:00.851Z DEBUG advmgr sector-storage/sched.go:356 SCHED 0 queued; 4 open windows
2021-12-09T13:40:00.851Z DEBUG advmgr sector-storage/sched_worker.go:280 task done {"workerid": "a0dcd718-0a1d-40f5-94c9-3a48bdd2874e"}
2021-12-09T13:40:00.852Z DEBUG advmgr sector-storage/sched.go:356 SCHED 0 queued; 4 open windows
2021-12-09T13:42:27.098Z WARN rpc go-jsonrpc@v0.1.5/handler.go:279 error in RPC call to 'Filecoin.SectorAddPieceToAny': got unexpected piece CID: expected:baga6ea4seaqgavm3awhvbnjw5bpzkqyynmjqdq4uqkwcsvgrjykfywi433unkeq, got:baga6ea4seaqg2nsld34emra2ljfgrbrdcswmbjdpaftrpzjuipudt3w7qpbikpa:
github.com/filecoin-project/lotus/extern/storage-sealing.(*Sealing).handleAddPiece
/home/stuart/lotus/extern/storage-sealing/input.go:230
2021-12-09T13:42:27.098Z WARN sectors storage-sealing/fsm.go:622 sector 2881 got error event sealing.SectorAddPieceFailed: got unexpected piece CID: expected:baga6ea4seaqgavm3awhvbnjw5bpzkqyynmjqdq4uqkwcsvgrjykfywi433unkeq, got:baga6ea4seaqg2nsld34emra2ljfgrbrdcswmbjdpaftrpzjuipudt3w7qpbikpa

@jennijuju jennijuju added area/markets/storage P1 P1: Must be resolved team/ignite Issues and PRs being tracked by Team Ignite at Protocol Labs and removed need/triage labels Dec 9, 2021
@jennijuju jennijuju added this to the v1.13.3 milestone Dec 9, 2021
@jennijuju jennijuju changed the title can't seal deals in sector Restart the lotus market subsystem will mess up the raw data Dec 9, 2021
@stuberman
Copy link

See more of these on v1.13.2-rc2. I had cleared out the backlog of old stuck deals and rebooted the markets node to start fresh. A few hours later I received two deals from Estuary which failed. here is that miner log

2021-12-10T01:48:30.551Z INFO sectors storage-sealing/input.go:256 Adding piece for deal 2858272 (publish msg: bafy2bzacedy4c6fjlom4qmbzcurcwnar63eepijmxiaiffpmpujm4oe7uurzc)
2021-12-10T01:48:30.553Z INFO sectors storage-sealing/input.go:256 Adding piece for deal 2858271 (publish msg: bafy2bzacedy4c6fjlom4qmbzcurcwnar63eepijmxiaiffpmpujm4oe7uurzc)
2021-12-10T01:48:30.587Z DEBUG advmgr sector-storage/sched.go:356 SCHED 1 queued; 4 open windows
2021-12-10T01:48:30.592Z DEBUG advmgr sector-storage/sched.go:452 SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]}]
2021-12-10T01:48:30.592Z DEBUG advmgr sector-storage/sched.go:453 SCHED Acceptable win: [[0 1]]
2021-12-10T01:48:30.592Z DEBUG advmgr sector-storage/sched.go:467 SCHED try assign sqi:0 sector 2882 to window 0
2021-12-10T01:48:30.592Z DEBUG advmgr sector-storage/sched.go:476 SCHED ASSIGNED sqi:0 sector 2882 task seal/v0/addpiece to window 0
2021-12-10T01:48:30.592Z DEBUG advmgr sector-storage/sched_worker.go:375 assign worker sector 2882
2021-12-10T01:48:30.592Z DEBUG advmgr sector-storage/sched.go:356 SCHED 0 queued; 4 open windows
2021-12-10T01:48:30.592Z DEBUG advmgr sector-storage/sched_worker.go:280 task done {"workerid": "a0dcd718-0a1d-40f5-94c9-3a48bdd2874e"}
2021-12-10T01:48:30.593Z DEBUG advmgr sector-storage/sched.go:356 SCHED 0 queued; 4 open windows
2021-12-10T01:48:36.010Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 7, "forRound": 1359818, "baseEpoch": 1359817, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455662, "lookbackEpochs": 900, "networkPowerAtLookback": "16177654392497504256", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:49:06.009Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359819, "baseEpoch": 1359818, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455663, "lookbackEpochs": 900, "networkPowerAtLookback": "16177712116857962496", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:49:36.183Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359820, "baseEpoch": 1359819, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455664, "lookbackEpochs": 900, "networkPowerAtLookback": "16177631405832536064", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:50:06.361Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359821, "baseEpoch": 1359820, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455665, "lookbackEpochs": 900, "networkPowerAtLookback": "16177631405832536064", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:50:36.344Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359822, "baseEpoch": 1359821, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455666, "lookbackEpochs": 900, "networkPowerAtLookback": "16177625702115966976", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:50:55.818Z INFO sectors storage-sealing/input.go:235 deal added to a sector {"deal": 2858272, "sector": "2882", "piece": "baga6ea4seaqbckf244y672h6rtjs3a6ax4it6usikq22zz53uxmxf7rrr522egq"}
2021-12-10T01:50:55.819Z DEBUG advmgr sector-storage/sched.go:356 SCHED 1 queued; 4 open windows
2021-12-10T01:50:55.822Z DEBUG advmgr sector-storage/sched.go:452 SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]}]
2021-12-10T01:50:55.822Z DEBUG advmgr sector-storage/sched.go:453 SCHED Acceptable win: [[0 3]]
2021-12-10T01:50:55.823Z DEBUG advmgr sector-storage/sched.go:467 SCHED try assign sqi:0 sector 2882 to window 0
2021-12-10T01:50:55.823Z DEBUG advmgr sector-storage/sched.go:476 SCHED ASSIGNED sqi:0 sector 2882 task seal/v0/addpiece to window 0
2021-12-10T01:50:55.823Z DEBUG advmgr sector-storage/sched_worker.go:375 assign worker sector 2882
2021-12-10T01:50:55.823Z DEBUG advmgr sector-storage/sched.go:356 SCHED 0 queued; 4 open windows
2021-12-10T01:50:55.823Z DEBUG advmgr sector-storage/sched_worker.go:280 task done {"workerid": "a0dcd718-0a1d-40f5-94c9-3a48bdd2874e"}
2021-12-10T01:50:55.823Z DEBUG advmgr sector-storage/sched.go:356 SCHED 0 queued; 4 open windows
2021-12-10T01:51:06.269Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359823, "baseEpoch": 1359822, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455667, "lookbackEpochs": 900, "networkPowerAtLookback": "16177625702115966976", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:51:36.009Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359824, "baseEpoch": 1359823, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455668, "lookbackEpochs": 900, "networkPowerAtLookback": "16177625702115966976", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:52:06.008Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359825, "baseEpoch": 1359824, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455669, "lookbackEpochs": 900, "networkPowerAtLookback": "16177625358518583296", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:52:36.153Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359826, "baseEpoch": 1359825, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455670, "lookbackEpochs": 900, "networkPowerAtLookback": "16177625427238060032", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:53:06.008Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 5, "forRound": 1359827, "baseEpoch": 1359826, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455671, "lookbackEpochs": 900, "networkPowerAtLookback": "16177625427238060032", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:53:21.037Z INFO sectors storage-sealing/input.go:235 deal added to a sector {"deal": 2858271, "sector": "2882", "piece": "baga6ea4seaqlltf5n7fsv2ul66jjswtlp6zjfbqosfjc2vaa5oujw5dqi7j7qhy"}
2021-12-10T01:53:21.051Z INFO sectors storage-sealing/input.go:108 starting to seal deal sector {"sector": "2882", "trigger": "filled"}
2021-12-10T01:53:21.053Z DEBUG advmgr sector-storage/manager.go:223 acquire unseal sector lock for sector {1278 2882}
2021-12-10T01:53:21.054Z WARN rpc go-jsonrpc@v0.1.5/handler.go:279 error in RPC call to 'Filecoin.SectorsUnsealPiece': cannot unseal piece (sector: {{1278 2882} 8}, offset: 0 size: 17045651456) - unsealed cid is undefined:
github.com/filecoin-project/lotus/extern/sector-storage.(*Manager).SectorsUnsealPiece
/home/stuart/lotus/extern/sector-storage/manager.go:240
2021-12-10T01:53:21.065Z INFO sectors storage-sealing/states_sealing.go:48 performing filling up rest of the sector... {"sector": "2882"}
2021-12-10T01:53:21.066Z DEBUG advmgr sector-storage/manager.go:223 acquire unseal sector lock for sector {1278 2882}
2021-12-10T01:53:21.066Z WARN rpc go-jsonrpc@v0.1.5/handler.go:279 error in RPC call to 'Filecoin.SectorsUnsealPiece': cannot unseal piece (sector: {{1278 2882} 8}, offset: 0 size: 17045651456) - unsealed cid is undefined:
github.com/filecoin-project/lotus/extern/sector-storage.(*Manager).SectorsUnsealPiece
/home/stuart/lotus/extern/sector-storage/manager.go:240
2021-12-10T01:53:21.071Z DEBUG advmgr sector-storage/manager.go:223 acquire unseal sector lock for sector {1278 2882}
2021-12-10T01:53:21.071Z WARN rpc go-jsonrpc@v0.1.5/handler.go:279 error in RPC call to 'Filecoin.SectorsUnsealPiece': cannot unseal piece (sector: {{1278 2882} 8}, offset: 0 size: 17045651456) - unsealed cid is undefined:
github.com/filecoin-project/lotus/extern/sector-storage.(*Manager).SectorsUnsealPiece
/home/stuart/lotus/extern/sector-storage/manager.go:240
2021-12-10T01:53:21.106Z DEBUG advmgr sector-storage/sched.go:356 SCHED 1 queued; 4 open windows
2021-12-10T01:53:21.110Z DEBUG advmgr sector-storage/sched.go:452 SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond: waiting:0} todo:[]}]
2021-12-10T01:53:21.110Z DEBUG advmgr sector-storage/sched.go:453 SCHED Acceptable win: [[2 3]]
2021-12-10T01:53:21.110Z DEBUG advmgr sector-storage/sched.go:467 SCHED try assign sqi:0 sector 2882 to window 2
2021-12-10T01:53:21.110Z DEBUG advmgr sector-storage/sched.go:476 SCHED ASSIGNED sqi:0 sector 2882 task seal/v0/precommit/1 to window 2
2021-12-10T01:53:21.110Z DEBUG advmgr sector-storage/sched_worker.go:375 assign worker sector 2882
2021-12-10T01:53:21.110Z DEBUG advmgr sector-storage/sched.go:356 SCHED 0 queued; 4 open windows
2021-12-10T01:53:21.113Z DEBUG advmgr sector-storage/sched_worker.go:280 task done {"workerid": "a0dcd718-0a1d-40f5-94c9-3a48bdd2874e"}
2021-12-10T01:53:21.113Z DEBUG advmgr sector-storage/sched.go:356 SCHED 0 queued; 4 open windows
2021-12-10T01:53:21.544Z DEBUG advmgr sector-storage/manager.go:223 acquire unseal sector lock for sector {1278 2882}
2021-12-10T01:53:36.264Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359828, "baseEpoch": 1359827, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455672, "lookbackEpochs": 900, "networkPowerAtLookback": "16177643530433626112", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:54:06.327Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 8, "forRound": 1359829, "baseEpoch": 1359828, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455673, "lookbackEpochs": 900, "networkPowerAtLookback": "16177643805311533056", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:54:36.258Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359830, "baseEpoch": 1359829, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455674, "lookbackEpochs": 900, "networkPowerAtLookback": "16177643805311533056", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:55:06.448Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359831, "baseEpoch": 1359830, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455675, "lookbackEpochs": 900, "networkPowerAtLookback": "16177640953453248512", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:55:34.468Z WARN rpc go-jsonrpc@v0.1.5/handler.go:279 error in RPC call to 'Filecoin.SectorsUnsealPiece': cannot unseal piece (sector: {{1278 2882} 8}, offset: 17045651456 size: 17045651456) - unsealed cid is undefined:
github.com/filecoin-project/lotus/extern/sector-storage.(*Manager).SectorsUnsealPiece
/home/stuart/lotus/extern/sector-storage/manager.go:240
2021-12-10T01:55:34.468Z WARN sectors storage-sealing/fsm.go:622 sector 2882 got error event sealing.SectorSealPreCommit1Failed: seal pre commit(1) failed: storage call error 0: presealing sector 2882 (/seal2/worker/unsealed/s-t01278-2882): pieces and comm_d do not match

Stack backtrace:
0: anyhow::private::new_adhoc
1: filecoin_proofs::api::seal::seal_pre_commit_phase1
2: filecoin_proofs_api::seal::seal_pre_commit_phase1_inner
3: filecoin_proofs_api::seal::seal_pre_commit_phase1
4: <std::panic::AssertUnwindSafe as core::ops::function::FnOnce<()>>::call_once
5: ffi_toolkit::catch_panic_response
6: fil_seal_pre_commit_phase1
7: _cgo_fe0a164c3578_Cfunc_fil_seal_pre_commit_phase1
at /tmp/go-build/cgo-gcc-prolog:1312:11
8: runtime.asmcgocall
at /usr/local/go/src/runtime/asm_amd64.s:667
2021-12-10T01:55:34.483Z INFO sectors storage-sealing/states_failed.go:26 SealPreCommit1Failed(2882), waiting 59.516997093s before retrying
2021-12-10T01:55:36.010Z INFO miner miner/miner.go:479 completed mineOne {"tookMilliseconds": 6, "forRound": 1359832, "baseEpoch": 1359831, "baseDeltaSeconds": 6, "nullRounds": 0, "lateStart": false, "beaconEpoch": 1455676, "lookbackEpochs": 900, "networkPowerAtLookback": "16177640953453248512", "minerPowerAtLookback": "512340459257856", "isEligible": true, "isWinner": false, "error": null}
2021-12-10T01:55:42.926Z DEBUG advmgr sector-storage/manager.go:223 acquire unseal sector lock for sector {1278 2882}
2021-12-10T01:55:42.926Z WARN rpc go-jsonrpc@v0.1.5/handler.go:279 error in RPC call to 'Filecoin.SectorsUnsealPiece': cannot unseal piece (sector: {{1278 2882} 8}, offset: 17045651456 size: 17045651456) - unsealed cid is undefined:
github.com/filecoin-project/lotus/extern/sector-storage.(*Manager).SectorsUnsealPiece
/home/stuart/lotus/extern/sector-storage/manager.go:240

@stuberman
Copy link

Same two deals from worker log

2021-12-10T01:48:30.593Z DEBUG advmgr sector-storage/worker_local.go:140 acquired sector {{1278 2882} 8} (e:0; a:1): {{0 0} /seal/worker/unsealed/s-t01278-2882 }
2021-12-10T01:48:33.161Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:48:33.397Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:48:35.341Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:48:45.342Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:48:55.344Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:49:05.345Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:49:15.352Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:49:25.354Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:49:35.355Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:49:37.326Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:49:37.552Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:49:45.356Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:49:55.358Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:50:05.493Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:50:15.495Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:50:25.497Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:50:35.498Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:50:41.300Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:50:41.571Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:50:45.500Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:50:55.501Z WARN stores stores/local.go:138 negative reserved storage: p.reserved=34359738368, reserved: -8192
2021-12-10T01:50:55.811 INFO filcrypto::proofs::api > generate_data_commitment: start
2021-12-10T01:50:55.812 INFO filcrypto::proofs::api > generate_data_commitment: finish
2021-12-10T01:50:55.820Z DEBUG advmgr sector-storage/worker_local.go:140 acquired sector {{1278 2882} 8} (e:1; a:0): {{0 0} /seal/worker/unsealed/s-t01278-2882 }
2021-12-10T01:53:21.030 INFO filcrypto::proofs::api > generate_data_commitment: start
2021-12-10T01:53:21.031 INFO filcrypto::proofs::api > generate_data_commitment: finish
2021-12-10T01:53:21.034Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.041Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.042Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.042Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.045Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.045Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.046Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.047Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.054Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.054Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.055Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.055Z DEBUG stores stores/http_handler.go:281 returning ok: worker has unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.059Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.059Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.060Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.060Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.064Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.064Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.065Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/0/17045651456
2021-12-10T01:53:21.066Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:0, size:17045651456
2021-12-10T01:53:21.107Z DEBUG advmgr sector-storage/worker_local.go:140 acquired sector {{1278 2882} 8} (e:1; a:0): {{0 0} /seal/worker/unsealed/s-t01278-2882 }
2021-12-10T01:53:21.117Z DEBUG advmgr sector-storage/worker_local.go:140 acquired sector {{1278 2882} 8} (e:1; a:6): {{0 0} /seal2/worker/unsealed/s-t01278-2882 /seal/worker/sealed/s-t01278-2882 /seal/worker/cache/s-t01278-2882}
2021-12-10T01:53:21.118 INFO filcrypto::proofs::api > seal_pre_commit_phase1: start
2021-12-10T01:53:21.118 INFO filecoin_proofs::api::seal > seal_pre_commit_phase1:start: SectorId(2882)
2021-12-10T01:53:21.531Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:53:21.532Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:53:21.533Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:53:21.533Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:53:21.536Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:53:21.537Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:53:21.538Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:53:21.538Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:34.422 INFO filcrypto::proofs::api > seal_pre_commit_phase1: finish
2021-12-10T01:55:42.738Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:55:42.739Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:42.740Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:55:42.740Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:42.744Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:55:42.744Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:42.745Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:55:42.745Z DEBUG stores stores/http_handler.go:281 returning ok: worker has unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:42.747Z INFO stores stores/http_handler.go:87 SERVE GET /remote/unsealed/s-t01278-2882
2021-12-10T01:55:42.908Z DEBUG stores stores/http_handler.go:155 served sector file/dir, sectorID={Miner:1278 Number:2882}, fileType=unsealed, path=/seal/worker/unsealed/s-t01278-2882
2021-12-10T01:55:42.913Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:55:42.913Z DEBUG stores stores/http_handler.go:281 returning ok: worker has unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:42.918Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:55:42.918Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:42.920Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:55:42.920Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:42.926Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:55:42.927Z DEBUG stores stores/http_handler.go:286 returning StatusRequestedRangeNotSatisfiable: worker does NOT have unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:42.928Z INFO stores stores/http_handler.go:187 SERVE Alloc check /remote/unsealed/s-t01278-2882/8/allocated/17045651456/17045651456
2021-12-10T01:55:42.928Z DEBUG stores stores/http_handler.go:281 returning ok: worker has unsealed file with unsealed piece, sector:{Miner:1278 Number:2882}, offset:17045651456, size:17045651456
2021-12-10T01:55:42.929Z INFO stores stores/http_handler.go:87 SERVE GET /remote/unsealed/s-t01278-2882
2021-12-10T01:56:34.073Z DEBUG advmgr sector-storage/worker_local.go:140 acquired sector {{1278 2882} 8} (e:1; a:0): {{0 0} /seal2/worker/unsealed/s-t01278-2882 }
2021-12-10T01:56:34.086Z INFO stores stores/local.go:639 remove /seal/worker/sealed/s-t01278-2882
2021-12-10T01:56:36.707Z INFO stores stores/local.go:639 remove /seal/worker/cache/s-t01278-2882
2021-12-10T01:56:41.478Z DEBUG advmgr sector-storage/worker_local.go:140 acquired sector {{1278 2882} 8} (e:1; a:6): {{0 0} /seal2/worker/unsealed/s-t01278-2882 /seal/worker/sealed/s-t01278-2882 /seal/worker/cache/s-t01278-2882}
2021-12-10T01:56:41.478 INFO filcrypto::proofs::api > seal_pre_commit_phase1: start
2021-12-10T01:56:41.478 INFO filecoin_proofs::api::seal > seal_pre_commit_phase1:start: SectorId(2882)
2021-12-10T01:57:28.969Z DEBUG stores stores/http_handler.go:155 served sector file/dir, sectorID={Miner:1278 Number:2882}, fileType=unsealed, path=/seal2/worker/unsealed/s-t01278-2882
2021-12-10T01:59:27.001 INFO filcrypto::proofs::api > seal_pre_commit_phase1: finish

@stuberman
Copy link

Logs from market node

markets.log

@dirkmc
Copy link
Contributor

dirkmc commented Dec 16, 2021 •
edited
Loading

We believe the underlying issue is that:

  1. The markets process is in the middle of sending data to the miner process
  2. The user restarts the miner
  3. The markets process reconnects to the miner process and continues sending data from the same place in the stream (instead of starting from zero)

The fix we need to make is:
Change the markets process to ensure that each time it retries add piece, it seeks to the beginning of the data source.

This was referenced Dec 17, 2021
Merged
Closed
magik6k added a commit that referenced this issue Dec 21, 2021
@magik6k
Merge pull request #7812 from filecoin-project/feat/retry-ap-seek-start
c755cee 
fix: #7577 markets: When retrying Add Piece, first seek to start of reader
@jennijuju jennijuju removed this from the v1.13.3 milestone Jan 2, 2022
@jennijuju jennijuju added this to the v1.15.0 milestone Jan 2, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/markets/storage kind/bug Kind: Bug P1 P1: Must be resolved team/ignite Issues and PRs being tracked by Team Ignite at Protocol Labs
Projects
None yet
Milestone
v1.15.0
Development

Successfully merging a pull request may close this issue.

fix: #7577 markets: When retrying Add Piece, first seek to start of reader filecoin-project/lotus
6 participants
@dirkmc @RobQuistNL @Araquiel @Shekelme @jennijuju @stuberman