Client -> Mainnet: Consensus Error on block 226522 "invalid receipt trie"

[holgerd77]

Yeah, we have our first consensus error - a real repeatable one and not some of this race condition stuff. 😅 I find this somewhat of a relief to now come to the "real stuff" after all this infrastructure code writing since this was one of the main reasons the client was build for. 🥳

Since this one is relatively early - on block 226522 - I would expect more to come further down the line, but we'll see.

Just pasting the stack trace here, haven't dug deeper into what's wrong:

ERROR [01-29|23:10:05] Error: invalid receiptTrie
    at VM.runBlock (/EthereumJS/ethereumjs-vm/packages/vm/dist/runBlock.js:88:19)
    at async /EthereumJS/ethereumjs-vm/packages/client/dist/lib/sync/execution/vmexecution.js:101:21
    at async /EthereumJS/ethereumjs-vm/packages/blockchain/dist/index.js:909:21
    at async Blockchain.runWithLock (/EthereumJS/ethereumjs-vm/packages/blockchain/dist/index.js:262:27)
    at async Blockchain.initAndLock (/EthereumJS/ethereumjs-vm/packages/blockchain/dist/index.js:250:16)
    at async Blockchain._iterator (/EthereumJS/ethereumjs-vm/packages/blockchain/dist/index.js:891:16)
    at async VMExecution.run (/EthereumJS/ethereumjs-vm/packages/client/dist/lib/sync/execution/vmexecution.js:147:28)
    at async Chain.<anonymous> (/EthereumJS/ethereumjs-vm/packages/client/dist/lib/sync/fullsync.js:32:17)

Curious to see how the debugging of such an error goes (we'll likely need stack traces for this from another client?).

[jochem-brouwer]

This is exciting! 😄

Optimally, we would get stack traces. However, (in this case), we can quickly figure out which transaction goes wrong: to do that, we download each receipt of the block (we can do that over web3), and compare those to our outputs. These are very helpful, as they contain, for instance, gasUsed. So we can figure out which transaction(s) is/are wrong, and in most cases gasUsed is the problem.

[jochem-brouwer]

Well we don't have to do that in this case, since the block only has one transaction 😅

[holgerd77]

Hmm, I think the tricky part here will be to actually attribute this to a cause and e.g. do an interpretation what actually caused a wrong gasUsed calculation, can you just state this from looking at a receipt? 🤔 Maybe in really simple cases. But we'll see. 😄

[jochem-brouwer]

Usually the gas difference between the reported one and the actual one is a very specific number, which can be used as a clue where to look. But we should get a trace via debug_traceTransaction though.

[holgerd77]

Ok, this is the block (as seen by our client, should be the same though):

{
    "header": {
        "parentHash": "0xd9b7336ac322a4fa9904dcca42f127b43b3e5829a313e661bb2142ce900fdf45",
        "uncleHash": "0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347",
        "coinbase": "0x52bc44d5378309ee2abf1539bf71de1b7d7be3b5",
        "stateRoot": "0xfc5c217e8a5b003ff7da5a80c39e986e212fb02bad8fe17cd27d92a2b5963fa5",
        "transactionsTrie": "0x7e9c2d95a5b99c122d269f149f0804a3b1b157ec22693389cd2c5db8b1e9d94b",
        "receiptTrie": "0xf1fd7ec09270db8b1f4c78fd933a93bdca77626bfc3e9484bdabfdfdf0d868a7",
        "bloom": "0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000",
        "difficulty": "0x6647c8f3e9e",
        "number": "0x374da",
        "gasLimit": "0x2fefd8",
        "gasUsed": "0x1f86b",
        "timestamp": "0x55f4f963",
        "extraData": "0xd783010103844765746887676f312e342e32856c696e7578",
        "mixHash": "0x5d3c9f8cfbf703341816f0769d99925ee8d4fd8b432aa3609e15b772e9b2384a",
        "nonce": "0xee920bf60079e087"
    },
    "transactions": [
        {
            "nonce": "0x1a",
            "gasPrice": "0xba43b7400",
            "gasLimit": "0x493e0",
            "to": "0x9ca228250f9d8f86c23690074c2b96d5f5479f79",
            "value": "0x0",
            "data": "0xa9059cbb000000000000000000000000bfe465e7eb5a2928b5bf22bef93ad06089dc6179000000000000000000000000000000000000000000000000006a94d74f430000",
            "v": "0x1c",
            "r": "0xc04f048766bea3b20dcea6d2fcaecc92f1a615d337606ab6eec2a1e8e1f27bfe",
            "s": "0x1c57e62653724560b06c95be750d958840db9fa44ffa777b6625b344bfadbbcf"
        }
    ],
    "uncleHeaders": []
}

[holgerd77]

And this is the receipt produced by our VM:

{
  stateRoot: <Buffer a3 d2 8b c1 9c 14 27 e1 df a4 5f 85 bb 12 d2 4c c7 1e 8f 0d 94 eb 71 01 fa 2b 05 5c 25 62 5d 34>,
  gasUsed: <Buffer 01 f8 6b>,
  bitvector: <Buffer 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ... 206 more bytes>,
  logs: []
}

Decimal gas used is: 129131

[jochem-brouwer]

Weird, that's the same amount as the block indicates. It can only be the state root, I guess.

Can you check if the before/after values of the storage slots are the same as these diffs reported by etherscan?

[holgerd77]

Here is the receipt as received by Ethers:

{
  to: '0x9Ca228250f9D8f86c23690074C2B96D5F5479f79',
  from: '0x147013436bD5c7DeF49a8e27c7Fba8Ac2B9dFE1F',
  contractAddress: null,
  transactionIndex: 0,
  root: '0x9d735b19daf3205f93e60f3eb02df6b211aebb4d3a2c512cb51055d8ecfb35c1',
  gasUsed: BigNumber { _hex: '0x01f86b', _isBigNumber: true },
  logsBloom: '0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000',
  blockHash: '0x63de8ba970ca56da5f12d5c4ff826501ab4e945f36338ae20be42f9e42e13b7a',
  transactionHash: '0x8420dbe268209c4e921bf6b78bc9fb959d9d9553fd16aacb9dd8cad955dbe729',
  logs: [],
  blockNumber: 226522,
  confirmations: 11545200,
  cumulativeGasUsed: BigNumber { _hex: '0x01f86b', _isBigNumber: true }
}

[holgerd77]

By adding some console.log statement in applyTransactions() (VM.runBlock()):

INFO [02-01|18:51:23] Imported blocks count=50 number=227859 hash=cdeb5d1c... hardfork=chainstart peers=3
0x147013436bD5c7DeF49a8e27c7Fba8Ac2B9dFE1F: 662316050000000000
0x52bc44d5378309EE2abF1539BF71dE1b7d7bE3b5: 2802482286953546035527
0x8398fF6c618e9515468c1c4b198d53666CBe8462: 0
0x9Ca228250f9D8f86c23690074C2B96D5F5479f79: 10000000000000000
WARN [02-01|18:51:23] Execution of block number=226522 hash=63de8ba9... failed

[holgerd77]

0x8398fF6c618e9515468c1c4b198d53666CBe8462 is not correct, should be 30000000000000000.

[holgerd77]

Some more debugging (in evm.ts), tx has the following messages executed: call -> create -> call, these are run with the following message objects in executeMessage():

Execute call
Message {
  to: Address {
    buf: <Buffer 83 98 ff 6c 61 8e 95 15 46 8c 1c 4b 19 8d 53 66 6c be 84 62>
  },
  value: <BN: 0>,
  caller: Address {
    buf: <Buffer 9c a2 28 25 0f 9d 8f 86 c2 36 90 07 4c 2b 96 d5 f5 47 9f 79>
  },
  gasLimit: <BN: 3b85d>,
  data: <Buffer >,
  depth: 1,
  code: <Buffer 60 60 60 40 52 60 40 51 60 60 80 61 0a 44 83 39 01 60 40 52 60 60 80 51 90 60 20 01 80 51 90 60 20 01 80 51 90 60 20 01 50 5b 82 60 00 60 00 61 01 00 ... 2674 more bytes>,
  _codeAddress: undefined,
  isStatic: false,
  isCompiled: false,
  salt: null,
  selfdestruct: {},
  delegatecall: false
}

Execute create
Message {
  to: Address {
    buf: <Buffer 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00>
  },
  value: <BN: 6a94d74f430000>,
  caller: Address {
    buf: <Buffer 9c a2 28 25 0f 9d 8f 86 c2 36 90 07 4c 2b 96 d5 f5 47 9f 79>
  },
  gasLimit: <BN: 8fc>,
  data: <Buffer >,
  depth: 1,
  code: <Buffer >,
  _codeAddress: undefined,
  isStatic: false,
  isCompiled: false,
  salt: undefined,
  selfdestruct: {},
  delegatecall: false
}

Execute call
Message {
  to: Address {
    buf: <Buffer 9c a2 28 25 0f 9d 8f 86 c2 36 90 07 4c 2b 96 d5 f5 47 9f 79>
  },
  value: <BN: 0>,
  caller: Address {
    buf: <Buffer 14 70 13 43 6b d5 c7 de f4 9a 8e 27 c7 fb a8 ac 2b 9d fe 1f>
  },
  gasLimit: <BN: 43988>,
  data: <Buffer a9 05 9c bb 00 00 00 00 00 00 00 00 00 00 00 00 bf e4 65 e7 eb 5a 29 28 b5 bf 22 be f9 3a d0 60 89 dc 61 79 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ... 18 more bytes>,
  depth: 0,
  code: <Buffer 60 60 60 40 52 60 00 35 7c 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 90 04 80 63 27 e2 35 e3 14 61 00 65 ... 3402 more bytes>,
  _codeAddress: undefined,
  isStatic: false,
  isCompiled: false,
  salt: undefined,
  selfdestruct: undefined,
  delegatecall: false
}

[holgerd77]

If I read correctly from Etherscan, the value from the second call is not correct being 0 and this should be rather the respective 30000000000000000 value, is this correct?

[holgerd77]

Ok, will stop for today.

[ryanio]

@holgerd77 that might be it:

[holgerd77]

Guess it's somewhere in the 0xf1: CALL opcode, this is actually called still with the correct 30000000000000000 value.

[holgerd77]

First attempt to isolate the code run here, not sure if this is creating all the necessary context, but it at least runs through:

const level = require('level')
import Common from '@ethereumjs/common'
import { Block } from '@ethereumjs/block'
import { Transaction } from '@ethereumjs/tx'
import VM from './lib'
import { SecureTrie as Trie } from '@ethereumjs/trie'
import { DefaultStateManager } from './lib/state'

const main = async () => {
  const common = new Common({ chain: 'mainnet', hardfork: 'chainstart' })
  const block = Block.fromBlockData(
    {
      header: {
        // Ensures our fees get added to coinbase after we run the Tx (this is important for the state root in the receipt)
        coinbase: Buffer.from('52bc44d5378309ee2abf1539bf71de1b7d7be3b5', 'hex'),
      },
    },
    { common }
  )

  const txData = {
    "nonce": "0x1a",
    "gasPrice": "0xba43b7400",
    "gasLimit": "0x493e0",
    "to": "0x9ca228250f9d8f86c23690074c2b96d5f5479f79",
    "value": "0x0",
    "data": "0xa9059cbb000000000000000000000000bfe465e7eb5a2928b5bf22bef93ad06089dc6179000000000000000000000000000000000000000000000000006a94d74f430000",
    "v": "0x1c",
    "r": "0xc04f048766bea3b20dcea6d2fcaecc92f1a615d337606ab6eec2a1e8e1f27bfe",
    "s": "0x1c57e62653724560b06c95be750d958840db9fa44ffa777b6625b344bfadbbcf"
  }
  const tx = Transaction.fromTxData(txData, { common })
  const trie = new Trie(level('/Users/hdrewes/Library/Ethereum/ethereumjs/mainnet/state/'))
  const stateManager = new DefaultStateManager({ trie, common })
  // Ensure we run on the right root
  stateManager.setStateRoot(Buffer.from('9dceb42e227ee6a244449d1d92cc5e0c17c63b520d0ff050d943baa8055d0ca6', 'hex'))
  const vm = new VM({ stateManager, common })

  const result = await vm.runTx({ tx, skipBalance: true, skipNonce: true, block })
  //console.log(result)
}

main()

Feel free to further improve on the code. This might also be handy for future debugging sessions. We might want to add scripts like this in an extra scripts folder on the client for convenience.

Update: some updates on the code, a more recent example might be found along #1081

[jochem-brouwer]

We won't be able to reproduce this, since we don't have access to your DB. It should be sufficient to dump all the data it accesses (so in particular, the origin account, the contract account (so code/balance)). If there are any SLOADs or SSTOREs then these values should also be made available.

So do I get this right? We actually do have an internal call, which has the right call value? But somehow this does not end up in the account? I can think of two things here which might go wrong, (1) we are internally manipulating a BN/Buffer wrong (similar to #733), or, possibly, the checkpoint memory cache thing which I recently added is bugged?

[holgerd77]

@jochem-brouwer of course you do, you just have to sync up to the respective block, this is a consensus error! 😄

Doesn't take very long, just 30-60 minutes. I guess for now we doesn't need a server for this, I assume that in the next weeks we will just go "in sync" on mainnet towards the next consensus bug or performance bottle neck blocks which we likely want to tackle together, and at the end it is more practical to have the databases locally for debugging.

It is also pretty handy to do local copies of the ethereumjs folder with certain snapshots on various states of block sync, than one can easily switch here. 😄 I've got 8 or so laying around in the meantime (ethereumjs-backup-60000, ethereumjs-backup-100000, ethereumjs-backup-200000,...).

[holgerd77]

Output of a run with the new debug feature from #1080, haven't done any analysis on this yet:

[holgerd77]

Ah, the second call is taking a nonsense to address (the zero address)? 🤔

[jochem-brouwer]

Hah yes you are right regarding that I should just sync 😅

Can you check the stack traces? (Via VMs step event). We have to figure out where this 0 address comes from.

[holgerd77]

The behavior of this code part seems to be wrong (the first Frontier case is triggered):

// If enough gas and allowed code size
if (
  totalGas.lte(message.gasLimit) &&
  (this._vm._allowUnlimitedContractSize || allowedCodeSize)
) {
  result.gasUsed = totalGas
} else {
  if (this._vm._common.gteHardfork('homestead')) {
    debug(`Not enough gas or code size not allowed (>= Homestead)`)
    result = { ...result, ...OOGResult(message.gasLimit) }
  } else {
    // we are in Frontier
    debug(`Not enough gas or code size not allowed (Frontier)`)
    if (totalGas.sub(returnFee).lte(message.gasLimit)) {
      // we cannot pay the code deposit fee (but the deposit code actually did run)
      result = { ...result, ...COOGResult(totalGas.sub(returnFee)) }
    } else {
      result = { ...result, ...OOGResult(message.gasLimit) }
    }
  }
}

If one is changing result = { ...result, ...COOGResult(totalGas.sub(returnFee)) } to result.gasUsed = totalGas.sub(returnFee) (so not overwriting the returnValue and not setting an error), the contract gets deployed some lines later (so: put into the state) and the call is executed towards the correct recipient (but receipt trie is still not correct):

This seems to have to do with the following behavior from the Homestead fork, respectively the behavior which should have been in place before in Frontier described in the EIP:

3. If contract creation does not have enough gas to pay for the final gas fee for adding the contract code to the state, the contract creation fails (i.e. goes out-of-gas) rather than leaving an empty contract.

My interpretation (or rather: assumption) here is that the contract call should run with this code - somewhat temporarily deployed - but at the end of the tx the contract / new account should not stay in the state? Might this be correct?

[jochem-brouwer]

(Just finished my exam 😄 ). So the contract creation fails on our VM? This does not seem to be the case on the chain; the contract is successfully deployed. See the parity trace and also the internal transactions on etherscan (does not show a failing internal transaction to the target address).

I'm currently also syncing the chain, ready to get 🔍 this 😄

[jochem-brouwer]

Just checked your reproduction code, it doesn't seem to be running the same code. It then only uses about 17k gas. If I set the trie's root to the state root of the previous block, it runs out of gas. I am running this in the VM package (and I did reproduce the failing block on client), you are also running it within VM right?

[jochem-brouwer]

Figured out what the problem was (w.r.t. reproduce script); VM does not run on Frontier. I have put some progress in #1081, please read my comments on there (I "reviewed" myself). The 0.03 eth now gets transfered to the right address, but it does not yet solve the problem, as there's a storage value which has an incorrect value. Will stop here.

But yes, you were right regarding which rule this seems to be about 😄

[holgerd77]

@jochem-brouwer thanks for having a look into this, great! 😄

As a side note: I updated the example code from above with a Common instance (have also edited the post above with the new code), this is still not working properly but going out with "Exit early on no code or value tranfer overflowed":

Did you actually have an example running which was working, and did you add anything else? (I would just find it nice if we once have a working example since this might be useful for similar future situations where we need to re-create VM runs from the client.

Other side note: also opened this issue here #1082 on the behavior of this first wrong example case since I have the impression the current behavior on such a case is not really fortunate for the end user (longer description in the issue).

[holgerd77]

@jochem-brouwer ah, just answered the example question myself by having a look at your test run code from #1081 and discovering:

// Ensure we run on the right root
  trie._setRoot(
    Buffer.from('9dceb42e227ee6a244449d1d92cc5e0c17c63b520d0ff050d943baa8055d0ca6', 'hex')
  )

😄

[holgerd77]

Fixed by #1081