New deals fail in devnet with error "deal duration out of bounds" even when selecting the deal period between 180 to 540 days

LexLuthr commented 2 years ago

Checklist

[X] This is not a security-related bug/issue. If it is, please follow please follow the security policy.
[X] This is not a question or a support request. If you have any lotus related questions, please ask in the lotus forum.
[X] This is not a new feature request. If it is, please file a feature request instead.
[X] This is not an enhancement request. If it is, please file a improvement suggestion instead.
[X] I have searched on the issue tracker and the lotus forum, and there is no existing related issue or discussion.
[X] 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.
[X] 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)
[X] lotus miner/market - storage deal
[ ] lotus miner/market - retrieval deal
[ ] lotus miner/market - data transfer
[ ] lotus client
[ ] lotus JSON-RPC API
[ ] lotus message management (mpool)
[ ] Other

Lotus Version

# ./lotus/lotus version
Daemon:  1.13.2-dev+2k+git.e196a81e9+api1.4.0
Local: lotus version 1.13.2-dev+mainnet+git.e196a81e9.dirty

# ./lotus/lotus-miner version
Daemon:  1.13.2-dev+2k+git.e196a81e9+api1.2.0
Local: lotus-miner version 1.13.2-dev+2k+git.e196a81e9

Describe the Bug

New deals fail in devnet with as the deal duration crosses goes out of bound

# lotus client list-deals  --show-failed
DealCid      DealId  Provider  State              On Chain?        Slashed?  PieceCID     Size       Price                     Duration  Verified
...mwtihaiq  0       f01000    StorageDealError   N                N         ...wfhwx4ki  1.984 KiB  0.000000004119070895 FIL  4322215   false
  Message: unexpected deal status while waiting for data request: 11 (StorageDealFailing). Provider message: deal rejected: deal duration out of bounds (min, max, provided): 518400, 1555200, 4322215
...pp3esgsu  0       f01000    StorageDealError   N                N         ...wfhwx4ki  1.984 KiB  0.000000003707343446 FIL  3890182   false
  Message: unexpected deal status while waiting for data request: 11 (StorageDealFailing). Provider message: deal rejected: deal duration out of bounds (min, max, provided): 518400, 1555200, 3890182
...m6kmdbxu  0       f01000    StorageDealError   N                N         ...wfhwx4ki  1.984 KiB  0.000000003913134266 FIL  4106122   false
  Message: unexpected deal status while waiting for data request: 11 (StorageDealFailing). Provider message: deal rejected: deal duration out of bounds (min, max, provided): 518400, 1555200, 4106122

As per @magik6k on a devnet the epoch/block time is 2 (or 4?) seconds instead of 30. Deal bounds are defined in terms of epochs, so when making a deal on a devnet, when you are specifying the duration in days, that number must be 15x smaller. But the cli does not allow to specify less than 180 day (minimum) period.

The workaround is commenting out the following code and rebuilding the lotus binary. The deals can be made with the new binary without any problems.

https://github.com/filecoin-project/lotus/blob/master/cli/client.go#L617-L620

//            if days < int(build.MinDealDuration/builtin.EpochsInDay) {
//                printErr(xerrors.Errorf("minimum duration is %d days", int(build.MinDealDuration/builtin.EpochsInDay)))
//                continue
//            }

and line 47 of the same file go fix Go compilation error about unused import.

// "github.com/filecoin-project/lotus/chain/actors/builtin"

Logging Information

.lotusDevnet/journal/lotus-journal.ndjson:
{"System":"markets/storage/client","Event":"state_change","Timestamp":"2021-11-24T12:59:13.629680256+05:30","Data":{"Event":"ClientEventFailed","Deal":{"Proposal":{"PieceCID":{"/":"baga6ea4seaqjuv4g4kv6k6mfgoqv5efhqj4coditqc7n6iuzmbe3cbnwfhwx4ki"},"PieceSize":2048,"VerifiedDeal":false,"Client":"t3q2axyzkhi5vbtqxurfxrema75ktghfvtgiku4fv4427gy5edqhphm6jh3wbhjcwllbhdsvpkx4nki7yfhdna","Provider":"t01000","Label":"mAVWg5AIgszaYFh7RQUzE4jnuG17hPjIb96OlkXKS7Wy+XpnpnHI","StartEpoch":188615,"EndEpoch":4294737,"StoragePricePerEpoch":"953","ProviderCollateral":"0","ClientCollateral":"0"},"ClientSignature":{"Type":2,"Data":"t7hDOIo8R0Ww/SNqpvRBP4RfDshlQcdrIPgy9xPxW+xS/ZXdvrtuf65Z9ExZ8rtRE7DHUM9ASOGnfQLzeWVE3wgc3mn8GEWeLbigrG01E8wFd3QYQL7DyCNBAfrxOBzi"},"ProposalCid":{"/":"bafyreihwmhuljpk4itboh7czotpmzquqzv53aynig3uyo2djqzm6kmdbxu"},"AddFundsCid":null,"State":26,"Miner":"12D3KooWCS1ghakwbfaQSvQgkiHUpr7gxawfwjGLZC2qjzSJkyXT","MinerWorker":"t0100","DealID":0,"DataRef":{"TransferType":"graphsync","Root":{"/":"bafk2bzacecztngawd3iuctge4i464g264e7deg7xuoszc4us5vwl4xuz5gohe"},"PieceCid":{"/":"baga6ea4seaqjuv4g4kv6k6mfgoqv5efhqj4coditqc7n6iuzmbe3cbnwfhwx4ki"},"PieceSize":2032,"RawBlockSize":0},"Message":"unexpected deal status while waiting for data request: 11 (StorageDealFailing). Provider message: deal rejected: deal duration out of bounds (min, max, provided): 518400, 1555200, 4106122","DealStages":{"Stages":[{"Name":"StorageDealReserveClientFunds","Description":"Reserving client funds","ExpectedDuration":"a few minutes","CreatedTime":"2021-11-24T12:59:13.579850964+05:30","UpdatedTime":"2021-11-24T12:59:13.579850964+05:30","Logs":[{"Log":"funds reserved, amount \u003c3913134266\u003e","UpdatedTime":"2021-11-24T12:59:13.579850964+05:30"}]},{"Name":"StorageDealFundsReserved","Description":"FundsReserved","ExpectedDuration":"a few minutes","CreatedTime":"2021-11-24T12:59:13.622300527+05:30","UpdatedTime":"2021-11-24T12:59:13.622300527+05:30","Logs":[{"Log":"unexpected deal status while waiting for data request: 11 (StorageDealFailing). Provider message: deal rejected: deal duration out of bounds (min, max, provided): 518400, 1555200, 4106122","UpdatedTime":"2021-11-24T12:59:13.622300527+05:30"}]},{"Name":"StorageDealFailing","Description":"Failing","ExpectedDuration":"","CreatedTime":"2021-11-24T12:59:13.626412174+05:30","UpdatedTime":"2021-11-24T07:29:13.629595405Z","Logs":[{"Log":"funds released, amount \u003c3913134266\u003e","UpdatedTime":"2021-11-24T12:59:13.626412174+05:30"}]}]},"PublishMessage":null,"SlashEpoch":0,"PollRetryCount":0,"PollErrorCount":0,"FastRetrieval":true,"FundsReserved":"0","CreationTime":"2021-11-24T12:59:13.572203368+05:30","TransferChannelID":null,"SectorNumber":0}}}
[root@192 ~]# less .lotusDevnet/journal/lotus-journal.ndjson

Repo Steps

Run a local devnet lotus node and start the lotus miner
Use the lotus CLI to make a deal with local miner

# lotus client deal
Data CID (from lotus client import): bafk2bzacecztngawd3iuctge4i464g264e7deg7xuoszc4us5vwl4xuz5gohe
.. calculating data size
Deal duration (days): 190
Miner Addresses (f0.. f0..), none to find: t01000
.. querying miner asks
-----
Proposing from t3q2axyzkhi5vbtqxurfxrema75ktghfvtgiku4fv4427gy5edqhphm6jh3wbhjcwllbhdsvpkx4nki7yfhdna
        Balance: 49999999.99987608021877228 FIL
Piece size: 2KiB (Payload size: 1.099KiB)
Duration: 4560h0m0s
Total price: ~0.000000003911112 FIL (0.000000000000000953 FIL per epoch)
Verified: false
Accept (yes/no): yes
.. executing
Deal (t01000) CID: bafyreihwmhuljpk4itboh7czotpmzquqzv53aynig3uyo2djqzm6kmdbxu

Error will appear when you check the deal list on the client side.

# lts client list-deals  --show-failed
DealCid      DealId  Provider  State              On Chain?        Slashed?  PieceCID     Size       Price                     Duration  Verified
...mwtihaiq  0       f01000    StorageDealError   N                N         ...wfhwx4ki  1.984 KiB  0.000000004119070895 FIL  4322215   false
  Message: unexpected deal status while waiting for data request: 11 (StorageDealFailing). Provider message: deal rejected: deal duration out of bounds (min, max, provided): 518400, 1555200, 4322215
...pp3esgsu  0       f01000    StorageDealError   N                N         ...wfhwx4ki  1.984 KiB  0.000000003707343446 FIL  3890182   false
  Message: unexpected deal status while waiting for data request: 11 (StorageDealFailing). Provider message: deal rejected: deal duration out of bounds (min, max, provided): 518400, 1555200, 3890182
...m6kmdbxu  0       f01000    StorageDealError   N                N         ...wfhwx4ki  1.984 KiB  0.000000003913134266 FIL  4106122   false
  Message: unexpected deal status while waiting for data request: 11 (StorageDealFailing). Provider message: deal rejected: deal duration out of bounds (min, max, provided): 518400, 1555200, 4106122

jackoelv commented 2 years ago

How is it going? Is there any fix for that?

jackoelv commented 2 years ago

storage provider event {"name": "ProviderEventFailed", "proposal CID": "bafyreigdghzgczmdo2l5kynazrcjvmuee6ezbqs4l7cp7j43wdgngma72y", "state": "StorageDealError", "message": "deal rejected: deal duration out of bounds (min, max, provided): 518400, 1555200, 3889526"} that is the problem.

jackoelv commented 2 years ago

I found the bug: 4s a epoch in devnet, 30s a epoch in mainnet. so the real duration is x 4/30*2880) days. the duration is 30/4 times more than mainnet.

jackoelv commented 2 years ago

in params_2k.go: 96: const BlockDelaySecs = uint64(4) here you can find it.

jackoelv commented 2 years ago

I think you can fix here:

cli/client.go 624: dur = 24 time.Hour time.Duration(days) epochs = abi.ChainEpoch(dur / (time.Duration(build.BlockDelaySecs) time.Second)) replace to: epochs = abi.ChainEpoch(dur / (time.Duration(30) time.Second))

It should solve this problem.

jackoelv commented 2 years ago

yes, I have solve this problem. Now I meet a new issue: when I run in devnet this command: lotus-miner storage-deals import-data xx

I got this:

ERROR: given data does not match expected commP (got: baga6ea4seaqj5rdeitkss6f5hdtgqkdellh65cti5neiuszcytkv533cplgzgpy, expected baga6ea4seaqhmpyav5opkbboc6tkj67vz7t3veypiajs6xjpfwzlxfvofuljkjq)

jackoelv commented 2 years ago

then I fix the issue by use manual deal. when import-data, It tells me: normal shutdown of state machine

jackoelv commented 2 years ago

well done. just need to get rid of "--start-epoch" then all working fine. if anybody has same issue can message to me.

jackoelv commented 2 years ago

@jennijuju you can close the issue now.

LexLuthr commented 2 years ago

@jackoelv Please do not recommend closing issues opened by other community members unless it has been fixed in the code. Please let the lotus team take a call on fixing the issues.

jackoelv commented 2 years ago

@LexLuthr take a look above:

I think you can fix here:

cli/client.go
624:
dur = 24 * time.Hour * time.Duration(days)
epochs = abi.ChainEpoch(dur / (time.Duration(build.BlockDelaySecs) * time.Second))
replace to:
epochs = abi.ChainEpoch(dur / (time.Duration(30) * time.Second))

It should solve this problem.

a little work, then the issue solved.

LexLuthr commented 2 years ago

@jackoelv I have already mentioned how to workaround the problem in my initial description. The issue was opened to fix this permanently in the code for 2k build.

jackoelv commented 2 years ago

Oh, got it: -P

filecoin-project / lotus