Local network: received block with large delay from miner

[stanbar]

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

./lotus version
Daemon:  1.17.2+2k+git.fb0fb7144+api1.5.0
Local: lotus version 1.17.2+2k+git.fb0fb7144

./lotus-miner version
Daemon:  1.17.2+2k+git.fb0fb7144+api1.5.0
Local: lotus-miner version 1.17.2+2k+git.fb0fb7144

Describe the Bug

I'm doing research and I need a local network of filecoin.
I followed the tutorial local-network on my server. Everything is running but I can not make a deal—it gets stuck on StorageDealStartDataTransfer.

I looked at lotus node logs and it repeatedly prints:

2022-10-31T12:26:12.190+0100    INFO    chain   chain/sync_manager.go:233       selected sync target: [bafy2bzaceapds4i6bqri2amihcc6vyndszujlcy7soutr32lmbn7oorjsh2d6]
2022-10-31T12:26:12.190+0100    INFO    chain   chain/sync_manager.go:315       worker 9538 syncing in [bafy2bzaceapds4i6bqri2amihcc6vyndszujlcy7soutr32lmbn7oorjsh2d6]
2022-10-31T12:26:12.190+0100    INFO    chain   chain/sync_manager.go:323       worker 9538 done; took 4.152µs
2022-10-31T12:26:16.391+0100    INFO    chain   chain/sync.go:625       block validation        {"took": 0.007938855, "height": "9603", "age": 882.391198107}
2022-10-31T12:26:16.393+0100    INFO    chainstore      store/store.go:644      New heaviest tipset! [bafy2bzacedhlynej2mopmdzso5ymzmwcykffft7rub3bgcdvcr2322xzjfcdy] (height=9603)
2022-10-31T12:26:16.395+0100    WARN    sub     sub/incoming.go:102     received block with large delay from miner      {"block": "bafy2bzacedhlynej2mopmdzso5ymzmwcykffft7rub3bgcdvcr2322xzjfcdy
", "delay": 882, "miner": "t01000"}
2022-10-31T12:26:16.398+0100    INFO    chain   chain/sync_manager.go:233       selected sync target: [bafy2bzacedhlynej2mopmdzso5ymzmwcykffft7rub3bgcdvcr2322xzjfcdy]
2022-10-31T12:26:16.398+0100    INFO    chain   chain/sync_manager.go:315       worker 9539 syncing in [bafy2bzacedhlynej2mopmdzso5ymzmwcykffft7rub3bgcdvcr2322xzjfcdy]
2022-10-31T12:26:16.398+0100    INFO    chain   chain/sync_manager.go:323       worker 9539 done; took 3.457µs
2022-10-31T12:26:20.478+0100    INFO    chain   chain/sync.go:625       block validation        {"took": 0.010734807, "height": "9604", "age": 882.478669505}
2022-10-31T12:26:20.486+0100    INFO    chainstore      store/store.go:644      New heaviest tipset! [bafy2bzaceait5begbslotwhhkrgkssy6pnijpgie6ti24o6dqiseswjwjp7tm] (height=9604)
2022-10-31T12:26:20.488+0100    WARN    sub     sub/incoming.go:102     received block with large delay from miner      {"block": "bafy2bzaceait5begbslotwhhkrgkssy6pnijpgie6ti24o6dqiseswjwjp7tm
", "delay": 882, "miner": "t01000"}
2022-10-31T12:26:20.492+0100    INFO    chain   chain/sync_manager.go:233       selected sync target: [bafy2bzaceait5begbslotwhhkrgkssy6pnijpgie6ti24o6dqiseswjwjp7tm]
2022-10-31T12:26:20.492+0100    INFO    chain   chain/sync_manager.go:315       worker 9540 syncing in [bafy2bzaceait5begbslotwhhkrgkssy6pnijpgie6ti24o6dqiseswjwjp7tm]
2022-10-31T12:26:20.492+0100    INFO    chain   chain/sync_manager.go:323       worker 9540 done; took 2.923µs

miner repeatedly shows:

2022-10-31T12:16:05.586+0100    INFO    storageminer    storage/winning_prover.go:77    GenerateWinningPoSt took 4.037696123s
2022-10-31T12:16:05.604+0100    INFO    miner   miner/miner.go:569      mined new block {"cid": "bafy2bzaceb7taxxt5twadhezsgv5qybscudmwddcpdggxrjx75ciumn2thzfa", "height": 9452, "miner": "t0100
0", "parents": ["t01000"], "parentTipset": "{bafy2bzacebiwzedn66rapq75repfmn352orgptxydks3kkzeqp2aqcip6g72k}", "took": 4.059341019}
2022-10-31T12:16:05.605+0100    WARN    miner   miner/miner.go:571      CAUTION: block production took longer than the block delay. Your computer may not be fast enough to keep up      {"tPower
check ": 0.001311227, "tTicket ": 0.002092124, "tSeed ": 0.000002793, "tProof ": 4.037999298, "tPending ": 0.000411552, "tCreateBlock ": 0.017524025}
2022-10-31T12:16:05.605+0100    WARN    miner   miner/miner.go:473      completed mineOne       {"tookMilliseconds": 4059, "forRound": 9452, "baseEpoch": 9451, "baseDeltaSeconds": 875, "nullRou
nds": 0, "lateStart": true, "beaconEpoch": 2392768, "lookbackEpochs": 900, "networkPowerAtLookback": "40960", "minerPowerAtLookback": "40960", "isEligible": true, "isWinner": true, "error": nul
l}
2022-10-31T12:16:05.605+0100    WARN    miner   miner/miner.go:320      mined block in the past {"block-time": "2022-10-31T12:01:30.000+0100", "time": "2022-10-31T12:16:05.605+0100", "differenc
e": 875.605092158}
2022-10-31T12:16:05.734+0100    INFO    storageminer    storage/winning_prover.go:70    Computing WinningPoSt ;[{SealProof:5 SectorNumber:1 SectorKey:<nil> SealedCID:bagboea4b5abcaip7ndr3ymf7an
cxad2dk4wycmud4pmxzt6nu7kenps72aqfublb}]; [135 132 205 52 202 236 63 98 232 3 89 42 135 102 136 184 24 55 174 57 86 218 160 9 241 75 99 189 22 237 229 157]
2022-10-31T12:16:05.734+0100    INFO    advmgr  sealer/manager_post.go:23       GenerateWinningPoSt run at lotus-miner
2022-10-31T12:16:09.793+0100    INFO    storageminer    storage/winning_prover.go:77    GenerateWinningPoSt took 4.058641208s
2022-10-31T12:16:09.810+0100    INFO    miner   miner/miner.go:569      mined new block {"cid": "bafy2bzacecwuj6ish7ydjz3mas65llnfuf2lklwxabevyr3eo3rviuawx7eu2", "height": 9453, "miner": "t0100
0", "parents": ["t01000"], "parentTipset": "{bafy2bzaceb7taxxt5twadhezsgv5qybscudmwddcpdggxrjx75ciumn2thzfa}", "took": 4.088337917}
2022-10-31T12:16:09.810+0100    WARN    miner   miner/miner.go:571      CAUTION: block production took longer than the block delay. Your computer may not be fast enough to keep up      {"tPower
check ": 0.004865626, "tTicket ": 0.00727474, "tSeed ": 0.000009988, "tProof ": 4.059505404, "tPending ": 0.000383922, "tCreateBlock ": 0.016298237}
2022-10-31T12:16:09.810+0100    WARN    miner   miner/miner.go:473      completed mineOne       {"tookMilliseconds": 4088, "forRound": 9453, "baseEpoch": 9452, "baseDeltaSeconds": 875, "nullRou
nds": 0, "lateStart": true, "beaconEpoch": 2392769, "lookbackEpochs": 900, "networkPowerAtLookback": "40960", "minerPowerAtLookback": "40960", "isEligible": true, "isWinner": true, "error": nul
l}
2022-10-31T12:16:09.810+0100    WARN    miner   miner/miner.go:320      mined block in the past {"block-time": "2022-10-31T12:01:34.000+0100", "time": "2022-10-31T12:16:09.810+0100", "differenc
e": 875.81028556}
2022-10-31T12:16:09.841+0100    INFO    storageminer    storage/winning_prover.go:70    Computing WinningPoSt ;[{SealProof:5 SectorNumber:0 SectorKey:<nil> SealedCID:bagboea4b5abca34cdyi2d625rx
n2givjt6qlbmhuyray5ch4ow3rlbqimznmfgz7}]; [159 131 65 96 4 243 36 79 246 203 132 224 138 252 87 158 92 234 73 89 29 226 126 185 223 127 189 219 209 103 22 211]
2022-10-31T12:16:09.841+0100    INFO    advmgr  sealer/manager_post.go:23       GenerateWinningPoSt run at lotus-miner

Isn't my hardware good enough? In the tutorial, you write:

This solution runs comfortably on a computer with 2 CPU cores and 4 GB RAM.

My server specs are more than that:

CPU: Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz
RAM: 16GB
SSD for OS: Samsung SSD PM85 238.47 GiB
SSD for storage: Samsung SSD 850 465.76GiB

Logging Information

Logs were provided above.

Repo Steps

No response

[rjan90]

Hey @stanbar!

It should not be a too big issue seeing this error message on a local-network, you should still be able to make a storage deal. Can you check if there is anything in your lotus-miner storage-deals list ?

[stanbar]

1. Create payload file payload.json with the content { "firstname": "Stanislaw", "lastname": "Baranski" }
2. Import file with ./lotus client import payload.json => Import 1667242248725384733, Root bafkqaol3biqcaitgnfzhg5domfwwkir2earfg5dbnzuxg3dbo4rcycraeargyyltorxgc3lfei5caiscmfzgc3ttnnusect5bi
3. Create deal with ./lotus client deal =>

[stanbar@aston lotus-local-net]$ ./lotus client deal
Data CID (from lotus client import): bafkqaol3biqcaitgnfzhg5domfwwkir2earfg5dbnzuxg3dbo4rcycraeargyyltorxgc3lfei5caiscmfzgc3ttnnusect5bi
.. calculating data size
Deal duration (days): 24
Miner Addresses (f0.. f0..), none to find: t01000
.. querying miner asks
-----
Proposing from t3s6btvvmrjnreinnx6g62lehroq4wofcxfg734kejk4fkav4p5lc5xlyeqflzl62siqcff2lpelyj3gr3g6da
        Balance: 49999999.999757824981101716 FIL

Piece size: 256B (Payload size: 203B)
Duration: 576h0m0s
Total price: ~0.0000000000616896 FIL (0.000000000000000119 FIL per epoch)
Verified: false

Accept (yes/no): yes
.. executing
Deal (t01000) CID: bafyreidgb5vqnvygluaushojpxm5mn5seua57uvy3b2yjggfim67uws4fe

[stanbar]

Update: I created a random payload of a size of 1KB and it worked 🤔.

1. Create payload dd if=/dev/urandom of=1kb-payload.bin bs=1KB count=1
2. Import ./lotus client import 1kb-payload.bin
3. Create a deal ./lotus client deal

[stanbar@aston lotus-local-net]$ ./lotus client deal
Data CID (from lotus client import): bafk2bzacebbk32gy3nlhtnftbwrzaaujvxyhl6pi6cnt2uxkv4p6fybfi622k
.. calculating data size
Deal duration (days): 24
Miner Addresses (f0.. f0..), none to find: t01000
.. querying miner asks
-----
Proposing from t3s6btvvmrjnreinnx6g62lehroq4wofcxfg734kejk4fkav4p5lc5xlyeqflzl62siqcff2lpelyj3gr3g6da
        Balance: 49999999.999757385004363118 FIL

Piece size: 2KiB (Payload size: 1.075KiB)
Duration: 576h0m0s
Total price: ~0.0000000004940352 FIL (0.000000000000000953 FIL per epoch)
Verified: false

Accept (yes/no): yes
.. executing
Deal (t01000) CID: bafyreifa5nkmqrbrrd63mjxbwiwcczxn2nwxz5sr6kxyckbgu6igj5od5y

Now ./lotus client list-deals shows

DealCid      DealId  Provider  State                          On Chain?  Slashed?  PieceCID     Size       Price                     Duration  Verified
...igj5od5y  0       t01000    StorageDealCheckForAcceptance  N          N         ...lhaguopa  1.984 KiB  0.000000000495697232 FIL  520144    false

  Message: Provider state: StorageDealPublish

./lotus-miner storage-deals list shows

...igj5od5y  0       StorageDealPublish  t3s6btvvmrjnreinnx6g62lehroq4wofcxfg734kejk4fkav4p5lc5xlyeqflzl62siqcff2lpelyj3gr3g6da  2KiB  0.000000000495697232 FIL  520144

I'm using the default 2KB sector sizes.

Does the size of the content matter?

[stanbar]

@rjan90 after 15h the deal is stuck on StorageDealSealing.

1. ./lotus client list-deals shows

DealCid      DealId  Provider  State                         On Chain?  Slashed?  PieceCID     Size       Price                     Duration  Verified
...dt3n7fgi  0       t01000    StorageDealStartDataTransfer  N          N         ...lkzyo6ly  254 B      0.0000000000619752 FIL    520800    false   
...67uws4fe  0       t01000    StorageDealStartDataTransfer  N          N         ...lkzyo6ly  254 B      0.000000000061906894 FIL  520226    false   
...igj5od5y  2       t01000    StorageDealSealing            N          N         ...lhaguopa  1.984 KiB  0.000000000495697232 FIL  520144    false   

2. ./lotus-miner storage-deals list shows:

ProposalCid  DealId  State               Client                                                                                  Size  Price                     Duration
...xr7ofy3i  0       StorageDealError    t3s6btvvmrjnreinnx6g62lehroq4wofcxfg734kejk4fkav4p5lc5xlyeqflzl62siqcff2lpelyj3gr3g6da  256B  0.000000000061753741 FIL  518939
...dt3n7fgi  0       StorageDealError    t3s6btvvmrjnreinnx6g62lehroq4wofcxfg734kejk4fkav4p5lc5xlyeqflzl62siqcff2lpelyj3gr3g6da  256B  0.0000000000619752 FIL    520800
...67uws4fe  0       StorageDealError    t3s6btvvmrjnreinnx6g62lehroq4wofcxfg734kejk4fkav4p5lc5xlyeqflzl62siqcff2lpelyj3gr3g6da  256B  0.000000000061906894 FIL  520226
...igj5od5y  2       StorageDealSealing  t3s6btvvmrjnreinnx6g62lehroq4wofcxfg734kejk4fkav4p5lc5xlyeqflzl62siqcff2lpelyj3gr3g6da  2KiB  0.000000000495697232 FIL  520144

3. ./lotus-miner sectors list --show-removed --seal-time

ID  State                  OnChain  Active  Expiration                      Deals  DealWeight  VerifiedPower
0   Proving                YES      YES     1550097 (in 10 weeks 16 hours)  CC
1   Proving                YES      YES     1550097 (in 10 weeks 16 hours)  1      2KiB        18KiB
2   SubmitCommitAggregate  NO       NO      n/a                             1      [2KiB]

[rjan90]

You need to send the CommitMessage to the chain for it to finish the sealing process. You can push that message manually with lotus-miner sectors batching commit --publish-now, or change the AggregateWait-time in your config.toml file

[stanbar]

Thank you, it worked!
But still, does the size of the content matter? Why did publishing content of size 256B result in deal data verification failed: proposal CommP doesn't match calculated CommP?

[rjan90]

Also converting this issue into a discussion