Expired deals continue to cause new sectors to be removed

[stuberman]

Describe the bug
Many older deals still in a status in lotus-miner sectors list where they are causing sealing problems.
An example is an expired deal from Dec 4 continues to be added to new sectors with other older deals and the sector is removed at the end of PC2

To Reproduce

1. While my miner is idle, it will create a new sector and add old expired deals.
2. See error below:

lotus-miner sectors status --on-chain-info --log 365
SectorID: 365
Status: Removed
CIDcommD: baga6ea4seaqfzritndxvdh6semu7aqk3snjvtmehftfatveisw3xjn2egr4t6gq
CIDcommR: bagboea4b5abcb4fgqxzpqancc4ir4hl4gbtboujwvz4xfqngf4ooqqerq3tdduqf
Ticket: 91967c6a19678b0ae9d7e210e03e1063dfbb256b0dcf21acad81866ef5e56b20
TicketH: 300445
Seed:
SeedH: 0
Precommit:
Commit:
Proof:
Deals: [1431209 1431396 1431415 0 0 0]
Retries: 0

Sector On Chain Info
SealProof: 0
Activation: 0
Expiration: 0
DealWeight: 0
VerifiedDealWeight: 0
InitialPledge: 0

Expiration Info
OnTime: 0
Early: 0

Event Log:
0. 2020-12-07 08:06:34 +0000 UTC: [event;sealing.SectorStart] {"User":{"ID":365,"SectorType":8}}

1. 2020-12-07 08:07:17 +0000 UTC: [event;sealing.SectorAddPiece] {"User":{"NewPiece":{"Piece":{"Size":2147483648,"PieceCID":{"/":"baga6ea4seaqjnupg2f6aawhbsslxfdexlwzvkjtc2gslqsaa4zcxgqykmacrkiy"}},"DealInfo":{"PublishCid":{"/":"bafy2bzaceabvuanwxzw4qawrlr4rnldy4utuevsyjnb6rwyik7uji5oxpyfzy"},"DealID":1431209,"DealSchedule":{"StartEpoch":301874,"EndEpoch":1341228},"KeepUnsealed":false}}}}
2. 2020-12-07 08:26:39 +0000 UTC: [event;sealing.SectorAddPiece] {"User":{"NewPiece":{"Piece":{"Size":2147483648,"PieceCID":{"/":"baga6ea4seaqfrqigcdom6f6hy4avhuysqezwfdbzil76g22nkrwjt2cr6okouki"}},"DealInfo":{"PublishCid":{"/":"bafy2bzacedf3zbka4olhhgk342qs26orxg7ta5axgn4ogy2mvaixqhazcsgwo"},"DealID":1431396,"DealSchedule":{"StartEpoch":302519,"EndEpoch":1344108},"KeepUnsealed":false}}}}
3. 2020-12-07 08:38:42 +0000 UTC: [event;sealing.SectorAddPiece] {"User":{"NewPiece":{"Piece":{"Size":2147483648,"PieceCID":{"/":"baga6ea4seaqaqzr6l4hibi7sz74ejfp3b7tvbpnw5l2sypstcgmwlpnhhmf2adq"}},"DealInfo":{"PublishCid":{"/":"bafy2bzacecdygdnu2hev4bmkt5llhvwh2oyvw7jc6ssst3e5hjpzuhzt7ggmq"},"DealID":1431415,"DealSchedule":{"StartEpoch":301708,"EndEpoch":1341228},"KeepUnsealed":false}}}}
4. 2020-12-07 13:06:34 +0000 UTC: [event;sealing.SectorStartPacking] {"User":{}}
5. 2020-12-07 13:12:45 +0000 UTC: [event;sealing.SectorPacked] {"User":{"FillerPieces":[{"Size":2147483648,"PieceCID":{"/":"baga6ea4seaqh34u3nf3tdgpi6k2aw54rtucikcpo25uofrzjpmprinydj7b4mla"}},{"Size":8589934592,"PieceCID":{"/":"baga6ea4seaqnqyicdbbfvnpjlmokmi45fgroiigxa2uw6nz6f6ojveoxlhizwai"}},{"Size":17179869184,"PieceCID":{"/":"baga6ea4seaqg2nsld34emra2ljfgrbrdcswmbjdpaftrpzjuipudt3w7qpbikpa"}}]}}
6. 2020-12-07 13:12:45 +0000 UTC: [event;sealing.SectorTicket] {"User":{"TicketValue":"kZZ8ahlniwrp1+IQ4D4QY9+7JWsNzyGsrYGGbvXlayA=","TicketEpoch":300445}}
7. 2020-12-07 17:33:12 +0000 UTC: [event;sealing.SectorPreCommit1] {"User":{"PreCommit1Out":"eyJyZWdpc3RlcmVkX3Byb29mIjoiU3RhY2tlZERyZzMyR2lCVjFfMSIsImxhYmVscyI6eyJTdGFja2VkRHJnMzJHaUJWMSI6eyJsYWJlbHMiOlt7InBhdGgiOiIvTG90dXMvd29ya2VyL2NhY2hlL3MtdDAxMjc4LTM2NSIsImlkIjoibGF5ZXItMSIsInNpemUiOjEwNzM3NDE4MjQsInJvd3NfdG9fZGlzY2FyZCI6N30seyJwYXRoIjoiL0xvdHVzL3dvcmtlci9jYWNoZS9zLXQwMTI3OC0zNjUiLCJpZCI6ImxheWVyLTIiLCJzaXplIjoxMDczNzQxODI0LCJyb3dzX3RvX2Rpc2NhcmQiOjd9LHsicGF0aCI6Ii9Mb3R1cy93b3JrZXIvY2FjaGUvcy10MDEyNzgtMzY1IiwiaWQiOiJsYXllci0zIiwic2l6ZSI6MTA3Mzc0MTgyNCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvTG90dXMvd29ya2VyL2NhY2hlL3MtdDAxMjc4LTM2NSIsImlkIjoibGF5ZXItNCIsInNpemUiOjEwNzM3NDE4MjQsInJvd3NfdG9fZGlzY2FyZCI6N30seyJwYXRoIjoiL0xvdHVzL3dvcmtlci9jYWNoZS9zLXQwMTI3OC0zNjUiLCJpZCI6ImxheWVyLTUiLCJzaXplIjoxMDczNzQxODI0LCJyb3dzX3RvX2Rpc2NhcmQiOjd9LHsicGF0aCI6Ii9Mb3R1cy93b3JrZXIvY2FjaGUvcy10MDEyNzgtMzY1IiwiaWQiOiJsYXllci02Iiwic2l6ZSI6MTA3Mzc0MTgyNCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvTG90dXMvd29ya2VyL2NhY2hlL3MtdDAxMjc4LTM2NSIsImlkIjoibGF5ZXItNyIsInNpemUiOjEwNzM3NDE4MjQsInJvd3NfdG9fZGlzY2FyZCI6N30seyJwYXRoIjoiL0xvdHVzL3dvcmtlci9jYWNoZS9zLXQwMTI3OC0zNjUiLCJpZCI6ImxheWVyLTgiLCJzaXplIjoxMDczNzQxODI0LCJyb3dzX3RvX2Rpc2NhcmQiOjd9LHsicGF0aCI6Ii9Mb3R1cy93b3JrZXIvY2FjaGUvcy10MDEyNzgtMzY1IiwiaWQiOiJsYXllci05Iiwic2l6ZSI6MTA3Mzc0MTgyNCwicm93c190b19kaXNjYXJkIjo3fSx7InBhdGgiOiIvTG90dXMvd29ya2VyL2NhY2hlL3MtdDAxMjc4LTM2NSIsImlkIjoibGF5ZXItMTAiLCJzaXplIjoxMDczNzQxODI0LCJyb3dzX3RvX2Rpc2NhcmQiOjd9LHsicGF0aCI6Ii9Mb3R1cy93b3JrZXIvY2FjaGUvcy10MDEyNzgtMzY1IiwiaWQiOiJsYXllci0xMSIsInNpemUiOjEwNzM3NDE4MjQsInJvd3NfdG9fZGlzY2FyZCI6N31dLCJfaCI6bnVsbH19LCJjb25maWciOnsicGF0aCI6Ii9Mb3R1cy93b3JrZXIvY2FjaGUvcy10MDEyNzgtMzY1IiwiaWQiOiJ0cmVlLWQiLCJzaXplIjoyMTQ3NDgzNjQ3LCJyb3dzX3RvX2Rpc2NhcmQiOjd9LCJjb21tX2QiOls5MiwxOTcsMTksMTA0LDIzOSw4MSwxNTksMjEwLDM1LDQxLDI0MCw2NSw5MSwxNDcsODMsODksMTc2LDEzNSw0NCwyMDIsOSwyMTIsMTM2LDE0OSwxODMsMTE2LDE4Myw2OCw1MiwxMjEsNjMsMjZdfQ=="}}
8. 2020-12-07 18:21:27 +0000 UTC: [event;sealing.SectorPreCommit2] {"User":{"Sealed":{"/":"bagboea4b5abcb4fgqxzpqancc4ir4hl4gbtboujwvz4xfqngf4ooqqerq3tdduqf"},"Unsealed":{"/":"baga6ea4seaqfzritndxvdh6semu7aqk3snjvtmehftfatveisw3xjn2egr4t6gq"}}}
9. 2020-12-07 18:21:27 +0000 UTC: [event;sealing.SectorDealsExpired] {"User":{}}
   sector deals expired: piece 0 (of 6) of sector 365 refers expired deal 1431209 - should start at 301874, head 301962
10. 2020-12-07 18:21:27 +0000 UTC: [event;sealing.SectorRemove] {"User":{}}
11. 2020-12-07 18:21:37 +0000 UTC: [event;sealing.SectorRemoved] {"User":{}}

Miner log
2020-12-07T18:21:27.627 INFO filecoin_proofs::api::seal > seal_pre_commit_phase2:finish
2020-12-07T18:21:27.627 INFO filcrypto::proofs::api > seal_pre_commit_phase2: finish
2020-12-07T18:21:27.725Z WARN sectors storage-sealing/fsm.go:511 sector 365 got error event sealing.SectorDealsExpired: sector deals expired: piece 0 (of 6) of sector 365 refers expired deal 1431209 - should start at 301874, head 301962
2020-12-07T18:21:27.738Z ERROR sectors storage-sealing/states_failed.go:326 non-precommitted sector with expired deals, can't recover from this yet
2020-12-07T18:21:27.743Z INFO stores stores/local.go:581 remove /Lotus/worker/sealed/s-t01278-365
2020-12-07T18:21:30.406Z INFO stores stores/local.go:581 remove /Lotus/worker/cache/s-t01278-365
2020-12-07T18:21:36.834Z INFO miner miner/miner.go:384 Time delta between now and our mining base: 6s (nulls: 0)

lotus-miner storage-deals list -v |grep 1431209
Dec 4 17:40:12 bafyreig6s2s42r6i3nplag2d44z4b3hblexrlhqao3axymcjv2wmqihimm 1431209 StorageDealAwaitingPreCommit f3qjnosleewjww2fd4gxf7245dhei6pqs6ssyixlwfhitmx7u6qxip6sbn2aweacu4xcqpj7gixu3fodv4nv2q 2GiB 0.0002078708 FIL 1039354

lotus-miner storage-deals list -v |grep 1431396
Dec 4 23:02:37 bafyreiayqvbddlk5v6tvuf4cjymvkrdfitrswyviyno2getbwkp3rrfwxy 1431396 StorageDealAwaitingPreCommit f3qjnosleewjww2fd4gxf7245dhei6pqs6ssyixlwfhitmx7u6qxip6sbn2aweacu4xcqpj7gixu3fodv4nv2q 2GiB 0.0002083178 FIL 1041589

lotus-miner storage-deals list -v |grep 1431415
Dec 4 16:17:45 bafyreibejkh77vzojuyg572vubjpoqlyvmb5uuvochlfaoowpjl4u45ibe 1431415 StorageDealAwaitingPreCommit f3qjnosleewjww2fd4gxf7245dhei6pqs6ssyixlwfhitmx7u6qxip6sbn2aweacu4xcqpj7gixu3fodv4nv2q 2GiB 0.000207904 FIL 1039520

Expected behavior
Expired deals should have state changed from "StorageDealAwaitingPreCommit" to "StorageDealError"

Screenshots
N/A

Version (run lotus version):
lotus-miner version

Daemon: 1.2.2+git.b13226bc2+api1.0.0
Local: lotus-miner version 1.2.2+git.b13226bc2

Additional context
This is a single miner no remote workers, Ryzen 9, x570 mobo, 128 GB ram 200GB swap, NVMe disks

I have deals going back to September showing "StorageDealSealing"
I ran these commands while the miner was idle with no outstanding sealing tasks running:

lotus-miner storage-deals list -v |grep StorageDealSealing

Sep 28 15:44:30 bafyreib7n56ylfmsasbwnugjv52n7worlay5npwcr6af6jo35n2up3phza 219097 StorageDealSealing f17kamajrdzjcjzj6b3y2ovc64kc7qxvkbx2dzvza 8MiB 0.0000523308 FIL 523308

Here is a listing of all states going back to August 2020:

StorageDealActive
lotus-miner storage-deals list |grep StorageDealActive |wc -l
3233

StorageDealProviderTransferRestart
lotus-miner storage-deals list |grep StorageDealProviderTransferRestart |wc -l
189

StorageDealWaitingForData
lotus-miner storage-deals list |grep StorageDealWaitingForData |wc -l
122

StorageDealAwaitingPreCommit
lotus-miner storage-deals list |grep StorageDealAwaitingPreCommit |wc -l
44

StorageDealError <---- these are mostly rejected deals due to prices rejected
lotus-miner storage-deals list |grep StorageDealError |wc -l
3694

StorageDealSealing
lotus-miner storage-deals list |grep StorageDealSealing |wc -l
1

[stuberman]

BTW - This wasted attempt at sealing cost 0.35 FIL - 3 PublishStorageDeals messages:
https://filfox.info/en/message/bafy2bzaceabvuanwxzw4qawrlr4rnldy4utuevsyjnb6rwyik7uji5oxpyfzy
https://filfox.info/en/message/bafy2bzacedf3zbka4olhhgk342qs26orxg7ta5axgn4ogy2mvaixqhazcsgwo
https://filfox.info/en/message/bafy2bzacecdygdnu2hev4bmkt5llhvwh2oyvw7jc6ssst3e5hjpzuhzt7ggmq

2020-12-07T07:55:21.925Z INFO markets loggers/loggers.go:20 storage event {"name": "ProviderEventVerifiedData", "proposal CID": "bafyreig6s2s42r6i3nplag2d44z4b3hblexrlhqao3axymcjv2wmqihimm", "state": "StorageDealReserveProviderFunds", "message": ""}
2020-12-07T07:55:21.949Z INFO markets loggers/loggers.go:20 storage event {"name": "ProviderEventFundsReserved", "proposal CID": "bafyreig6s2s42r6i3nplag2d44z4b3hblexrlhqao3axymcjv2wmqihimm", "state": "StorageDealReserveProviderFunds", "message": ""}
2020-12-07T07:55:21.963Z INFO markets loggers/loggers.go:20 storage event {"name": "ProviderEventFunded", "proposal CID": "bafyreig6s2s42r6i3nplag2d44z4b3hblexrlhqao3axymcjv2wmqihimm", "state": "StorageDealPublish", "message": ""}
2020-12-07T07:55:21.973Z INFO storageadapter storageadapter/provider.go:74 publishing deal
2020-12-07T07:55:22.170Z INFO markets loggers/loggers.go:20 storage event {"name": "ProviderEventDealPublishInitiated", "proposal CID": "bafyreig6s2s42r6i3nplag2d44z4b3hblexrlhqao3axymcjv2wmqihimm", "state": "StorageDealPublishing", "message": ""}
2020-12-07T07:58:41.764Z INFO miner miner/miner.go:384 Time delta between now and our mining base: 11s (nulls: 0)
2020-12-07T07:58:52.888Z ERROR data-transfer channels/channel_state.go:101 unexpected EOF
2020-12-07T07:59:02.588Z INFO badger [email protected]/db.go:1030 Storing value log head: {Fid:3822 Len:36 Offset:1073616596}

2020-12-07T08:06:30.385Z INFO markets loggers/loggers.go:20 storage event {"name": "ProviderEventFundsReleased", "proposal CID": "bafyreig6s2s42r6i3nplag2d44z4b3hblexrlhqao3axymcjv2wmqihimm", "state": "StorageDealPublishing", "message": ""}
2020-12-07T08:06:30.445Z INFO markets loggers/loggers.go:20 storage event {"name": "ProviderEventDealPublished", "proposal CID": "bafyreig6s2s42r6i3nplag2d44z4b3hblexrlhqao3axymcjv2wmqihimm", "state": "StorageDealStaged", "message": ""}
2020-12-07T08:06:34.879Z INFO sectors storage-sealing/sealing.go:165 Adding piece for deal 1431209 (publish msg: bafy2bzaceabvuanwxzw4qawrlr4rnldy4utuevsyjnb6rwyik7uji5oxpyfzy)
2020-12-07T08:06:34.932Z WARN advmgr sector-storage/manager.go:313 stub NewSector
2020-12-07T08:06:34.932Z INFO sectors storage-sealing/sealing.go:399 Creating sector 365
2020-12-07T08:06:34.945Z INFO sectors storage-sealing/fsm.go:283 Waiting for deals 365
2020-12-07T08:06:34.945Z INFO sectors storage-sealing/sealing.go:223 Adding piece to sector 365
2020-12-07T08:06:34.946Z DEBUG advmgr sector-storage/sched.go:354 SCHED 1 queued; 2 open windows
2020-12-07T08:06:34.946Z DEBUG advmgr sector-storage/sched.go:449 SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:false cpuUse:0 cond:} todo:[]}]
2020-12-07T08:06:34.946Z DEBUG advmgr sector-storage/sched.go:450 SCHED Acceptable win: [[0 1]]
2020-12-07T08:06:34.946Z DEBUG advmgr sector-storage/sched.go:465 SCHED try assign sqi:0 sector 365 to window 0
2020-12-07T08:06:34.946Z DEBUG advmgr sector-storage/sched.go:472 SCHED ASSIGNED sqi:0 sector 365 task seal/v0/addpiece to window 0
2020-12-07T08:06:34.946Z DEBUG advmgr sector-storage/sched_worker.go:367 assign worker sector 365
2020-12-07T08:06:34.946Z DEBUG advmgr sector-storage/sched.go:354 SCHED 0 queued; 2 open windows
2020-12-07T08:06:34.946Z DEBUG advmgr sector-storage/sched_worker.go:277 task done {"workerid": "4e0d9349-b72e-4564-a7c0-38c94d432de9"}
2020-12-07T08:06:34.947Z DEBUG advmgr sector-storage/sched.go:354 SCHED 0 queued; 2 open windows
2020-12-07T08:06:34.962Z DEBUG advmgr sector-storage/worker_local.go:129 acquired sector {{1278 365} 8} (e:0; a:1): {{0 0} /Lotus/worker/unsealed/s-t01278-365 }
2020-12-07T08:06:34.996 INFO filecoin_proofs::api > generate_piece_commitment:start

2020-12-07T08:19:33.997Z INFO markets loggers/loggers.go:20 storage event {"name": "ProviderEventDataTransferCompleted", "proposal CID": "bafyreiayqvbddlk5v6tvuf4cjymvkrdfitrswyviyno2getbwkp3rrfwxy", "state": "StorageDealVerifyData", "message": ""}
2020-12-07T08:26:39.032Z INFO sectors storage-sealing/fsm.go:283 Waiting for deals 365
2020-12-07T08:26:39.062Z WARN storageadapter storageadapter/provider.go:138 New Deal: deal 1431396
2020-12-07T08:26:39.150Z INFO markets loggers/loggers.go:20 storage event {"name": "ProviderEventDealHandedOff", "proposal CID": "bafyreiayqvbddlk5v6tvuf4cjymvkrdfitrswyviyno2getbwkp3rrfwxy", "state": "StorageDealAwaitingPreCommit", "message": ""}

[stuberman]

Full log of stuck deals in verbose mode
Stuck deals verbose.txt

[jennijuju]

related https://github.com/filecoin-project/lotus/issues/4689