Deals that are in RecoverDealIds are not recovering/

[jennijuju]

Lotus version: 0.5.10

Note: One of the community member said that he did update-state ... Removing, which understandably freaked out the FSM (ERROR: normal shutdown of state machine) but seemingly resolved upon restarting the miner.

-One of the given error message:

Filecoin.StateMarketStorageDeal': deal id not found

• Another one:

can't fix sector deals: piece 1 (of 118) of sector 70 refers expired deal 69211 - should start at 31304, head 31413:

• suspicion: the message that has the deal id got re-orged out of the network?

[Storage-Hive]

From miner log:
2020-09-03T21:13:50.927-0400 INFO sectors storage-sealing/sealing.go:236 Starting packing sector 70
2020-09-03T21:13:50.927-0400 INFO sectors storage-sealing/sealing.go:241 send Starting packing event success sector 70
2020-09-03T21:13:50.930-0400 WARN sectors storage-sealing/states_sealing.go:41 Creating 4 filler pieces for sector 70
2020-09-03T21:13:50.938-0400 DEBUG advmgr sector-storage/sched.go:430 SCHED try assign sqi:0 sector 70 to window 7
2020-09-03T21:13:50.938-0400 DEBUG advmgr sector-storage/sched.go:437 SCHED ASSIGNED sqi:0 sector 70 task seal/v0/addpiece to window 7
2020-09-03T21:13:50.938-0400 DEBUG advmgr sector-storage/sched.go:596 assign worker sector 70
2020-09-03T21:14:08.836-0400 DEBUG advmgr sector-storage/sched.go:430 SCHED try assign sqi:0 sector 70 to window 8
2020-09-03T21:14:08.836-0400 DEBUG advmgr sector-storage/sched.go:437 SCHED ASSIGNED sqi:0 sector 70 task seal/v0/addpiece to window 8
2020-09-03T21:14:08.836-0400 DEBUG advmgr sector-storage/sched.go:596 assign worker sector 70
2020-09-03T21:15:26.881-0400 DEBUG advmgr sector-storage/sched.go:430 SCHED try assign sqi:0 sector 70 to window 8
2020-09-03T21:15:26.881-0400 DEBUG advmgr sector-storage/sched.go:437 SCHED ASSIGNED sqi:0 sector 70 task seal/v0/addpiece to window 8
2020-09-03T21:15:26.881-0400 DEBUG advmgr sector-storage/sched.go:596 assign worker sector 70
2020-09-03T21:18:06.085-0400 DEBUG advmgr sector-storage/sched.go:430 SCHED try assign sqi:0 sector 70 to window 8
2020-09-03T21:18:06.085-0400 DEBUG advmgr sector-storage/sched.go:437 SCHED ASSIGNED sqi:0 sector 70 task seal/v0/addpiece to window 8
2020-09-03T21:18:06.085-0400 DEBUG advmgr sector-storage/sched.go:596 assign worker sector 70
2020-09-03T21:23:23.396-0400 DEBUG advmgr sector-storage/sched.go:430 SCHED try assign sqi:0 sector 70 to window 9
2020-09-03T21:23:23.396-0400 DEBUG advmgr sector-storage/sched.go:437 SCHED ASSIGNED sqi:0 sector 70 task seal/v0/precommit/1 to window 9
2020-09-04T01:13:19.362-0400 DEBUG advmgr sector-storage/sched.go:596 assign worker sector 70
2020-09-04T11:33:52.763-0400 DEBUG advmgr sector-storage/sched.go:430 SCHED try assign sqi:0 sector 70 to window 9
2020-09-04T11:33:52.763-0400 DEBUG advmgr sector-storage/sched.go:437 SCHED ASSIGNED sqi:0 sector 70 task seal/v0/precommit/2 to window 9
2020-09-04T12:12:48.883-0400 DEBUG advmgr sector-storage/sched.go:596 assign worker sector 70
2020-09-04T15:46:39.943-0400 WARN sectors storage-sealing/states_sealing.go:161 invalid deals in sector 70: getting deal 67264 for piece 0: deal 67264 not found
2020-09-04T15:46:39.947-0400 ERROR sectors storage-sealing/fsm.go:28 unhandled sector error (70): can't fix sector deals: piece 1 (of 118) of sector 70 refers expired deal 69211 - should start at 31304, head 31413:
lotus-miner sectors status 70 --log
SectorID: 70
Status: RecoverDealIDs
CIDcommD: baga6ea4seaqpgwh3yk7t4w627v5wtchf7fdspvtl62aie6zlmjmk5lwehfayqly
CIDcommR: bagboea4b5abcao55xre6ncxcms7shtl5iroa3k6cj5popnhcdbvedy6vkhhu2zib
Ticket: 70535d95ba4fd2da270e024b62784db40c97077a2af45c512c0107ac4a449cb5
TicketH: 28305
Seed:
SeedH: 0
Precommit:
Commit:
Proof:
Deals: [67264 69211 66608 64028 0 0 0 0 0 0 0 0 0 70293 63776 66134 0 0 0 0 0 0 0 0 0 64297 65861 0 0 0 0 0 0 0 0 0 0 72426 65069 0 0 0 0 0 0 0 0 0 0 68090 65673 67096 0 0 0 0 0 0 0 0 0 0 69051 65335 62039 0 0 0 0 0 0 0 0 0 0 71623 71016 66343 0 0 0 0 0 0 0 0 0 67764 63282 68695 66791 0 0 0 0 0 0 0 0 0 0 67518 69493 64565 0 0 0 0 0 0 0 0 0 68400 0 0 0 0]

[William8Work]

the logs if helps troubleshootign:

daemon - see the dea 51724 error:
2020-09-04T14:33:03.705-0700 WARN rpc go-jsonrpc@v0.1.2-0.20200822201400-474f4fdccc52/handler.go:241 error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 51724 not found:
2020-09-04T15:20:46.255-0700 WARN rpc go-jsonrpc@v0.1.2-0.20200822201400-474f4fdccc52/handler.go:241 error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 51724 not found:
2020-09-04T15:20:46.350-0700 WARN rpc go-jsonrpc@v0.1.2-0.20200822201400-474f4fdccc52/handler.go:241 error in RPC call to 'Filecoin.StateMarketStorageDeal': deal 51724 not found:

Inside the miner storage deal list of this deal id:
$ lotus-miner storage-deals list | grep 51724
...5fi453du 51724 StorageDealError t3rey7pw2asdskrqpretcbnxjczkyr4lyindagouytbxtigbhihdwz4sxfwhf5m4cpofdd23huxraq4tmwmera 8MiB 0.00007539275 FIL 603142

Inside the miner on this specific sector involved with this deal:
lotus-miner sectors list | grep 51724
35: RecoverDealIDs sSet: NO active: NO tktH: 19350 seedH: 0 deals: [51724 51803 51880 0 0 0 0 0 0 0 0 0 0 0]

[maxvint]

Lotus version: 0.10.0
For miner log:

2020-10-16T14:36:28.439+0800	WARN	sectors	storage-sealing/states_sealing.go:92	invalid deals in sector 3846: getting deal 629941 for piece 0: deal 629941 not found
2020-10-16T14:36:28.464+0800	WARN	sectors	storage-sealing/states_sealing.go:92	invalid deals in sector 4320: getting deal 628458 for piece 0: deal 628458 not found
2020-10-16T14:36:28.520+0800	WARN	sectors	storage-sealing/states_sealing.go:92	invalid deals in sector 4180: getting deal 630069 for piece 0: deal 630069 not found
2020-10-16T14:36:28.567+0800	WARN	sectors	storage-sealing/states_sealing.go:92	invalid deals in sector 3980: getting deal 628146 for piece 0: deal 628146 not found
2020-10-16T14:36:28.596+0800	WARN	sectors	storage-sealing/states_sealing.go:92	invalid deals in sector 4140: getting deal 628146 for piece 0: deal 628146 not found
2020-10-16T14:36:31.178+0800	WARN	sectors	storage-sealing/states_sealing.go:92	invalid deals in sector 4312: getting deal 652718 for piece 0: deal 652718 not found
2020-10-16T14:36:31.481+0800	WARN	sectors	storage-sealing/states_sealing.go:92	invalid deals in sector 4342: getting deal 649129 for piece 0: deal 649129 not found
2020-10-16T14:36:31.484+0800	WARN	sectors	storage-sealing/states_sealing.go:92	invalid deals in sector 4329: getting deal 648735 for piece 0: deal 648735 not found

For lotus-miner sector-status log:

0.	2020-10-16 13:55:28 +0800 CST:	[event;sealing.SectorStart]	{"User":{"ID":4342,"SectorType":3}}
1.	2020-10-16 13:57:20 +0800 CST:	[event;sealing.SectorAddPiece]	{"User":{"NewPiece":{"Piece":{"Size":4294967296,"PieceCID":{"/":"baga6ea4seaqhmrr257c2dc4shu6qyinpjn6uopvaphxlb7v2yimrntjejv4koba"}},"DealInfo":{"PublishCid":{"/":"bafy2bzacebo73bx5l2eehrn7zcxv3q2lvi3lgduk23fyqprcncgyxttxjx6hm"},"DealID":637227,"DealSchedule":{"StartEpoch":147378,"EndEpoch":672372},"KeepUnsealed":true}}}}
2.	2020-10-16 14:07:40 +0800 CST:	[event;sealing.SectorStartPacking]	{"User":{}}
3.	2020-10-16 14:17:43 +0800 CST:	[event;sealing.SectorPacked]	{"User":{"FillerPieces":[{"Size":4294967296,"PieceCID":{"/":"baga6ea4seaqgntqfunthkuwpixacxtcoqojjdg66vq254l7vmjyyjdu7pntvcby"}},{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai"}},{"Size":17179869184,"PieceCID":{"/":"baga6ea4seaqg2nsld34emra2ljfgrbrdcswmbjdpaftrpzjuipudt3w7qpbikpa"}}]}}
4.	2020-10-16 14:17:43 +0800 CST:	[event;sealing.SectorInvalidDealIDs]	{"User":{"Return":"PreCommit1"}}
5.	2020-10-16 14:17:52 +0800 CST:	[event;sealing.SectorUpdateDealIDs]	{"User":{"Updates":{"0":649129}}}
6.	2020-10-16 14:17:52 +0800 CST:	[event;sealing.SectorInvalidDealIDs]	{"User":{"Return":"PreCommit1"}}
7.	2020-10-16 14:18:02 +0800 CST:	[event;sealing.SectorUpdateDealIDs]	{"User":{"Updates":{"0":649129}}}
8.	2020-10-16 14:18:02 +0800 CST:	[event;sealing.SectorInvalidDealIDs]	{"User":{"Return":"PreCommit1"}}
9.	2020-10-16 14:18:11 +0800 CST:	[event;sealing.SectorUpdateDealIDs]	{"User":{"Updates":{"0":649129}}}
10.	2020-10-16 14:18:11 +0800 CST:	[event;sealing.SectorInvalidDealIDs]	{"User":{"Return":"PreCommit1"}}
11.	2020-10-16 14:18:22 +0800 CST:	[event;sealing.SectorUpdateDealIDs]	{"User":{"Updates":{"0":649129}}}
12.	2020-10-16 14:18:22 +0800 CST:	[event;sealing.SectorInvalidDealIDs]	{"User":{"Return":"PreCommit1"}}
13.	2020-10-16 14:18:32 +0800 CST:	[event;sealing.SectorUpdateDealIDs]	{"User":{"Updates":{"0":649129}}}
14.	2020-10-16 14:18:32 +0800 CST:	[event;sealing.SectorInvalidDealIDs]	{"User":{"Return":"PreCommit1"}}
15.	2020-10-16 14:18:43 +0800 CST:	[event;sealing.SectorUpdateDealIDs]	{"User":{"Updates":{"0":649129}}}

For lotus client list-deals, i can find the deal:

...pzrexqge  628146  f02299    StorageDealSealing             Y (epoch 0)       Y (epoch 0)  ...qzoq5ijq  3.969 GiB  0.001047244 FIL    523622    false
...ytijvbgq  628458  f02299    StorageDealSealing             Y (epoch 0)       Y (epoch 0)  ...tvt5swca  3.969 GiB  0.001047226 FIL    523613    false
...

Some of my sectors are under RecoverDealIDs state, what should i do?

[coinmini]

I have the same problem here.

[magik6k]

#4730

[funktafide]

Sector stuck in RecoveringDealIDs. I have attached the sector log as well a the output of lotus-miner info all.
InfoAll.txt
SectorLog.txt

[askender]

same issue, lotus version
Daemon: 1.2.0+git.dc3d17c9+api1.0.0
Local: lotus version 1.2.0+git.dc3d17c9

There is no deal in lotus-miner sectors list for 2 weeks, and I start make deals today:

2020-12-04T17:25:07.163+0800 INFO sectors storage-sealing/sealing.go:160 Adding piece for deal 1323251 (publish msg: bafy2bzaceak5hcfajp4z5okqvms7aqszmbuzet2bscqvlgi4kepsnis25r3fw)
2020-12-04T17:25:29.703+0800 WARN storageadapter storageadapter/provider.go:138 New Deal: deal 1323251
2020-12-04T17:27:07.916+0800 INFO markets loggers/loggers.go:19 storage event {"name": "ProviderEventDealActivationFailed", "proposal CID": "bafyreiepxp4yxlpvynmm6vdao4kgbql6oz4vkbhsmc4okvmfame6ux4q7a", "state": "StorageDealFailing", "message": "error activating deal: failed to set up called handler: called check error (h: 292250): failed to look up deal on chain: deal 1323251 not found"}
2020-12-04T17:27:07.918+0800 WARN providerstates providerstates/provider_states.go:482 deal bafyreiepxp4yxlpvynmm6vdao4kgbql6oz4vkbhsmc4okvmfame6ux4q7a failed: error activating deal: failed to set up called handler: called check error (h: 292250): failed to look up deal on chain: deal 1323251 not found
2020-12-04T17:27:07.918+0800 INFO markets loggers/loggers.go:19 storage event {"name": "ProviderEventFailed", "proposal CID": "bafyreiepxp4yxlpvynmm6vdao4kgbql6oz4vkbhsmc4okvmfame6ux4q7a", "state": "StorageDealError", "message": "error activating deal: failed to set up called handler: called check error (h: 292250): failed to look up deal on chain: deal 1323251 not found"}
2020-12-04T18:23:52.055+0800 WARN sectors storage-sealing/states_sealing.go:126 invalid deals in sector 1465: getting deal 1323251 for piece 0: deal 1323251 not found
2020-12-04T18:23:52.058+0800 WARN sectors storage-sealing/states_failed.go:354 getting deal 1323251 for piece 0: deal 1323251 not found

https://filfox.info/en/message/bafy2bzaceak5hcfajp4z5okqvms7aqszmbuzet2bscqvlgi4kepsnis25r3fw is on chain at 2020-11-17 13:10:30.
Why the old deal jump out suddenly? I guess I close all the workers so no addpiece is working.

miner log keep repeating these now:
2020-12-05T00:15:42.913+0800 WARN sectors storage-sealing/states_sealing.go:126 invalid deals in sector 1465: getting deal 1323251 for piece 0: deal 1323251 not found
2020-12-05T00:15:42.918+0800 WARN sectors storage-sealing/states_failed.go:354 getting deal 1323251 for piece 0: deal 1323251 not found

What should I do? I guess I can delete the sector. But a old deal(should timeout) hurt a new deal. I think there should be a check before a miner start to accept new deals.

[xinaxu]

Same issue here
lotus version 1.4.0+git.e9989d0e4.dirty

Event Log:
0.      2020-12-31 20:41:19 +0000 UTC:  [event;sealing.SectorStart]     {"User":{"ID":3192,"SectorType":8}}
1.      2020-12-31 20:48:12 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{"NewPiece":{"Piece":{"Size":17179869184,"PieceCID":{"/":"baga6ea4seaqlux6jhvnmeixjl653zev7kzcvvwwsms53zjovxhn7oqvsgdqbafi"}},"DealInfo":{"PublishCid":{"/":"bafy2bzacedbfq4jkdlfcmgn4624o2th64utfar4o6a7qryxr4cmsw74hy2zf2"},"DealID":1467160,"DealSchedule":{"StartEpoch":382687,"EndEpoch":1434984},"KeepUnsealed":false}}}}
2.      2020-12-31 21:52:00 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{"NewPiece":{"Piece":{"Size":17179869184,"PieceCID":{"/":"baga6ea4seaqnqpc4vkkubrvoj3elhbeqddfxdyxqh5mmkgoe2llxfapm6yck4bq"}},"DealInfo":{"PublishCid":{"/":"bafy2bzacebhyxwzj2yabkbcgbnaprozikqe4opxp7jadb57vjs4aib4pzxu2w"},"DealID":1467166,"DealSchedule":{"StartEpoch":385548,"EndEpoch":1440744},"KeepUnsealed":true}}}}
3.      2020-12-31 22:07:53 +0000 UTC:  [event;sealing.SectorStartPacking]      {"User":{}}
4.      2020-12-31 22:07:53 +0000 UTC:  [event;sealing.SectorPacked]    {"User":{"FillerPieces":null}}
5.      2020-12-31 22:07:53 +0000 UTC:  [event;sealing.SectorTicket]    {"User":{"TicketValue":"zLf6Oemq83KyZISRzMeOmELmTC2E8lZ3UwVhYijsD8c=","TicketEpoch":370635}}
6.      2020-12-31 22:07:53 +0000 UTC:  [event;sealing.SectorInvalidDealIDs]    {"User":{"Return":"PreCommit1"}}
7.      2020-12-31 22:07:55 +0000 UTC:  [event;sealing.SectorUpdateDealIDs]     {"User":{"Updates":{"0":1467160}}}
8.      2020-12-31 22:07:55 +0000 UTC:  [event;sealing.SectorInvalidDealIDs]    {"User":{"Return":"PreCommit1"}}
9.      2020-12-31 22:07:55 +0000 UTC:  [event;sealing.SectorUpdateDealIDs]     {"User":{"Updates":{"0":1467160}}}
10.     2020-12-31 22:07:55 +0000 UTC:  [event;sealing.SectorInvalidDealIDs]    {"User":{"Return":"PreCommit1"}}
11.     2020-12-31 22:07:55 +0000 UTC:  [event;sealing.SectorUpdateDealIDs]     {"User":{"Updates":{"0":1467160}}}
12.     2020-12-31 22:07:55 +0000 UTC:  [event;sealing.SectorInvalidDealIDs]    {"User":{"Return":"PreCommit1"}}
13.     2020-12-31 22:07:55 +0000 UTC:  [event;sealing.SectorUpdateDealIDs]     {"User":{"Updates":{"0":1467160}}}
14.     2020-12-31 22:07:55 +0000 UTC:  [event;sealing.SectorInvalidDealIDs]    {"User":{"Return":"PreCommit1"}}
15.     2020-12-31 22:07:56 +0000 UTC:  [event;sealing.SectorUpdateDealIDs]     {"User":{"Updates":{"0":1467160}}}
16.     2020-12-31 22:07:56 +0000 UTC:  [event;sealing.SectorInvalidDealIDs]    {"User":{"Return":"PreCommit1"}}
17.     2020-12-31 22:07:56 +0000 UTC:  [event;sealing.SectorUpdateDealIDs]     {"User":{"Updates":{"0":1467160}}}
18.     2020-12-31 22:07:56 +0000 UTC:  [event;sealing.SectorInvalidDealIDs]    {"User":{"Return":"PreCommit1"}}
19.     2020-12-31 22:07:56 +0000 UTC:  [event;sealing.SectorUpdateDealIDs]     {"User":{"Updates":{"0":1467160}}}