Skip to content

Worker call and gas counters reset to zero when a fuzz worker hits --timeout #1601

Description

@elopez

Describe the issue:

When a fuzz worker stops because the campaign time limit was reached, and at least one test still needs shrinking, the final report claims Total calls: 0 no matter how many calls the campaign actually made. The status line drops to fuzzing: 0/<testLimit> and the gas rate goes negative.

Only the reporting is wrong — findings, corpus and coverage are all correct.

Root cause

spawnWorker gives each worker a single stateRef (lib/Echidna/UI.hs:249), and that ref is the only channel through which a worker's WorkerState reaches the reporting layer — workerStates just reads it back (lib/Echidna/UI.hs:287-288). The worker publishes into it through the callback get >>= writeIORef stateRef (lib/Echidna/UI.hs:259).

When a fuzz worker stops on TimeLimitReached with tests still needing shrinking, a second, shrink-only worker run is started outside the timeout (lib/Echidna/UI.hs:276-278, added for #839) — and it is handed the same stateRef:

when (any needsShrinking tests) $ void $
  runReaderT (runWorker FuzzWorker (get >>= writeIORef stateRef)
              vm dict workerId [] 0 cliSelectedContract) env

runFuzzWorker unconditionally builds a fresh initialState (lib/Echidna/Campaign.hs:339-347) with ncalls = 0, ncallseqs = 0, totalGas = 0, newCoverage = False and the pristine dict. The first thing that run does inside runStateT is lift callback (lib/Echidna/Campaign.hs:351), before any shrinking happens — so the zeroed state is written straight over the accumulated one, and every later reader sees zeros:

  • ppTotalCalls (lib/Echidna/UI/Report.hs:52-55) → Total calls: 0
  • statusLine (lib/Echidna/UI.hs:431-438) → fuzzing: 0/N; and since deltaGas = totalGas - gasTracker.totalGasConsumed, the reset makes the delta negative, hence the negative gas/s
  • the TUI's Total calls and gas rate (lib/Echidna/UI/Widgets.hs:199, :273-276)

Scope

Triggers when both hold, so it is easy to hit with any --timeout/timeout: run that finds something:

  1. a fuzz worker stops with TimeLimitReached, and
  2. at least one test still needs shrinking at that moment.

Confirmed not affected:

  • Findings and exit code — tests live in env.testRefs, not WorkerState.
  • Corpus and coverage — also Env refs.
  • Seed:ppSeed reads genDict.defSeed, which the second run recomputes identically.
  • Shrinking quality, despite the genDict reset: shrinkTest is (MonadIO, MonadThrow, MonadRandom, MonadReader Env) with no MonadState constraint, and updateTests never touches the state, so the worker's dictionary never reaches the shrinker.

Expected behaviour

Total calls: should report the calls the campaign made, the status line should keep its count, and the gas rate should never be negative.

Suggested fix

Stop the shrink-only pass from publishing into the ref the campaign reports from — e.g. hand it a throwaway IORef, since nothing needs its live state once the campaign is over. Alternatively, seed the second run with the state the first one finished with so the counters keep accumulating across both.

Code example to reproduce the issue:

Any contract with a falsifiable property works. Using tests/solidity/basic/flags.sol from this repo:

contract Test {
  event Flag(bool);

  bool private flag0 = true;
  bool private flag1 = true;

  function set0(int val) public returns (bool){
    if (val % 100 == 0)
      flag0 = false;
  }

  function set1(int val) public returns (bool){
    if (val % 10 == 0 && !flag0)
      flag1 = false;
  }

  function echidna_alwaystrue() public returns (bool){
    return(true);
  }

  function echidna_revert_always() public returns (bool){
    revert();
  }

  function echidna_sometimesfalse() public returns (bool){
    emit Flag(flag0);
    emit Flag(flag1);
    return(flag1);
  }
}

Run it with a time limit short enough that shrinking is still outstanding when it fires:

echidna basic/flags.sol --format text --test-limit 100000000 --timeout 5 --workers 2

Version:

Echidna 2.3.3   (built from master at 2bfa64ef)
slither 0.11.3

macOS (aarch64), GHC 9.8.4. Reproduces with both --format text and the interactive TUI.

Relevant log output:

[19:07:29.90] [status] tests: 1/3, fuzzing: 67593/100000000, values: [], cov: 404, corpus: 3, gas/s: 500363892
[19:07:31.90] [Worker 0] Time limit reached. Stopping.
[19:07:31.90] [Worker 1] Time limit reached. Stopping.
[19:07:31.90] [status] tests: 1/3, fuzzing: 0/100000000, values: [], cov: 404, corpus: 3, gas/s: -750545838
echidna_sometimesfalse: failed!💥
  Reason: ReturnFalse
  Call sequence:
    Test.set0(0)
    Test.set1(0)

echidna_alwaystrue: passing
echidna_revert_always: passing

Unique instructions: 404
Unique codehashes: 1
Corpus size: 3
Seed: 8331856644448189321
Total calls: 0

Note the last status line before the summary: the call count drops from 67593 to 0, and gas/s is negative.

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions