VM Debugging

packages/vm/README.md

@@ -167,6 +167,43 @@ by it, the exception will bubble into the VM and interrupt it, possibly
 corrupting its state. It's strongly recommended not to throw from withing
 event handlers.
 
+# Understanding the VM
+
+If you want to understand your VM runs we have added a hierarchically structured list of debug loggers for your convenience which can be activated in arbitrary combinations. We also use these loggers internally for development and testing. These loggers use the [debug](https://github.com/visionmedia/debug) library and can be activated on the CL with `DEBUG=[Logger Selection] node [Your Script to Run].js` and produce output like the following:
+
+![EthereumJS VM Debug Logger](./debug.png?raw=true)
+
+The following loggers are currently available:
+
+| Logger | Description |
+| - | - |
+| `vm:tx` | Transaction operations (account updates, checkpointing,...) |
+| `vm:tx:gas` | Transaction gas logger |
+| `vm:evm` | EVM control flow, CALL or CREATE message execution |
+| `vm:evm:gas` | EVM gas logger |
+| `vm:ops` | Opcode traces |
+| `vm:ops:[Lower-case opcode name]` | Traces on a specific opcode |
+
+Here are some examples for useful logger combinations.
+
+Run one specific logger:
+
+```shell
+DEBUG=vm:tx ts-node test.ts
+```
+
+Run all loggers currently available:
+
+```shell
+DEBUG=vm:*,vm:*:* ts-node test.ts
+```
+
+Run some specific loggers including a logger specifically logging the `SSTORE` executions from the VM (this is from the screenshot above):
+
+```shell
+DEBUG=vm:tx,vm:evm,vm:ops:sstore,vm:*:gas ts-node test.ts
+```
+
 # Internal Structure
 
 The VM processes state changes at many levels.

packages/vm/lib/evm/evm.ts

@@ -1,3 +1,4 @@
+import { debug as createDebugLogger } from 'debug'
 import {
   Account,
   Address,
@@ -14,8 +15,12 @@ import { getPrecompile, PrecompileFunc } from './precompiles'
 import TxContext from './txContext'
 import Message from './message'
 import EEI from './eei'
+import { short } from './opcodes/util'
 import { default as Interpreter, InterpreterOpts, RunState } from './interpreter'
 
+const debug = createDebugLogger('vm:evm')
+const debugGas = createDebugLogger('vm:evm:gas')
+
 /**
  * Result of executing a message via the [[EVM]].
  */
@@ -132,13 +137,31 @@ export default class EVM {
     await this._vm._emit('beforeMessage', message)
 
     await this._state.checkpoint()
+    debug('-'.repeat(100))
+    debug(`message checkpoint`)
 
     let result
+    debug(
+      `New message caller=${message.caller.toString()} gasLimit=${message.gasLimit.toString()} to=${
+        message.to ? message.to.toString() : ''
+      } value=${message.value.toString()} delegatecall=${message.delegatecall ? 'yes' : 'no'}`
+    )
     if (message.to) {
+      debug(`Message CALL execution (to: ${message.to.toString()})`)
       result = await this._executeCall(message)
     } else {
+      debug(`Message CREATE execution (to undefined)`)
       result = await this._executeCreate(message)
     }
+    debug(
+      `Received message results gasUsed=${result.gasUsed} execResult: [ gasUsed=${
+        result.gasUsed
+      } exceptionError=${
+        result.execResult.exceptionError ? result.execResult.exceptionError.toString() : ''
+      } returnValue=${short(
+        result.execResult.returnValue
+      )} gasRefund=${result.execResult.gasRefund?.toString()} ]`
+    )
     // TODO: Move `gasRefund` to a tx-level result object
     // instead of `ExecResult`.
     result.execResult.gasRefund = this._refund.clone()
@@ -148,13 +171,16 @@ export default class EVM {
       if (this._vm._common.gteHardfork('homestead') || err.error != ERROR.CODESTORE_OUT_OF_GAS) {
         result.execResult.logs = []
         await this._state.revert()
+        debug(`message checkpoint reverted`)
       } else {
         // we are in chainstart and the error was the code deposit error
         // we do like nothing happened.
         await this._state.commit()
+        debug(`message checkpoint committed`)
       }
     } else {
       await this._state.commit()
+      debug(`message checkpoint committed`)
     }
 
     await this._vm._emit('afterMessage', result)
@@ -182,8 +208,8 @@ export default class EVM {
 
     // Load code
     await this._loadCode(message)
-    // Exit early if there's no code or value transfer overflowed
     if (!message.code || message.code.length === 0 || errorMessage) {
+      debug(`Exit early on no code or value tranfer overflowed`)
       return {
         gasUsed: new BN(0),
         execResult: {
@@ -196,12 +222,14 @@ export default class EVM {
 
     let result: ExecResult
     if (message.isCompiled) {
+      debug(`Run precompile`)
       result = await this.runPrecompile(
         message.code as PrecompileFunc,
         message.data,
         message.gasLimit
       )
     } else {
+      debug(`Start bytecode processing...`)
       result = await this.runInterpreter(message)
     }
 
@@ -219,9 +247,11 @@ export default class EVM {
     message.code = message.data
     message.data = Buffer.alloc(0)
     message.to = await this._generateAddress(message)
+    debug(`Generated CREATE contract address ${message.to.toString()}`)
     let toAccount = await this._state.getAccount(message.to)
     // Check for collision
     if ((toAccount.nonce && toAccount.nonce.gtn(0)) || !toAccount.codeHash.equals(KECCAK256_NULL)) {
+      debug(`Returning on address collision`)
       return {
         gasUsed: message.gasLimit,
         createdAddress: message.to,
@@ -256,8 +286,8 @@ export default class EVM {
       errorMessage = e
     }
 
-    // Exit early if there's no contract code or value transfer overflowed
     if (!message.code || message.code.length === 0 || errorMessage) {
+      debug(`Exit early on no code or value tranfer overflowed`)
       return {
         gasUsed: new BN(0),
         createdAddress: message.to,
@@ -269,6 +299,7 @@ export default class EVM {
       }
     }
 
+    debug(`Start bytecode processing...`)
     let result = await this.runInterpreter(message)
 
     // fee for size of the return value
@@ -279,6 +310,9 @@ export default class EVM {
         this._vm._common.param('gasPrices', 'createData')
       )
       totalGas = totalGas.add(returnFee)
+      debugGas(
+        `Add return value size fee (${returnFee.toString()} to gas used (-> ${totalGas.toString()}))`
+      )
     }
 
     // Check for SpuriousDragon EIP-170 code size limit
@@ -297,12 +331,15 @@ export default class EVM {
       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)) }
+          //result = { ...result, ...COOGResult(totalGas.sub(returnFee)) }
+          result.gasUsed = totalGas.sub(returnFee)
         } else {
           result = { ...result, ...OOGResult(message.gasLimit) }
         }
@@ -312,6 +349,7 @@ export default class EVM {
     // Save code if a new contract was created
     if (!result.exceptionError && result.returnValue && result.returnValue.toString() !== '') {
       await this._state.putContractCode(message.to, result.returnValue)
+      debug(`Code saved on new contract creation`)
     }
 
     return {
@@ -438,7 +476,9 @@ export default class EVM {
 
   async _reduceSenderBalance(account: Account, message: Message): Promise<void> {
     account.balance.isub(message.value)
-    return this._state.putAccount(message.caller, account)
+    const result = this._state.putAccount(message.caller, account)
+    debug(`Reduce sender (${message.caller.toString()}) balance (-> ${account.balance.toString()})`)
+    return result
   }
 
   async _addToBalance(toAccount: Account, message: Message): Promise<void> {
@@ -448,7 +488,9 @@ export default class EVM {
     }
     toAccount.balance = newBalance
     // putAccount as the nonce may have changed for contract creation
-    return this._state.putAccount(message.to, toAccount)
+    const result = this._state.putAccount(message.to, toAccount)
+    debug(`Add toAccount (${message.to.toString()}) balance (-> ${toAccount.balance.toString()})`)
+    return result
   }
 
   async _touchAccount(address: Address): Promise<void> {

packages/vm/lib/evm/interpreter.ts

@@ -1,3 +1,4 @@
+import { debug as createDebugLogger } from 'debug'
 import { Account, Address, BN } from 'ethereumjs-util'
 import Common from '@ethereumjs/common'
 import { StateManager } from '../state/index'
@@ -68,6 +69,9 @@ export default class Interpreter {
   _runState: RunState
   _eei: EEI
 
+  // Opcode debuggers (e.g. { 'push': [debug Object], 'sstore': [debug Object], ...})
+  private opDebuggers: any = {}
+
   constructor(vm: any, eei: EEI) {
     this._vm = vm // TODO: remove when not needed
     this._state = vm.stateManager
@@ -193,6 +197,29 @@ export default class Interpreter {
       memoryWordCount: this._runState.memoryWordCount,
       codeAddress: this._eei._env.codeAddress,
     }
+
+    // Create opTrace for debug functionality
+    let hexStack = []
+    hexStack = eventObj.stack.map((item: any) => {
+      return '0x' + new BN(item).toString(16, 0)
+    })
+
+    const name = eventObj.opcode.name
+    const nameLC = name.toLowerCase()
+    const opTrace = {
+      pc: eventObj.pc,
+      op: name,
+      gas: '0x' + eventObj.gasLeft.toString('hex'),
+      gasCost: '0x' + eventObj.opcode.fee.toString(16),
+      stack: hexStack,
+      depth: eventObj.depth,
+    }
+
+    if (!(nameLC in this.opDebuggers)) {
+      this.opDebuggers[nameLC] = createDebugLogger(`vm:ops:${nameLC}`)
+    }
+    this.opDebuggers[nameLC](JSON.stringify(opTrace))
+
     /**
      * The `step` event for trace output
      *

packages/vm/lib/evm/opcodes/util.ts

@@ -72,6 +72,15 @@ export function divCeil(a: BN, b: BN): BN {
   return div.isNeg() ? div.isubn(1) : div.iaddn(1)
 }
 
+export function short(buffer: Buffer): string {
+  const MAX_LENGTH = 50
+  const bufferStr = buffer.toString('hex')
+  if (bufferStr.length <= MAX_LENGTH) {
+    return bufferStr
+  }
+  return bufferStr.slice(0, MAX_LENGTH) + '...'
+}
+
 /**
  * Calls relevant stateManager.getContractStorage method based on hardfork
  *