diff --git a/fvm/evm/debug/tracer.go b/fvm/evm/debug/tracer.go index 58df192073e..0a047aed3df 100644 --- a/fvm/evm/debug/tracer.go +++ b/fvm/evm/debug/tracer.go @@ -32,11 +32,12 @@ type EVMTracer interface { var _ EVMTracer = &CallTracer{} type CallTracer struct { - logger zerolog.Logger - tracer *tracers.Tracer - tracerConfig []byte - uploader Uploader - blockID flow.Identifier + logger zerolog.Logger + tracer *tracers.Tracer + resultsByTxID map[gethCommon.Hash]json.RawMessage + tracerConfig []byte + uploader Uploader + blockID flow.Identifier } func NewEVMCallTracer(uploader Uploader, logger zerolog.Logger) (*CallTracer, error) { @@ -48,10 +49,11 @@ func NewEVMCallTracer(uploader Uploader, logger zerolog.Logger) (*CallTracer, er } return &CallTracer{ - logger: logger.With().Str("module", "evm-tracer").Logger(), - tracer: tracer, - tracerConfig: tracerConfig, - uploader: uploader, + logger: logger.With().Str("module", "evm-tracer").Logger(), + tracer: tracer, + resultsByTxID: make(map[gethCommon.Hash]json.RawMessage), + tracerConfig: tracerConfig, + uploader: uploader, }, nil } @@ -69,6 +71,10 @@ func (t *CallTracer) WithBlockID(id flow.Identifier) { t.blockID = id } +func (t *CallTracer) GetResultByTxHash(txID gethCommon.Hash) json.RawMessage { + return t.resultsByTxID[txID] +} + func (t *CallTracer) Collect(txID gethCommon.Hash) { // upload is concurrent and it doesn't produce any errors, as the // client doesn't expect it, we don't want to break execution flow, @@ -93,26 +99,19 @@ func (t *CallTracer) Collect(txID gethCommon.Hash) { } }() - res, err := t.tracer.GetResult() - if err != nil { - l.Error().Err(err).Msg("failed to produce trace results") - } - - // reset tracing to have fresh state - if err := t.ResetTracer(); err != nil { - l.Error().Err(err). - Str("traces", string(res)). - Msg("failed to reset trace") + res, found := t.resultsByTxID[txID] + if !found { + l.Error().Msg("trace result not found") return } - - if err = t.uploader.Upload(TraceID(txID, t.blockID), res); err != nil { + if err := t.uploader.Upload(TraceID(txID, t.blockID), res); err != nil { l.Error().Err(err). Str("traces", string(res)). Msg("failed to upload trace results, no more retries") return } - + // remove the result + delete(t.resultsByTxID, txID) l.Debug().Msg("evm traces uploaded successfully") }() @@ -145,154 +144,167 @@ func NewSafeTxTracer(ct *CallTracer) *tracers.Tracer { Str("block-id", ct.blockID.String()). Logger() - if ct.tracer.OnTxStart != nil { - wrapped.OnTxStart = func( - vm *tracing.VMContext, - tx *types.Transaction, - from gethCommon.Address, - ) { - defer func() { - if r := recover(); r != nil { - err, ok := r.(error) - if !ok { - err = fmt.Errorf("panic: %v", r) - } - l.Err(err). - Stack(). - Msg("OnTxStart trace collection failed") + wrapped.OnTxStart = func( + vm *tracing.VMContext, + tx *types.Transaction, + from gethCommon.Address, + ) { + defer func() { + if r := recover(); r != nil { + err, ok := r.(error) + if !ok { + err = fmt.Errorf("panic: %v", r) } - }() + l.Err(err). + Stack(). + Msg("OnTxStart trace collection failed") + } + }() + l.Debug().Msg("tracing OnTxStart is called") + if ct.tracer.OnTxStart != nil { ct.tracer.OnTxStart(vm, tx, from) - l.Debug().Msg("tracing OnTxStart is called") + } + // reset tracing to have fresh state + if err := ct.ResetTracer(); err != nil { + l.Error().Err(err). + Msg("failed to reset tracer") + return } } - if ct.tracer.OnTxEnd != nil { - wrapped.OnTxEnd = func(receipt *types.Receipt, err error) { - defer func() { - if r := recover(); r != nil { - err, ok := r.(error) - if !ok { - err = fmt.Errorf("panic: %v", r) - } - l.Err(err). - Stack(). - Msg("OnTxEnd trace collection failed") + wrapped.OnTxEnd = func(receipt *types.Receipt, err error) { + defer func() { + if r := recover(); r != nil { + err, ok := r.(error) + if !ok { + err = fmt.Errorf("panic: %v", r) } - }() + l.Err(err). + Stack(). + Msg("OnTxEnd trace collection failed") + } + }() + l.Debug().Msg("tracing OnTxEnd is called") + if ct.tracer.OnTxEnd != nil { ct.tracer.OnTxEnd(receipt, err) - l.Debug().Msg("tracing OnTxEnd is called") } + + // collect results for the tracer + res, err := ct.tracer.GetResult() + if err != nil { + l.Error().Err(err).Msg("failed to produce trace results") + return + } + ct.resultsByTxID[receipt.TxHash] = res } - if ct.tracer.OnEnter != nil { - wrapped.OnEnter = func( - depth int, - typ byte, - from, to gethCommon.Address, - input []byte, - gas uint64, - value *big.Int, - ) { - defer func() { - if r := recover(); r != nil { - err, ok := r.(error) - if !ok { - err = fmt.Errorf("panic: %v", r) - } - l.Err(err). - Stack(). - Msg("OnEnter trace collection failed") + wrapped.OnEnter = func( + depth int, + typ byte, + from, to gethCommon.Address, + input []byte, + gas uint64, + value *big.Int, + ) { + defer func() { + if r := recover(); r != nil { + err, ok := r.(error) + if !ok { + err = fmt.Errorf("panic: %v", r) } - }() + l.Err(err). + Stack(). + Msg("OnEnter trace collection failed") + } + }() + l.Debug().Int("depth", depth).Msg("tracing OnEnter is called") + if ct.tracer.OnEnter != nil { ct.tracer.OnEnter(depth, typ, from, to, input, gas, value) - l.Debug().Int("depth", depth).Msg("tracing OnEnter is called") } } - if ct.tracer.OnExit != nil { - wrapped.OnExit = func(depth int, output []byte, gasUsed uint64, err error, reverted bool) { - defer func() { - if r := recover(); r != nil { - err, ok := r.(error) - if !ok { - err = fmt.Errorf("panic: %v", r) - } - l.Err(err). - Stack(). - Msg("OnExit trace collection failed") + wrapped.OnExit = func(depth int, output []byte, gasUsed uint64, err error, reverted bool) { + defer func() { + if r := recover(); r != nil { + err, ok := r.(error) + if !ok { + err = fmt.Errorf("panic: %v", r) } - }() + l.Err(err). + Stack(). + Msg("OnExit trace collection failed") + } + }() + l.Debug().Int("depth", depth).Msg("tracing OnExit is called") + if ct.tracer.OnExit != nil { ct.tracer.OnExit(depth, output, gasUsed, err, reverted) - l.Debug().Int("depth", depth).Msg("tracing OnExit is called") } } - if ct.tracer.OnOpcode != nil { - wrapped.OnOpcode = func( - pc uint64, - op byte, - gas, cost uint64, - scope tracing.OpContext, - rData []byte, - depth int, - err error, - ) { - defer func() { - if r := recover(); r != nil { - err, ok := r.(error) - if !ok { - err = fmt.Errorf("panic: %v", r) - } - l.Err(err). - Stack(). - Msg("OnOpcode trace collection failed") + wrapped.OnOpcode = func( + pc uint64, + op byte, + gas, cost uint64, + scope tracing.OpContext, + rData []byte, + depth int, + err error, + ) { + defer func() { + if r := recover(); r != nil { + err, ok := r.(error) + if !ok { + err = fmt.Errorf("panic: %v", r) } - }() + l.Err(err). + Stack(). + Msg("OnOpcode trace collection failed") + } + }() + l.Debug().Msg("tracing OnOpcode is called") + if ct.tracer.OnOpcode != nil { ct.tracer.OnOpcode(pc, op, gas, cost, scope, rData, depth, err) - l.Debug().Msg("tracing OnOpcode is called") } } - - if ct.tracer.OnFault != nil { - wrapped.OnFault = func( - pc uint64, - op byte, - gas, cost uint64, - scope tracing.OpContext, - depth int, - err error) { - defer func() { - if r := recover(); r != nil { - err, ok := r.(error) - if !ok { - err = fmt.Errorf("panic: %v", r) - } - l.Err(err). - Stack(). - Msg("OnFault trace collection failed") + wrapped.OnFault = func( + pc uint64, + op byte, + gas, cost uint64, + scope tracing.OpContext, + depth int, + err error) { + defer func() { + if r := recover(); r != nil { + err, ok := r.(error) + if !ok { + err = fmt.Errorf("panic: %v", r) } - }() + l.Err(err). + Stack(). + Msg("OnFault trace collection failed") + } + }() + l.Debug().Msg("tracing OnFault is called") + if ct.tracer.OnFault != nil { ct.tracer.OnFault(pc, op, gas, cost, scope, depth, err) - l.Debug().Msg("tracing OnFault is called") } } - if ct.tracer.OnGasChange != nil { - wrapped.OnGasChange = func(old, new uint64, reason tracing.GasChangeReason) { - defer func() { - if r := recover(); r != nil { - err, ok := r.(error) - if !ok { - err = fmt.Errorf("panic: %v", r) - } - l.Err(err). - Stack(). - Msg("OnGasChange trace collection failed") + wrapped.OnGasChange = func(old, new uint64, reason tracing.GasChangeReason) { + defer func() { + if r := recover(); r != nil { + err, ok := r.(error) + if !ok { + err = fmt.Errorf("panic: %v", r) } - }() + l.Err(err). + Stack(). + Msg("OnGasChange trace collection failed") + } + }() + l.Debug().Msg("tracing OnGasChange is called") + if ct.tracer.OnGasChange != nil { ct.tracer.OnGasChange(old, new, reason) - l.Debug().Msg("tracing OnGasChange is called") } } diff --git a/fvm/evm/debug/tracer_test.go b/fvm/evm/debug/tracer_test.go index 480d5d17ba6..1f3213ba1f4 100644 --- a/fvm/evm/debug/tracer_test.go +++ b/fvm/evm/debug/tracer_test.go @@ -17,7 +17,7 @@ import ( func Test_CallTracer(t *testing.T) { t.Run("collect traces and upload them", func(t *testing.T) { - txID := gethCommon.Hash{0x05} + var txID gethCommon.Hash blockID := flow.Identifier{0x01} var res json.RawMessage @@ -39,22 +39,61 @@ func Test_CallTracer(t *testing.T) { data := []byte{0x02, 0x04} amount := big.NewInt(1) + // first transaction tr := tracer.TxTracer() require.NotNil(t, tr) - tr.OnEnter(0, 0, from, to, []byte{0x01, 0x02}, 10, big.NewInt(1)) tx := gethTypes.NewTransaction(nonce, to, amount, 100, big.NewInt(10), data) + txID = tx.Hash() tr.OnTxStart(nil, tx, from) + tr.OnEnter(0, 0, from, to, []byte{0x01, 0x02}, 10, big.NewInt(1)) tr.OnEnter(1, byte(vm.ADD), from, to, data, 20, big.NewInt(2)) tr.OnExit(1, nil, 10, nil, false) - tr.OnTxEnd(&gethTypes.Receipt{}, nil) tr.OnExit(0, []byte{0x02}, 200, nil, false) + tr.OnTxEnd(&gethTypes.Receipt{TxHash: tx.Hash()}, nil) + tracer.Collect(tx.Hash()) + }) - res, err = tr.GetResult() + t.Run("collect traces and upload them (after a failed transaction)", func(t *testing.T) { + blockID := flow.Identifier{0x01} + var txID gethCommon.Hash + var res json.RawMessage + + mockUpload := &testutils.MockUploader{ + UploadFunc: func(id string, message json.RawMessage) error { + require.Equal(t, TraceID(txID, blockID), id) + require.Equal(t, res, message) + return nil + }, + } + + tracer, err := NewEVMCallTracer(mockUpload, zerolog.Nop()) require.NoError(t, err) - require.NotNil(t, res) + tracer.WithBlockID(blockID) - tracer.Collect(txID) + from := gethCommon.HexToAddress("0x01") + to := gethCommon.HexToAddress("0x02") + nonce := uint64(10) + data := []byte{0x02, 0x04} + amount := big.NewInt(1) + + tr := tracer.TxTracer() + require.NotNil(t, tr) + + // failed transaction (no exit and collect call) + tx := gethTypes.NewTransaction(nonce, to, amount, 300, big.NewInt(30), data) + tr.OnTxStart(nil, tx, from) + tr.OnEnter(0, 0, from, to, []byte{0x01, 0x02}, 10, big.NewInt(1)) + tr.OnEnter(1, byte(vm.ADD), from, to, data, 20, big.NewInt(2)) + + // success + tx = gethTypes.NewTransaction(nonce, to, amount, 400, big.NewInt(40), data) + txID = tx.Hash() + tr.OnTxStart(nil, tx, from) + tr.OnEnter(0, 0, from, to, []byte{0x01, 0x02}, 10, big.NewInt(1)) + tr.OnExit(0, []byte{0x02}, 200, nil, false) + tr.OnTxEnd(&gethTypes.Receipt{TxHash: tx.Hash()}, nil) + tracer.Collect(tx.Hash()) }) t.Run("collector panic recovery", func(t *testing.T) { diff --git a/fvm/evm/emulator/emulator.go b/fvm/evm/emulator/emulator.go index 8ecc8ae6cef..132bf32600a 100644 --- a/fvm/evm/emulator/emulator.go +++ b/fvm/evm/emulator/emulator.go @@ -122,13 +122,11 @@ func (bl *BlockView) DirectCall(call *types.DirectCall) (res *types.Result, err if proc.evm.Config.Tracer != nil && proc.evm.Config.Tracer.OnTxStart != nil { proc.evm.Config.Tracer.OnTxStart(proc.evm.GetVMContext(), call.Transaction(), call.From.ToCommon()) defer func() { - if proc.evm.Config.Tracer.OnTxEnd != nil { - if err == nil && res != nil { - proc.evm.Config.Tracer.OnTxEnd(res.Receipt(), res.ValidationError) - } + if proc.evm.Config.Tracer.OnTxEnd != nil && + err == nil && res != nil { + proc.evm.Config.Tracer.OnTxEnd(res.Receipt(), res.ValidationError) } }() - } // re-route based on the sub type @@ -171,13 +169,6 @@ func (bl *BlockView) RunTransaction( // call tracer if proc.evm.Config.Tracer != nil && proc.evm.Config.Tracer.OnTxStart != nil { proc.evm.Config.Tracer.OnTxStart(proc.evm.GetVMContext(), tx, msg.From) - defer func() { - if proc.evm.Config.Tracer.OnTxEnd != nil { - if err == nil && result != nil { - proc.evm.Config.Tracer.OnTxEnd(result.Receipt(), result.ValidationError) - } - } - }() } // run msg @@ -191,6 +182,13 @@ func (bl *BlockView) RunTransaction( return nil, err } + // call tracer on tx end + if proc.evm.Config.Tracer != nil && + proc.evm.Config.Tracer.OnTxEnd != nil && + res != nil { + proc.evm.Config.Tracer.OnTxEnd(res.Receipt(), res.ValidationError) + } + return res, nil } @@ -214,19 +212,9 @@ func (bl *BlockView) BatchRunTransactions(txs []*gethTypes.Transaction) ([]*type continue } - // call tracer + // call tracer on tx start if proc.evm.Config.Tracer != nil && proc.evm.Config.Tracer.OnTxStart != nil { proc.evm.Config.Tracer.OnTxStart(proc.evm.GetVMContext(), tx, msg.From) - defer func() { - if proc.evm.Config.Tracer.OnTxEnd != nil { - j := i - res := batchResults[j] - if err == nil && res != nil { - proc.evm.Config.Tracer.OnTxEnd(res.Receipt(), res.ValidationError) - } - } - }() - } // run msg @@ -245,6 +233,13 @@ func (bl *BlockView) BatchRunTransactions(txs []*gethTypes.Transaction) ([]*type // collect result batchResults[i] = res + + // call tracer on tx end + if proc.evm.Config.Tracer != nil && + proc.evm.Config.Tracer.OnTxEnd != nil && + res != nil { + proc.evm.Config.Tracer.OnTxEnd(res.Receipt(), res.ValidationError) + } } // finalize after all the batch transactions are executed to save resources diff --git a/fvm/evm/emulator/emulator_test.go b/fvm/evm/emulator/emulator_test.go index e0669888d1f..4e268a28902 100644 --- a/fvm/evm/emulator/emulator_test.go +++ b/fvm/evm/emulator/emulator_test.go @@ -1207,6 +1207,8 @@ func TestTransactionTracing(t *testing.T) { return nil } + tracer.WithBlockID(blockID) + // interact and record trace res, err := blk.DirectCall( types.NewContractCall( @@ -1219,12 +1221,12 @@ func TestTransactionTracing(t *testing.T) { ), ) require.NoError(t, err) + require.NoError(t, res.ValidationError) + require.NoError(t, res.VMError) txID = res.TxHash - trace, err = tracer.TxTracer().GetResult() - require.NoError(t, err) - tracer.WithBlockID(blockID) - tracer.Collect(txID) + trace = tracer.GetResultByTxHash(txID) + require.NotEmpty(t, trace) testAccount.SetNonce(testAccount.Nonce() + 1) require.Eventuallyf(t, func() bool { @@ -1265,11 +1267,10 @@ func TestTransactionTracing(t *testing.T) { ) requireSuccessfulExecution(t, err, res) txID = res.TxHash - trace, err = tracer.TxTracer().GetResult() - require.NoError(t, err) tracer.WithBlockID(blockID) - tracer.Collect(txID) + trace = tracer.GetResultByTxHash(txID) + require.NotEmpty(t, trace) testAccount.SetNonce(testAccount.Nonce() + 1) require.Eventuallyf(t, func() bool { @@ -1310,11 +1311,11 @@ func TestTransactionTracing(t *testing.T) { res, err := blk.RunTransaction(tx) requireSuccessfulExecution(t, err, res) txID = res.TxHash - trace, err = tracer.TxTracer().GetResult() - require.NoError(t, err) tracer.WithBlockID(blockID) - tracer.Collect(txID) + trace = tracer.GetResultByTxHash(txID) + require.NotEmpty(t, trace) + testAccount.SetNonce(testAccount.Nonce() + 1) require.Eventuallyf(t, func() bool { <-uploaded @@ -1388,12 +1389,11 @@ func TestTransactionTracing(t *testing.T) { res, err := blk.RunTransaction(tx) requireSuccessfulExecution(t, err, res) txID = res.TxHash - trace, err = tracer.TxTracer().GetResult() - require.NoError(t, err) - require.NotEmpty(t, trace) tracer.WithBlockID(blockID) - tracer.Collect(txID) + trace = tracer.GetResultByTxHash(txID) + require.NotEmpty(t, trace) + testAccount.SetNonce(testAccount.Nonce() + 1) require.Eventuallyf(t, func() bool { <-uploaded @@ -1482,11 +1482,9 @@ func TestTransactionTracing(t *testing.T) { require.NoError(t, err) require.Len(t, results, 1) txID = results[0].TxHash - trace, err = tracer.TxTracer().GetResult() - require.NoError(t, err) tracer.WithBlockID(blockID) - tracer.Collect(txID) + trace = tracer.GetResultByTxHash(txID) require.Eventuallyf(t, func() bool { <-uploaded diff --git a/fvm/evm/handler/handler_test.go b/fvm/evm/handler/handler_test.go index 62e006fd49e..5d2ba656e0e 100644 --- a/fvm/evm/handler/handler_test.go +++ b/fvm/evm/handler/handler_test.go @@ -1080,7 +1080,6 @@ func TestHandler_TransactionRun(t *testing.T) { testutils.RunWithTestFlowEVMRootAddress(t, backend, func(rootAddr flow.Address) { testutils.RunWithEOATestAccount(t, backend, rootAddr, func(eoa *testutils.EOATestAccount) { - var traceResult json.RawMessage txID := gethCommon.HexToHash("0x1") blockID := flow.Identifier{0x02} uploaded := make(chan struct{}) @@ -1095,7 +1094,7 @@ func TestHandler_TransactionRun(t *testing.T) { uploader := &testutils.MockUploader{ UploadFunc: func(id string, message json.RawMessage) error { - assert.Equal(t, traceResult, message) + assert.NotEmpty(t, message) assert.Equal(t, debug.TraceID(txID, blockID), id) close(uploaded) return nil @@ -1118,9 +1117,6 @@ func TestHandler_TransactionRun(t *testing.T) { tr.OnEnter(0, byte(gethVM.ADD), from, *tx.To(), tx.Data(), 20, big.NewInt(2)) tr.OnExit(0, []byte{0x02}, 200, nil, false) tr.OnTxEnd(result.Receipt(), nil) - - traceResult, err = tr.GetResult() - require.NoError(t, err) return result, nil }, } @@ -1181,6 +1177,11 @@ func TestHandler_TransactionRun(t *testing.T) { em := &testutils.TestEmulator{ RunTransactionFunc: func(tx *gethTypes.Transaction) (*types.Result, error) { + tr := tracer.TxTracer() + tr.OnTxStart(nil, tx, gethCommon.Address{}) + tr.OnEnter(0, 0, gethCommon.Address{}, *tx.To(), []byte{0x01, 0x02}, 10, big.NewInt(1)) + tr.OnExit(0, []byte{0x02}, 200, nil, false) + tr.OnTxEnd(&gethTypes.Receipt{TxHash: result.TxHash}, nil) return result, nil }, } @@ -1240,19 +1241,20 @@ func TestHandler_TransactionRun(t *testing.T) { em := &testutils.TestEmulator{ BatchRunTransactionFunc: func(txs []*gethTypes.Transaction) ([]*types.Result, error) { runResults = make([]*types.Result, len(txs)) + tr := tracer.TxTracer() for i, tx := range txs { - tr := tracer.TxTracer() - // TODO(Ramtin): figure out me - // tr.CaptureTxStart(200) - // tr.CaptureTxEnd(150) - - traceResults[i], _ = tr.GetResult() + from := gethCommon.Address{byte(i)} + tr.OnTxStart(nil, tx, from) + tr.OnEnter(0, 0, from, *tx.To(), []byte{0x01, 0x02}, 10, big.NewInt(1)) + tr.OnExit(0, []byte{0x02}, 200, nil, false) + tr.OnTxEnd(&gethTypes.Receipt{TxHash: tx.Hash()}, nil) runResults[i] = &types.Result{ TxHash: tx.Hash(), Logs: []*gethTypes.Log{ testutils.GetRandomLogFixture(t), }, } + traceResults[i] = tracer.GetResultByTxHash(tx.Hash()) } return runResults, nil }, diff --git a/fvm/evm/types/result.go b/fvm/evm/types/result.go index 412a7af7e9e..8a4ba270dc6 100644 --- a/fvm/evm/types/result.go +++ b/fvm/evm/types/result.go @@ -139,6 +139,7 @@ func (res *Result) Receipt() *gethTypes.Receipt { } receipt := &gethTypes.Receipt{ + TxHash: res.TxHash, GasUsed: res.GasConsumed, CumulativeGasUsed: res.CumulativeGasUsed, Logs: res.Logs,