path: root/eth/api_tracer.go

// Copyright 2017 The go-ethereum Authors
// This file is part of the go-ethereum library.
//
// The go-ethereum library is free software: you can redistribute it and/or modify
// it under the terms of the GNU Lesser General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
//
// The go-ethereum library is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU Lesser General Public License for more details.
//
// You should have received a copy of the GNU Lesser General Public License
// along with the go-ethereum library. If not, see <http://www.gnu.org/licenses/>.

package eth

import (
    "bytes"
    "context"
    "errors"
    "fmt"
    "io/ioutil"
    "runtime"
    "sync"
    "time"

    "github.com/ethereum/go-ethereum/common"
    "github.com/ethereum/go-ethereum/common/hexutil"
    "github.com/ethereum/go-ethereum/core"
    "github.com/ethereum/go-ethereum/core/rawdb"
    "github.com/ethereum/go-ethereum/core/state"
    "github.com/ethereum/go-ethereum/core/types"
    "github.com/ethereum/go-ethereum/core/vm"
    "github.com/ethereum/go-ethereum/eth/tracers"
    "github.com/ethereum/go-ethereum/internal/ethapi"
    "github.com/ethereum/go-ethereum/log"
    "github.com/ethereum/go-ethereum/rlp"
    "github.com/ethereum/go-ethereum/rpc"
    "github.com/ethereum/go-ethereum/trie"
)

const (
    // defaultTraceTimeout is the amount of time a single transaction can execute
    // by default before being forcefully aborted.
    defaultTraceTimeout = 5 * time.Second

    // defaultTraceReexec is the number of blocks the tracer is willing to go back
    // and reexecute to produce missing historical state necessary to run a specific
    // trace.
    defaultTraceReexec = uint64(128)
)

// TraceConfig holds extra parameters to trace functions.
type TraceConfig struct {
    *vm.LogConfig
    Tracer  *string
    Timeout *string
    Reexec  *uint64
}

// txTraceResult is the result of a single transaction trace.
type txTraceResult struct {
    Result interface{} `json:"result,omitempty"` // Trace results produced by the tracer
    Error  string      `json:"error,omitempty"`  // Trace failure produced by the tracer
}

// blockTraceTask represents a single block trace task when an entire chain is
// being traced.
type blockTraceTask struct {
    statedb *state.StateDB   // Intermediate state prepped for tracing
    block   *types.Block     // Block to trace the transactions from
    rootref common.Hash      // Trie root reference held for this task
    results []*txTraceResult // Trace results procudes by the task
}

// blockTraceResult represets the results of tracing a single block when an entire
// chain is being traced.
type blockTraceResult struct {
    Block  hexutil.Uint64   `json:"block"`  // Block number corresponding to this trace
    Hash   common.Hash      `json:"hash"`   // Block hash corresponding to this trace
    Traces []*txTraceResult `json:"traces"` // Trace results produced by the task
}

// txTraceTask represents a single transaction trace task when an entire block
// is being traced.
type txTraceTask struct {
    statedb *state.StateDB // Intermediate state prepped for tracing
    index   int            // Transaction offset in the block
}

// TraceChain returns the structured logs created during the execution of EVM
// between two blocks (excluding start) and returns them as a JSON object.
func (api *PrivateDebugAPI) TraceChain(ctx context.Context, start, end rpc.BlockNumber, config *TraceConfig) (*rpc.Subscription, error) {
    // Fetch the block interval that we want to trace
    var from, to *types.Block

    switch start {
    case rpc.PendingBlockNumber:
        from = api.eth.miner.PendingBlock()
    case rpc.LatestBlockNumber:
        from = api.eth.blockchain.CurrentBlock()
    default:
        from = api.eth.blockchain.GetBlockByNumber(uint64(start))
    }
    switch end {
    case rpc.PendingBlockNumber:
        to = api.eth.miner.PendingBlock()
    case rpc.LatestBlockNumber:
        to = api.eth.blockchain.CurrentBlock()
    default:
        to = api.eth.blockchain.GetBlockByNumber(uint64(end))
    }
    // Trace the chain if we've found all our blocks
    if from == nil {
        return nil, fmt.Errorf("starting block #%d not found", start)
    }
    if to == nil {
        return nil, fmt.Errorf("end block #%d not found", end)
    }
    return api.traceChain(ctx, from, to, config)
}

// traceChain configures a new tracer according to the provided configuration, and
// executes all the transactions contained within. The return value will be one item
// per transaction, dependent on the requestd tracer.
func (api *PrivateDebugAPI) traceChain(ctx context.Context, start, end *types.Block, config *TraceConfig) (*rpc.Subscription, error) {
    // Tracing a chain is a **long** operation, only do with subscriptions
    notifier, supported := rpc.NotifierFromContext(ctx)
    if !supported {
        return &rpc.Subscription{}, rpc.ErrNotificationsUnsupported
    }
    sub := notifier.CreateSubscription()

    // Ensure we have a valid starting state before doing any work
    origin := start.NumberU64()
    database := state.NewDatabase(api.eth.ChainDb())

    if number := start.NumberU64(); number > 0 {
        start = api.eth.blockchain.GetBlock(start.ParentHash(), start.NumberU64()-1)
        if start == nil {
            return nil, fmt.Errorf("parent block #%d not found", number-1)
        }
    }
    statedb, err := state.New(start.Root(), database)
    if err != nil {
        // If the starting state is missing, allow some number of blocks to be reexecuted
        reexec := defaultTraceReexec
        if config != nil && config.Reexec != nil {
            reexec = *config.Reexec
        }
        // Find the most recent block that has the state available
        for i := uint64(0); i < reexec; i++ {
            start = api.eth.blockchain.GetBlock(start.ParentHash(), start.NumberU64()-1)
            if start == nil {
                break
            }
            if statedb, err = state.New(start.Root(), database); err == nil {
                break
            }
        }
        // If we still don't have the state available, bail out
        if err != nil {
            switch err.(type) {
            case *trie.MissingNodeError:
                return nil, errors.New("required historical state unavailable")
            default:
                return nil, err
            }
        }
    }
    // Execute all the transaction contained within the chain concurrently for each block
    blocks := int(end.NumberU64() - origin)

    threads := runtime.NumCPU()
    if threads > blocks {
        threads = blocks
    }
    var (
        pend    = new(sync.WaitGroup)
        tasks   = make(chan *blockTraceTask, threads)
        results = make(chan *blockTraceTask, threads)
    )
    for th := 0; th < threads; th++ {
        pend.Add(1)
        go func() {
            defer pend.Done()

            // Fetch and execute the next block trace tasks
            for task := range tasks {
                signer := types.MakeSigner(api.config, task.block.Number())

                // Trace all the transactions contained within
                for i, tx := range task.block.Transactions() {
                    msg, _ := tx.AsMessage(signer)
                    vmctx := core.NewEVMContext(msg, task.block.Header(), api.eth.blockchain, nil)

                    res, err := api.traceTx(ctx, msg, vmctx, task.statedb, config)
                    if err != nil {
                        task.results[i] = &txTraceResult{Error: err.Error()}
                        log.Warn("Tracing failed", "hash", tx.Hash(), "block", task.block.NumberU64(), "err", err)
                        break
                    }
                    task.statedb.Finalise(true)
                    task.results[i] = &txTraceResult{Result: res}
                }
                // Stream the result back to the user or abort on teardown
                select {
                case results <- task:
                case <-notifier.Closed():
                    return
                }
            }
        }()
    }
    // Start a goroutine to feed all the blocks into the tracers
    begin := time.Now()

    go func() {
        var (
            logged time.Time
            number uint64
            traced uint64
            failed error
            proot  common.Hash
        )
        // Ensure everything is properly cleaned up on any exit path
        defer func() {
            close(tasks)
            pend.Wait()

            switch {
            case failed != nil:
                log.Warn("Chain tracing failed", "start", start.NumberU64(), "end", end.NumberU64(), "transactions", traced, "elapsed", time.Since(begin), "err", failed)
            case number < end.NumberU64():
                log.Warn("Chain tracing aborted", "start", start.NumberU64(), "end", end.NumberU64(), "abort", number, "transactions", traced, "elapsed", time.Since(begin))
            default:
                log.Info("Chain tracing finished", "start", start.NumberU64(), "end", end.NumberU64(), "transactions", traced, "elapsed", time.Since(begin))
            }
            close(results)
        }()
        // Feed all the blocks both into the tracer, as well as fast process concurrently
        for number = start.NumberU64() + 1; number <= end.NumberU64(); number++ {
            // Stop tracing if interruption was requested
            select {
            case <-notifier.Closed():
                return
            default:
            }
            // Print progress logs if long enough time elapsed
            if time.Since(logged) > 8*time.Second {
                if number > origin {
                    nodes, imgs := database.TrieDB().Size()
                    log.Info("Tracing chain segment", "start", origin, "end", end.NumberU64(), "current", number, "transactions", traced, "elapsed", time.Since(begin), "memory", nodes+imgs)
                } else {
                    log.Info("Preparing state for chain trace", "block", number, "start", origin, "elapsed", time.Since(begin))
                }
                logged = time.Now()
            }
            // Retrieve the next block to trace
            block := api.eth.blockchain.GetBlockByNumber(number)
            if block == nil {
                failed = fmt.Errorf("block #%d not found", number)
                break
            }
            // Send the block over to the concurrent tracers (if not in the fast-forward phase)
            if number > origin {
                txs := block.Transactions()

                select {
                case tasks <- &blockTraceTask{statedb: statedb.Copy(), block: block, rootref: proot, results: make([]*txTraceResult, len(txs))}:
                case <-notifier.Closed():
                    return
                }
                traced += uint64(len(txs))
            }
            // Generate the next state snapshot fast without tracing
            _, _, _, err := api.eth.blockchain.Processor().Process(block, statedb, vm.Config{})
            if err != nil {
                failed = err
                break
            }
            // Finalize the state so any modifications are written to the trie
            root, err := statedb.Commit(true)
            if err != nil {
                failed = err
                break
            }
            if err := statedb.Reset(root); err != nil {
                failed = err
                break
            }
            // Reference the trie twice, once for us, once for the trancer
            database.TrieDB().Reference(root, common.Hash{})
            if number >= origin {
                database.TrieDB().Reference(root, common.Hash{})
            }
            // Dereference all past tries we ourselves are done working with
            if proot != (common.Hash{}) {
                database.TrieDB().Dereference(proot)
            }
            proot = root

            // TODO(karalabe): Do we need the preimages? Won't they accumulate too much?
        }
    }()

    // Keep reading the trace results and stream the to the user
    go func() {
        var (
            done = make(map[uint64]*blockTraceResult)
            next = origin + 1
        )
        for res := range results {
            // Queue up next received result
            result := &blockTraceResult{
                Block:  hexutil.Uint64(res.block.NumberU64()),
                Hash:   res.block.Hash(),
                Traces: res.results,
            }
            done[uint64(result.Block)] = result

            // Dereference any paret tries held in memory by this task
            database.TrieDB().Dereference(res.rootref)

            // Stream completed traces to the user, aborting on the first error
            for result, ok := done[next]; ok; result, ok = done[next] {
                if len(result.Traces) > 0 || next == end.NumberU64() {
                    notifier.Notify(sub.ID, result)
                }
                delete(done, next)
                next++
            }
        }
    }()
    return sub, nil
}

// TraceBlockByNumber returns the structured logs created during the execution of
// EVM and returns them as a JSON object.
func (api *PrivateDebugAPI) TraceBlockByNumber(ctx context.Context, number rpc.BlockNumber, config *TraceConfig) ([]*txTraceResult, error) {
    // Fetch the block that we want to trace
    var block *types.Block

    switch number {
    case rpc.PendingBlockNumber:
        block = api.eth.miner.PendingBlock()
    case rpc.LatestBlockNumber:
        block = api.eth.blockchain.CurrentBlock()
    default:
        block = api.eth.blockchain.GetBlockByNumber(uint64(number))
    }
    // Trace the block if it was found
    if block == nil {
        return nil, fmt.Errorf("block #%d not found", number)
    }
    return api.traceBlock(ctx, block, config)
}

// TraceBlockByHash returns the structured logs created during the execution of
// EVM and returns them as a JSON object.
func (api *PrivateDebugAPI) TraceBlockByHash(ctx context.Context, hash common.Hash, config *TraceConfig) ([]*txTraceResult, error) {
    block := api.eth.blockchain.GetBlockByHash(hash)
    if block == nil {
        return nil, fmt.Errorf("block #%x not found", hash)
    }
    return api.traceBlock(ctx, block, config)
}

// TraceBlock returns the structured logs created during the execution of EVM
// and returns them as a JSON object.
func (api *PrivateDebugAPI) TraceBlock(ctx context.Context, blob []byte, config *TraceConfig) ([]*txTraceResult, error) {
    block := new(types.Block)
    if err := rlp.Decode(bytes.NewReader(blob), block); err != nil {
        return nil, fmt.Errorf("could not decode block: %v", err)
    }
    return api.traceBlock(ctx, block, config)
}

// TraceBlockFromFile returns the structured logs created during the execution of
// EVM and returns them as a JSON object.
func (api *PrivateDebugAPI) TraceBlockFromFile(ctx context.Context, file string, config *TraceConfig) ([]*txTraceResult, error) {
    blob, err := ioutil.ReadFile(file)
    if err != nil {
        return nil, fmt.Errorf("could not read file: %v", err)
    }
    return api.TraceBlock(ctx, blob, config)
}

// traceBlock configures a new tracer according to the provided configuration, and
// executes all the transactions contained within. The return value will be one item
// per transaction, dependent on the requestd tracer.
func (api *PrivateDebugAPI) traceBlock(ctx context.Context, block *types.Block, config *TraceConfig) ([]*txTraceResult, error) {
    // Create the parent state database
    if err := api.eth.engine.VerifyHeader(api.eth.blockchain, block.Header(), true); err != nil {
        return nil, err
    }
    parent := api.eth.blockchain.GetBlock(block.ParentHash(), block.NumberU64()-1)
    if parent == nil {
        return nil, fmt.Errorf("parent %x not found", block.ParentHash())
    }
    reexec := defaultTraceReexec
    if config != nil && config.Reexec != nil {
        reexec = *config.Reexec
    }
    statedb, err := api.computeStateDB(parent, reexec)
    if err != nil {
        return nil, err
    }
    // Execute all the transaction contained within the block concurrently
    var (
        signer = types.MakeSigner(api.config, block.Number())

        txs     = block.Transactions()
        results = make([]*txTraceResult, len(txs))

        pend = new(sync.WaitGroup)
        jobs = make(chan *txTraceTask, len(txs))
    )
    threads := runtime.NumCPU()
    if threads > len(txs) {
        threads = len(txs)
    }
    for th := 0; th < threads; th++ {
        pend.Add(1)
        go func() {
            defer pend.Done()

            // Fetch and execute the next transaction trace tasks
            for task := range jobs {
                msg, _ := txs[task.index].AsMessage(signer)
                vmctx := core.NewEVMContext(msg, block.Header(), api.eth.blockchain, nil)

                res, err := api.traceTx(ctx, msg, vmctx, task.statedb, config)
                if err != nil {
                    results[task.index] = &txTraceResult{Error: err.Error()}
                    continue
                }
                results[task.index] = &txTraceResult{Result: res}
            }
        }()
    }
    // Feed the transactions into the tracers and return
    var failed error
    for i, tx := range txs {
        // Send the trace task over for execution
        jobs <- &txTraceTask{statedb: statedb.Copy(), index: i}

        // Generate the next state snapshot fast without tracing
        msg, _ := tx.AsMessage(signer)
        vmctx := core.NewEVMContext(msg, block.Header(), api.eth.blockchain, nil)

        vmenv := vm.NewEVM(vmctx, statedb, api.config, vm.Config{})
        if _, _, _, err := core.ApplyMessage(vmenv, msg, new(core.GasPool).AddGas(msg.Gas())); err != nil {
            failed = err
            break
        }
        // Finalize the state so any modifications are written to the trie
        statedb.Finalise(true)
    }
    close(jobs)
    pend.Wait()

    // If execution failed in between, abort
    if failed != nil {
        return nil, failed
    }
    return results, nil
}

// computeStateDB retrieves the state database associated with a certain block.
// If no state is locally available for the given block, a number of blocks are
// attempted to be reexecuted to generate the desired state.
func (api *PrivateDebugAPI) computeStateDB(block *types.Block, reexec uint64) (*state.StateDB, error) {
    // If we have the state fully available, use that
    statedb, err := api.eth.blockchain.StateAt(block.Root())
    if err == nil {
        return statedb, nil
    }
    // Otherwise try to reexec blocks until we find a state or reach our limit
    origin := block.NumberU64()
    database := state.NewDatabase(api.eth.ChainDb())

    for i := uint64(0); i < reexec; i++ {
        block = api.eth.blockchain.GetBlock(block.ParentHash(), block.NumberU64()-1)
        if block == nil {
            break
        }
        if statedb, err = state.New(block.Root(), database); err == nil {
            break
        }
    }
    if err != nil {
        switch err.(type) {
        case *trie.MissingNodeError:
            return nil, errors.New("required historical state unavailable")
        default:
            return nil, err
        }
    }
    // State was available at historical point, regenerate
    var (
        start  = time.Now()
        logged time.Time
        proot  common.Hash
    )
    for block.NumberU64() < origin {
        // Print progress logs if long enough time elapsed
        if time.Since(logged) > 8*time.Second {
            log.Info("Regenerating historical state", "block", block.NumberU64()+1, "target", origin, "elapsed", time.Since(start))
            logged = time.Now()
        }
        // Retrieve the next block to regenerate and process it
        if block = api.eth.blockchain.GetBlockByNumber(block.NumberU64() + 1); block == nil {
            return nil, fmt.Errorf("block #%d not found", block.NumberU64()+1)
        }
        _, _, _, err := api.eth.blockchain.Processor().Process(block, statedb, vm.Config{})
        if err != nil {
            return nil, err
        }
        // Finalize the state so any modifications are written to the trie
        root, err := statedb.Commit(true)
        if err != nil {
            return nil, err
        }
        if err := statedb.Reset(root); err != nil {
            return nil, err
        }
        database.TrieDB().Reference(root, common.Hash{})
        if proot != (common.Hash{}) {
            database.TrieDB().Dereference(proot)
        }
        proot = root
    }
    nodes, imgs := database.TrieDB().Size()
    log.Info("Historical state regenerated", "block", block.NumberU64(), "elapsed", time.Since(start), "nodes", nodes, "preimages", imgs)
    return statedb, nil
}

// TraceTransaction returns the structured logs created during the execution of EVM
// and returns them as a JSON object.
func (api *PrivateDebugAPI) TraceTransaction(ctx context.Context, hash common.Hash, config *TraceConfig) (interface{}, error) {
    // Retrieve the transaction and assemble its EVM context
    tx, blockHash, _, index := rawdb.ReadTransaction(api.eth.ChainDb(), hash)
    if tx == nil {
        return nil, fmt.Errorf("transaction %x not found", hash)
    }
    reexec := defaultTraceReexec
    if config != nil && config.Reexec != nil {
        reexec = *config.Reexec
    }
    msg, vmctx, statedb, err := api.computeTxEnv(blockHash, int(index), reexec)
    if err != nil {
        return nil, err
    }
    // Trace the transaction and return
    return api.traceTx(ctx, msg, vmctx, statedb, config)
}

// traceTx configures a new tracer according to the provided configuration, and
// executes the given message in the provided environment. The return value will
// be tracer dependent.
func (api *PrivateDebugAPI) traceTx(ctx context.Context, message core.Message, vmctx vm.Context, statedb *state.StateDB, config *TraceConfig) (interface{}, error) {
    // Assemble the structured logger or the JavaScript tracer
    var (
        tracer vm.Tracer
        err    error
    )
    switch {
    case config != nil && config.Tracer != nil:
        // Define a meaningful timeout of a single transaction trace
        timeout := defaultTraceTimeout
        if config.Timeout != nil {
            if timeout, err = time.ParseDuration(*config.Timeout); err != nil {
                return nil, err
            }
        }
        // Constuct the JavaScript tracer to execute with
        if tracer, err = tracers.New(*config.Tracer); err != nil {
            return nil, err
        }
        // Handle timeouts and RPC cancellations
        deadlineCtx, cancel := context.WithTimeout(ctx, timeout)
        go func() {
            <-deadlineCtx.Done()
            tracer.(*tracers.Tracer).Stop(errors.New("execution timeout"))
        }()
        defer cancel()

    case config == nil:
        tracer = vm.NewStructLogger(nil)

    default:
        tracer = vm.NewStructLogger(config.LogConfig)
    }
    // Run the transaction with tracing enabled.
    vmenv := vm.NewEVM(vmctx, statedb, api.config, vm.Config{Debug: true, Tracer: tracer})

    ret, gas, failed, err := core.ApplyMessage(vmenv, message, new(core.GasPool).AddGas(message.Gas()))
    if err != nil {
        return nil, fmt.Errorf("tracing failed: %v", err)
    }
    // Depending on the tracer type, format and return the output
    switch tracer := tracer.(type) {
    case *vm.StructLogger:
        return &ethapi.ExecutionResult{
            Gas:         gas,
            Failed:      failed,
            ReturnValue: fmt.Sprintf("%x", ret),
            StructLogs:  ethapi.FormatLogs(tracer.StructLogs()),
        }, nil

    case *tracers.Tracer:
        return tracer.GetResult()

    default:
        panic(fmt.Sprintf("bad tracer type %T", tracer))
    }
}

// computeTxEnv returns the execution environment of a certain transaction.
func (api *PrivateDebugAPI) computeTxEnv(blockHash common.Hash, txIndex int, reexec uint64) (core.Message, vm.Context, *state.StateDB, error) {
    // Create the parent state database
    block := api.eth.blockchain.GetBlockByHash(blockHash)
    if block == nil {
        return nil, vm.Context{}, nil, fmt.Errorf("block %x not found", blockHash)
    }
    parent := api.eth.blockchain.GetBlock(block.ParentHash(), block.NumberU64()-1)
    if parent == nil {
        return nil, vm.Context{}, nil, fmt.Errorf("parent %x not found", block.ParentHash())
    }
    statedb, err := api.computeStateDB(parent, reexec)
    if err != nil {
        return nil, vm.Context{}, nil, err
    }
    // Recompute transactions up to the target index.
    signer := types.MakeSigner(api.config, block.Number())

    for idx, tx := range block.Transactions() {
        // Assemble the transaction call message and return if the requested offset
        msg, _ := tx.AsMessage(signer)
        context := core.NewEVMContext(msg, block.Header(), api.eth.blockchain, nil)
        if idx == txIndex {
            return msg, context, statedb, nil
        }
        // Not yet the searched for transaction, execute on top of the current state
        vmenv := vm.NewEVM(context, statedb, api.config, vm.Config{})
        if _, _, _, err := core.ApplyMessage(vmenv, msg, new(core.GasPool).AddGas(tx.Gas())); err != nil {
            return nil, vm.Context{}, nil, fmt.Errorf("tx %x failed: %v", tx.Hash(), err)
        }
        // Ensure any modifications are committed to the state
        statedb.Finalise(true)
    }
    return nil, vm.Context{}, nil, fmt.Errorf("tx index %d out of range for block %x", txIndex, blockHash)
}