[BUG] Sector duration calculation causes Precommit rejection

[stuberman]

Describe the bug
New deal is accepted by miner and published but later rejected at Precommit due to duration calculation.

Version (run lotus version):

To Reproduce
Steps to reproduce the behavior:

1. Accept deal with duration of 1551627
2. See error

Expected behavior
Miner should not accept a deal if it will be invalidated prior to ExpectedSealDuration, as this causes sector termination, unnecessary publish fees and waste if compute resources.

Logs

1. Deal downloaded and accepted

2021-04-19T20:45:38.221Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventOpen", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealValidating", "message": ""}

2021-04-19T20:45:38.241Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventDealDeciding", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealAcceptWait", "message": ""}

2021-04-19T20:45:38.344Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventDataRequested", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealWaitingForData", "message": ""}

...7hqio5mu 0 StorageDealWaitingForData f3qh7m6ul2n6pbko6bovtthogzv4qdu4bh6hlmbjw55khic6wegintl5ma55fwbxjzh5g4hweyj3n5j3lbd3ra 32GiB 0 FIL 1551627

2. Deal imported into miner

2021-04-19T20:54:24.579Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventVerifiedData", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealReserveProviderFunds", "message": ""}

2021-04-19T20:54:24.611Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventFundsReserved", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealReserveProviderFunds", "message": ""}

2021-04-19T20:54:24.623Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventFunded", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealPublish", "message": ""}

2021-04-19T20:58:19.852Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventDealPublishInitiated", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealPublishing", "message": ""}

...7hqio5mu 0 StorageDealPublish f3qh7m6ul2n6pbko6bovtthogzv4qdu4bh6hlmbjw55khic6wegintl5ma55fwbxjzh5g4hweyj3n5j3lbd3ra 32GiB 0 FIL 1551627

3. Deal published and staged for AP

2021-04-19T21:04:30.372Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventFundsReleased", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealPublishing", "message": ""}

2021-04-19T21:04:30.384Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventDealPublished", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealStaged", "message": ""}

2021-04-19T21:04:30.397Z INFO sectors storage-sealing/input.go:236 Adding piece for deal 1765300 (publish msg: bafy2bzaceavvdfjzlnvaisxs4a3dkoqjc2z35kznauhqie5lu3vk5yadcqrdq)

2021-04-19T21:04:30.444Z WARN advmgr sector-storage/manager.go:323 stub NewSector

2021-04-19T21:04:30.449Z INFO sectors storage-sealing/input.go:411 Creating sector {"number": "1085", "type": "deal", "proofType": 8}

...7hqio5mu 1765300 StorageDealStaged f3qh7m6ul2n6pbko6bovtthogzv4qdu4bh6hlmbjw55khic6wegintl5ma55fwbxjzh5g4hweyj3n5j3lbd3ra 32GiB 0 FIL 1551627

4. PC1 Sealing starts

2021-04-19T21:09:27.864Z INFO markets loggers/loggers.go:20 storage provider event {"name": "ProviderEventDealHandedOff", "proposal CID": "bafyreia3aicoczfj3iaqfvzf3pu53isnhv5na57smfinfzuwpp7hqio5mu", "state": "StorageDealAwaitingPreCommit", "message": ""}

...7hqio5mu 1765300 StorageDealAwaitingPreCommit f3qh7m6ul2n6pbko6bovtthogzv4qdu4bh6hlmbjw55khic6wegintl5ma55fwbxjzh5g4hweyj3n5j3lbd3ra 32GiB 0 FIL 1551627

5. After PC1 & PC2 complete, get errors:

2021-04-19T23:42:29.199Z INFO sectors storage-sealing/states_sealing.go:316 submitting precommit for sector 1085 (deposit: 515169765777068872):

2021-04-19T23:42:29.201Z WARN sectors storage-sealing/fsm.go:552 sector 1085 got error event sealing.SectorChainPreCommitFailed: pushing message to mpool: GasEstimateMessageGas error: estimating gas used: message execution failed: exit 16, reason: invalid expiration 2245548, cannot be more than 1555200 past current epoch 685645 (RetCode=16)

2021-04-19T23:42:29.224Z INFO sectors storage-sealing/states_failed.go:26 PreCommitFailed(1085), waiting 59.775686683s before retrying

6. Loops forces me to terminate sector

Screenshots
See publish message for start and end Epochs:
"StartEpoch": 691041,
"endEpoch": 2242668,
Miner error message shows current Epoch as 685645 [+ 1559903] = 2245548 "endEpoch" too long
Publish message shows "StartEpoch" 691041 + [1551627] = 2242668 "endEpoch" not too long
Current Epoch from error message less startEpoch from publish message: 685645 - 691041 = -5396 or ~45 hours

Additional context

1. Notice the error message says "cannot be more than 1555200 past current epoch 685645"
   But status shows duration of 1551627 (This is 3,573 less than maximum or ~30 hours)
2. From Deal acceptance to import was 10 minutes
3. Deal publish to AP was 10 minutes
4. AP to PC1 was 5 minutes
5. PC1 to error was 2:33 hrs/mins

@ribasushi

[arajasek]

@stuberman Thank you for the fantastic report!