Update ethereum/tests / Reintroduce VM debug logger with safe guard

[holgerd77]

This PR updates ethereum/tests.

It will do this two steps:

1. Update to latest v8.0.5 release and see how things go (first CI on PR opening)
2. Update to latest develop which now also includes the EIP-1559 blockchain tests from here

CI is run with the type: test all hardforks label.

[codecov]

Codecov Report

Merging #1269 (01b739f) into master (026a54f) will decrease coverage by 1.73%.
The diff coverage is 16.74%.

Flag	Coverage Δ
block	86.44% <ø> (+0.24%)	⬆️
blockchain	84.42% <ø> (+0.06%)	⬆️
client	84.43% <ø> (-0.23%)	⬇️
common	88.12% <ø> (ø)
devp2p	83.78% <ø> (ø)
ethash	82.83% <ø> (ø)
tx	89.61% <ø> (ø)
vm	76.83% <16.74%> (-4.45%)	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

[holgerd77]

Calling a contract with an undefined opcode as first byte of the code from here ethereum/tests#836 is currently failing, can be run with ts-node ./tests/tester --state --fork=Berlin --test='undefinedOpcodeFirstByte'.

[holgerd77]

I will reintroduce the debug logger here removed in #1198 in its most naive approach by just adding all debug lines and then commenting them out. Then it is at least possible to do proper debugging in the specific situations one is needing it by simply doing a search/replace on //debug(, then do the debugging and after finding the error just discard all the changes with a git checkout.

[ryanio]

for the debug logger, could you guard it within an if clause to skip if undefined? like if (process.env.DEBUG) { debug() } it would be verbose but I know the goal is to not execute the string literal.

[holgerd77]

@ryanio is it guaranteed that this doesn't execute the string literal then? Then I can do for sure.

[holgerd77]

@ryanio ok, I will do. The current guard will break in the browser though since process is not available, will do a slight modification.

[holgerd77]

Phew, what an impressively shitty work to re-add all this stuff one had already done months ago. 😬 So happy when I'm through with this.

[holgerd77]

Ok, this is side-tracking too much and the bug here is unrelated to the 1559 changes and not really very important and in the VM for a long time. I have opened a dedicated issue which we can handle separately and will add to the skipped tests and continue here.

[holgerd77]

London tests are currently all failing, see e.g. ts-node ./tests/tester --blockchain --fork=London --file='CREATE2_EOF1'.

This is due to a difference in the naming of the base fee field, in the tests this is called baseFee while we are calling it baseFeePerGas, have opened a question here on ethereum/tests.

The base fee on our side therefore defaults to 7 and then differs from the base fee provided

[holgerd77]

Update: I've now fixed this (at least temporarily) for both state and blockchain tests.

This should now provide a basis to start with the real thing and do fixes on failing tests.

@ryanio @jochem-brouwer I would ask you to really prioritize this, I likely can't continue with this today any more, so that we are getting not too much into delay! Thanks!

[holgerd77]

Current failing tests:

State Tests

Run all with: ts-node ./tests/tester --state --fork=London

2 failures (total 150)

• basefeeExample, run with `ts-node ./tests/tester --state --fork=London --test='basefeeExample'``
• eip1559, run with ts-node ./tests/tester --state --fork=London --test='eip1559'

Blockchain Tests

10 failures (total 1275)

• badBlocks, run with ts-node ./tests/tester --blockchain --fork=London --file='badBlocks'
• gasLimit20m, ts-node ./tests/tester --blockchain --fork=London --file='gasLimit20m'
• gasLimit40m, ts-node ./tests/tester --blockchain --fork=London --file='gasLimit40m'

[ryanio]

@holgerd77 thanks for working on this, i can help triage these bugs the rest of today after our call.

i had one more idea for the debug logger guard, if we don't want to make every 1 debug line into 3 with an if statement, i just tried this experiment:

const DEBUG = true
const debug = console.debug ?? createDebugLogger('vm:state')

let didRun = false

const evaluate = () => {
    didRun = true
    return 'hello'
}

let debugGuard = (fn: Function) => { 
    if (DEBUG) {
      debug(fn())
    }
}

debugGuard(() => `${evaluate()}`)
console.log('didRun: ', didRun)

didRun = false
debugGuard = () => {} // set to no-op

console.log('---')

debugGuard(() => `${evaluate()}`)
console.log('didRun: ', didRun)

returns

> ts-node test.ts
hello
didRun:  true
---
didRun:  false

so what we could do is wrap all the debug with e.g. debugGuard and execute the string literal in a function that would never be called in non-debug by setting debugGuard to no-op.

[ryanio]

Failing state tests should be resolved with 8ba316d

For the blockchain tests, I described the issue in further detail in ethereum/tests#837 (comment)

[ryanio]

rebased on master, updated ethereum-tests submodule to ethereum/tests@1bb7d82

[holgerd77]

Rebased this.

[ryanio]

Rebased and updated to ethereum/tests v9.0.1

[holgerd77]

This is slowly getting urgent (will add a respective label) and we should prioritize here to get the tests up and running, since london is approaching quickly and the first testnet forks are on the horizon (fork dates likely today I guess?).

So open for anyone to pick up. I've asked Dimitry on the #tooling Discord channel on the state of the ethereum/tests repo, was a bit unsure lately since there was so much activity going on.

[holgerd77]

Rebased this on top of the new config PR #1297

[holgerd77]

Ok, I guess this is working now. This needed a fix to include failed tx validation into the test runs (before it was just throwing within the test runner and going out of the test execution context), see 45b9bec.

Ready for review. 😄

[ryanio]

lgtm!

[ryanio]

@alcuadrado just a note we reintroduced the vm debug logger here but with a much more careful approach to guard string interpolation under if (this.DEBUG) statements.

Our benchmarks didn't seem to report a deviation but let us know in a next release if you notice any slow down.

Benchmark result from this PR:

Block 9422905 x 1,924 ops/sec ±3.19% (91 runs sampled)
Block 9422906 x 1,851 ops/sec ±4.79% (90 runs sampled)
Block 9422907 x 1,749 ops/sec ±9.09% (88 runs sampled)
Block 9422908 x 1,860 ops/sec ±1.05% (93 runs sampled)
Block 9422909 x 1,562 ops/sec ±10.72% (79 runs sampled)
Block 9422910 x 1,788 ops/sec ±1.17% (93 runs sampled)
Block 9422911 x 1,760 ops/sec ±1.22% (94 runs sampled)
Block 9422912 x 1,755 ops/sec ±1.14% (92 runs sampled)
Block 9422913 x 1,766 ops/sec ±1.24% (93 runs sampled)
Block 9422914 x 1,540 ops/sec ±8.80% (84 runs sampled)

[holgerd77]

Oh nice, wasn't aware of these skipped tests any more.