Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PoSt failed:invalid post was submitted #10733

Closed
4 of 11 tasks
siriusyim opened this issue Apr 23, 2023 · 8 comments
Closed
4 of 11 tasks

PoSt failed:invalid post was submitted #10733

siriusyim opened this issue Apr 23, 2023 · 8 comments
Labels
area/proving Area: Proving kind/bug Kind: Bug need/team-input Hint: Needs Team Input P1 P1: Must be resolved

Comments

@siriusyim
Copy link
Contributor

Checklist

  • This is not a security-related bug/issue. If it is, please follow please follow the security policy.
  • 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, 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 fvm/fevm - Lotus FVM and FEVM interactions
  • lotus miner/worker - sealing
  • lotus miner - proving(WindowPoSt/WinningPoSt)
  • lotus JSON-RPC API
  • lotus message management (mpool)
  • Other

Lotus Version

~# lotus version
Daemon:  1.22.0+calibnet+git.0d8659e76+api1.5.0
Local: lotus version 1.22.0+calibnet+git.0d8659e76
~# lotus-miner version
Daemon:  1.22.0+calibnet+git.0d8659e76+api1.5.0
Local: lotus-miner version 1.22.0+calibnet+git.0d8659e76

Repro Steps

  1. Run lotus
  2. Run lotus-miner
  3. Run lotus-worker (window,winning,storage)
    ...

Describe the Bug

During wdPost, the PoSt calculation and verification can be completed, but when the message is submitted, the GasEstimateMessageGas function reports an error "invalid post was submitted (16)"

Logging Information

default log level


2023-04-23T03:49:30.023 INFO filecoin_proofs::api::post_util > generate_sector_challenges:finish
2023-04-23T03:49:30.023 DEBUG filcrypto::util::types > generate_fallback_sector_challenges: end
2023-04-23T03:49:30.023 DEBUG filcrypto::util::types > generate_fallback_sector_challenges: start
2023-04-23T03:49:30.023 INFO filecoin_proofs::api::post_util > generate_sector_challenges:start
2023-04-23T03:49:30.023 DEBUG filcrypto::util::types > generate_fallback_sector_challenges: start
2023-04-23T03:49:30.023 INFO filecoin_proofs::api::post_util > generate_sector_challenges:start
2023-04-23T03:49:30.023 INFO filecoin_proofs::api::post_util > generate_sector_challenges:finish
2023-04-23T03:49:30.023 DEBUG filcrypto::util::types > generate_fallback_sector_challenges: end
2023-04-23T03:49:30.091+0800    WARN    wdpost  wdpost/wdpost_run.go:249        Checked sectors {"checked": 191, "good": 191}
2023-04-23T03:49:30.092+0800    WARN    wdpost  wdpost/wdpost_run.go:249        Checked sectors {"checked": 3, "good": 3}
2023-04-23T03:49:30.092+0800    INFO    wdpost  wdpost/wdpost_run_faults.go:153 attempting recovery declarations for 3 sectors
2023-04-23T03:49:30.097+0800    INFO    wdpost  wdpost/wdpost_run.go:411        running window post     {"cycle": "2023-04-23T03:49:29.729+0800", "chain-random": "sHJaKhwLBePVEbIcjbq+Dt4NyWpCOLDIcmEhySni/3k=", "deadline": {"CurrentEpoch":495553,"PeriodStart":495572,"Index":0,"Open":495572,"Close":495632,"Challenge":4
2023-04-23T03:49:30.097+0800    INFO    advmgr  sealer/manager_post.go:131      generateWindowPoSt maxPartitionSize:2349 partitionCount:1
2023-04-23T03:49:30.097 DEBUG filcrypto::util::types > generate_fallback_sector_challenges: start
2023-04-23T03:49:30.097 INFO filecoin_proofs::api::post_util > generate_sector_challenges:start
2023-04-23T03:49:30.098 INFO filecoin_proofs::api::post_util > generate_sector_challenges:finish
2023-04-23T03:49:30.098 DEBUG filcrypto::util::types > generate_fallback_sector_challenges: end
2023-04-23T03:49:30.098+0800    INFO    advmgr  sealer/manager_post.go:213      generateWindowPost      {"index": 0}
2023-04-23T03:49:30.105+0800    WARN    wdpost  wdpost/wdpost_run_faults.go:180 declare faults recovered Message CID    {"cid": "bafy2bzacec3t7ji6gizfwxdcmau6vco5tmk7rez35k6jfbu3c26t3axzzeywg"}
2023-04-23T03:49:40.089+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 2, "forRound": 495554, "baseEpoch": 495553, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:50:10.007+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495555, "baseEpoch": 495554, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:50:40.410+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 2, "forRound": 495556, "baseEpoch": 495555, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:51:10.401+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 4, "forRound": 495557, "baseEpoch": 495556, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:51:40.379+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 4, "forRound": 495558, "baseEpoch": 495557, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:52:00.756+0800    WARN    advmgr  sealer/manager_post.go:226      generateWindowPost partition:0, get skip count:0
2023-04-23T03:52:00.756 DEBUG filcrypto::util::types > merge_window_post_partition_proofs: start
2023-04-23T03:52:00.756 DEBUG filcrypto::util::types > merge_window_post_partition_proofs: end
2023-04-23T03:52:00.756+0800    INFO    wdpost  wdpost/wdpost_run.go:431        computing window post   {"cycle": "2023-04-23T03:49:29.729+0800", "batch": 0, "elapsed": 150.659711742, "skip": 0, "err": null}
2023-04-23T03:52:00.759 DEBUG filcrypto::util::types > verify_window_post: start
2023-04-23T03:52:00.765 INFO filecoin_proofs::api::window_post > verify_window_post:start
2023-04-23T03:52:00.765 INFO filecoin_proofs::caches > trying parameters memory cache for: WINDOW_POST[34359738368]-verifying-key
2023-04-23T03:52:00.765 INFO filecoin_proofs::caches > no params in memory cache for WINDOW_POST[34359738368]-verifying-key
2023-04-23T03:52:00.817 INFO storage_proofs_core::parameter_cache > parameter set identifier for cache: FallbackPoSt::PublicParams{sector_size: 34359738368, challenge_count: 10, sector_count: 2349}
2023-04-23T03:52:00.817 INFO storage_proofs_core::parameter_cache > ensuring that all ancestor directories for: "/var/tmp/filecoin-proof-parameters/v28-proof-of-spacetime-fallback-merkletree-poseidon_hasher-8-8-0-0377ded656c6f524f1618760bffe4e0a1c51d5a70c4509eedae8a27555733edc.vk" exist
2023-04-23T03:52:00.817 INFO storage_proofs_core::parameter_cache > checking cache_path: "/var/tmp/filecoin-proof-parameters/v28-proof-of-spacetime-fallback-merkletree-poseidon_hasher-8-8-0-0377ded656c6f524f1618760bffe4e0a1c51d5a70c4509eedae8a27555733edc.vk" for verifying key
2023-04-23T03:52:00.817 INFO storage_proofs_core::parameter_cache > Verify production parameters is false
2023-04-23T03:52:01.953 INFO storage_proofs_core::parameter_cache > read verifying key from cache "/var/tmp/filecoin-proof-parameters/v28-proof-of-spacetime-fallback-merkletree-poseidon_hasher-8-8-0-0377ded656c6f524f1618760bffe4e0a1c51d5a70c4509eedae8a27555733edc.vk"
2023-04-23T03:52:02.613 INFO filecoin_proofs::api::window_post > verify_window_post:finish
2023-04-23T03:52:02.613 DEBUG filcrypto::util::types > verify_window_post: end
2023-04-23T03:52:02.613+0800    INFO    wdpost  wdpost/wdpost_run.go:276        post cycle done {"cycle": "2023-04-23T03:49:29.729+0800", "took": 152.883441917}
2023-04-23T03:52:10.488+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495559, "baseEpoch": 495558, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:52:40.010+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495560, "baseEpoch": 495559, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:53:10.423+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495561, "baseEpoch": 495560, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:53:40.150+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495562, "baseEpoch": 495561, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:54:10.218+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495563, "baseEpoch": 495562, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:54:40.007+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495564, "baseEpoch": 495563, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:55:10.236+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 4, "forRound": 495565, "baseEpoch": 495564, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:55:40.319+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495566, "baseEpoch": 495565, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:56:10.416+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495567, "baseEpoch": 495566, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:56:40.033+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495568, "baseEpoch": 495567, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:57:10.008+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495569, "baseEpoch": 495568, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:57:40.008+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495570, "baseEpoch": 495569, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:58:10.243+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495571, "baseEpoch": 495570, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:58:40.419+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495572, "baseEpoch": 495571, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:59:10.174+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495573, "baseEpoch": 495572, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T03:59:40.009+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495574, "baseEpoch": 495573, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T04:00:10.007+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495575, "baseEpoch": 495574, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T04:00:40.169+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495576, "baseEpoch": 495575, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T04:01:01.643+0800    ERROR   wdpost  wdpost/wdpost_run.go:697        estimating gas  {"error": "message execution failed: exit 16, reason: message failed with backtrace:\n00: f01035 (method 5) -- invalid post was submitted (16)\n (RetCode=16)"}
2023-04-23T04:01:01.670+0800    ERROR   wdpost  wdpost/wdpost_run.go:179        submit window post failed: pushing message to mpool:
    github.com/filecoin-project/lotus/storage/wdpost.(*WindowPoStScheduler).submitPoStMessage
        /home/sirius/go/src/github.com/siriusyim/lotus/storage/wdpost/wdpost_run.go:658
  - GasEstimateMessageGas error: message execution failed: exit 16, reason: message failed with backtrace:
00: f01035 (method 5) -- invalid post was submitted (16)
 (RetCode=16)
2023-04-23T04:01:01.670+0800    WARN    wdpost  wdpost/wdpost_changehandler.go:494      Aborted window post Submitting (Deadline: &{CurrentEpoch:495572 PeriodStart:495572 Index:0 Open:495572 Close:495632 Challenge:495552 FaultCutoff:495502 WPoStPeriodDeadlines:48 WPoStProvingPeriod:2880 WPoStChallengeWindow:60 WPoStC
2023-04-23T04:01:10.403+0800    INFO    miner   miner/miner.go:478      completed mineOne       {"tookMilliseconds": 3, "forRound": 495577, "baseEpoch": 495576, "baseDeltaSeconds": 10, "nullRounds": 0, "lateStart": false, "beaconEpoch": 0, "lookbackEpochs": 900, "networkPowerAtLookback": "1460834996813824", "minerPow
2023-04-23T04:01:30.213+0800    ERROR   wdpost  wdpost/wdpost_run.go:697        estimating gas  {"error": "message execution failed: exit 16, reason: message failed with backtrace:\n00: f01035 (method 5) -- invalid post was submitted (16)\n (RetCode=16)"}
2023-04-23T04:01:30.237+0800    ERROR   wdpost  wdpost/wdpost_run.go:179        submit window post failed: pushing message to mpool:
    github.com/filecoin-project/lotus/storage/wdpost.(*WindowPoStScheduler).submitPoStMessage
        /home/sirius/go/src/github.com/siriusyim/lotus/storage/wdpost/wdpost_run.go:658
  - GasEstimateMessageGas error: message execution failed: exit 16, reason: message failed with backtrace:
00: f01035 (method 5) -- invalid post was submitted (16)
 (RetCode=16)
@siriusyim
Copy link
Contributor Author

siriusyim commented Apr 23, 2023

I added a print log in the verify_window_post function
image

@siriusyim
Copy link
Contributor Author

siriusyim commented Apr 23, 2023

I added a print log in the verify_window_post function image

Because the call to wdpost_run.go:468 is successful
image

@siriusyim
Copy link
Contributor Author

The difference between the input parameters of the smart contract call and the input parameters of the wdpost_run.go call is as follows:
image

@0x5459
Copy link
Contributor

0x5459 commented Apr 23, 2023

filecoin-project/ref-fvm#1727 (comment)

@siriusyim
Copy link
Contributor Author

filecoin-project/ref-fvm#1727 (comment)

So this bug should be solved by releasing a new version and MANDATORY network upgrade in calibnet?

@jennijuju
Copy link
Member

filecoin-project/ref-fvm#1727 (comment)

So this bug should be solved by releasing a new version and MANDATORY network upgrade in calibnet?

thanks for reporting - we will take a look soon

@arajasek
Copy link
Contributor

@siriusyim @0x5459 Thank you SO much for the report, the investigation! Really grateful to you and everyone else 💙

I think we're going to "soft" update calibrationnet -- so long as folks start using 1.22.1 or later, the problem will go away. There will be some forkiness until that happens.

We will also have to hard-code exceptions for the bad messages -- until we do that historical sync won't work, but that is a slightly lower priority.

@rjan90
Copy link
Contributor

rjan90 commented May 30, 2023

Closing this issue, as this has now been fixed. Again, thanks to everyone involved here for both the report, investigation and fix to this issue!

@rjan90 rjan90 closed this as completed May 30, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/proving Area: Proving kind/bug Kind: Bug need/team-input Hint: Needs Team Input P1 P1: Must be resolved
Projects
None yet
Development

No branches or pull requests

6 participants