joystream icon indicating copy to clipboard operation
joystream copied to clipboard

Benchmarks should always panic on failure

Open Lezek123 opened this issue 2 years ago • 4 comments

The issue

Recently I observed very unusual behavior when generating weights for project-token pallet on https://github.com/Joystream/joystream/pull/4341.

The project-token transfer benchmark would fail with MembershipHandleAlreadyRegistered error, but only if project token account bloat bond in genesis config was set to > 0. This error on the surface seemed like something completely unrelated to the change that was causing it and turned out very hard to debug.

As it turned out, the issue was actually caused by insufficient balance during issue_token call here:

    transfer {
        let (owner_member_id, owner_account) = create_owner::<T>();
        /* ... */
        let token_id = issue_token::<T>(TransferPolicyParams::Permissionless)?;
        /* ... */

As you can see, the issue_token call doesn't panic, but instead returns an error in case of failure.

This turned out to be problematic because of how the benchmark command executes the benchmarking functions, specifically here: https://github.com/paritytech/substrate/blob/master/utils/frame/benchmarking-cli/src/pallet/command.rs#L300.

In case --no-verify flag is not provided, for each benchmarking step, first a StateMachine instance is created that runs the benchmark function along with the verify logic. The result of this execution is ignored (unless there is a panic invoked), however the state changes are preserved in a mutable changes object (they are normally cleaned up after successful execution, however if the benchmarking function returns Err, the cleanup step is never reached). Then a second StateMachine instance is created, executing the same logic, however reusing a runtime state from the previous instance (&mut changes). The result of this execution is no longer ignored, it is properly decoded, and the main process fails in case it is Err (however it has little significance at this point and can be very confusing. It also won't tell us at which line the error occured if it didn't cause panic)

This is why a mysterious MembershipHandleAlreadyRegistered was occuring. The first StateMachine execution failed with InsufficientJoyBalance during issue_token call. This caused the database/state cleanup function to not be reached, however the error itself was ignored. During the next StateMachine execution, the owner member already existed (as the state was preserved), so the execution immediately failed with MembershipHandleAlreadyRegistered on create_owner.

The solution

Make sure all benchmarking functions do not return Err on failure, either through call()?; syntax or explicitly. Benchmarking functions should always panic on Err, so either assert_ok!(result) or result.unwrap(); should be used instead. This will prevent difficult-to-debug issues like the one mentioned above from occuring.

┆Issue is synchronized with this Asana task by Unito

Lezek123 avatar Oct 10 '22 14:10 Lezek123

Very nicely identified and described, seems like a nightmare to pin down. Is it not strange this has not been an issue prior?

bedeho avatar Oct 10 '22 17:10 bedeho

Is it not strange this has not been an issue prior?

Most of the benchmarks are already following this rule to always panic on failure. Ironically I was probably the first person that started breaking it in content/project-token benchmarks, because during tests it worked as expected and the error message was more meaningful when compared to the .unwrap() approach. So there are 2 reasons:

  • Most of the benchmarks that return Err on failure were added recently
  • This issue only manifests itself during the actual weight generation, not during benchmark tests.

Lezek123 avatar Oct 10 '22 18:10 Lezek123

Unfortunately, some of the substrate's native benchmarks are also subject to this issue (they return Err on failure). I just ran into it again when tweaking staking parameters.

Confusing error when pallet_staking benchmarks ran w/o --no-verify flag:

Generating weights for pallet_staking...
Error: Input("AlreadyBonded")
There was a problem generating the weights for pallet_staking, check the error above

The actual error when ran w/ --no-verify flag:

Generating weights for pallet_staking...
Error: Input("TooManyValidators")
There was a problem generating the weights for pallet_staking, check the error above

Lezek123 avatar Oct 11 '22 06:10 Lezek123

@mnaamani I was thinking that since the issue appears also in the substrate benchmarks and --no-verify "solves" it, perhaps we can use this flag by default in ./generate-weights.sh. During actual weight generation one can then choose whether to skip the verification code or not (the former also having the benefit of lower execution time while the latter being more safe)

Lezek123 avatar Oct 11 '22 09:10 Lezek123

What is the status of this issue?

bedeho avatar Nov 17 '22 16:11 bedeho

What is the status of this issue?

Not started yet

Lezek123 avatar Nov 17 '22 16:11 Lezek123