x/evm: logger (#272)

* x/evm: logger

* changelog

* go mod verify and tidy

* typo

CHANGELOG.md

@@ -53,6 +53,7 @@ Ref: https://keepachangelog.com/en/1.0.0/
   * (`app/ante`) Moved `AnteHandler` implementation to `app/ante`
   * (keys) Marked `ExportEthKeyCommand` as **UNSAFE**
   * (`x/evm`) Moved `BeginBlock` and `EndBlock` to `x/evm/abci.go`
+* [\#272](https://github.com/ChainSafe/ethermint/pull/272) Add `Logger` for evm module.
 
 ### Features
 

go.mod

@@ -13,9 +13,11 @@ require (
 	github.com/ethereum/go-ethereum v1.9.13
 	github.com/fjl/memsize v0.0.0-20190710130421-bcb5799ab5e5 // indirect
 	github.com/gogo/protobuf v1.3.1
-	github.com/golangci/golangci-lint v1.23.8 // indirect
 	github.com/gorilla/mux v1.7.4
 	github.com/huin/goupnp v1.0.0 // indirect
+	github.com/mattn/go-colorable v0.1.4 // indirect
+	github.com/onsi/ginkgo v1.11.0 // indirect
+	github.com/onsi/gomega v1.8.1 // indirect
 	github.com/pkg/errors v0.9.1
 	github.com/prometheus/tsdb v0.9.1 // indirect
 	github.com/regen-network/cosmos-proto v0.1.1-0.20200213154359-02baa11ea7c2

x/evm/handler.go

@@ -46,7 +46,6 @@ func handleMsgEthereumTx(ctx sdk.Context, k Keeper, msg types.MsgEthereumTx) (*s
 	ethHash := common.BytesToHash(txHash)
 
 	st := types.StateTransition{
-		Sender:       sender,
 		AccountNonce: msg.Data.AccountNonce,
 		Price:        msg.Data.Price,
 		GasLimit:     msg.Data.GasLimit,
@@ -55,7 +54,8 @@ func handleMsgEthereumTx(ctx sdk.Context, k Keeper, msg types.MsgEthereumTx) (*s
 		Payload:      msg.Data.Payload,
 		Csdb:         k.CommitStateDB.WithContext(ctx),
 		ChainID:      intChainID,
-		THash:        &ethHash,
+		TxHash:       &ethHash,
+		Sender:       sender,
 		Simulate:     ctx.IsCheckTx(),
 	}
 
@@ -65,20 +65,23 @@ func handleMsgEthereumTx(ctx sdk.Context, k Keeper, msg types.MsgEthereumTx) (*s
 	k.TxCount++
 
 	// TODO: move to keeper
-	returnData, err := st.TransitionCSDB(ctx)
+	executionResult, err := st.TransitionDb(ctx)
 	if err != nil {
 		return nil, err
 	}
 
 	// update block bloom filter
-	k.Bloom.Or(k.Bloom, returnData.Bloom)
+	k.Bloom.Or(k.Bloom, executionResult.Bloom)
 
 	// update transaction logs in KVStore
-	err = k.SetTransactionLogs(ctx, returnData.Logs, txHash)
+	err = k.SetTransactionLogs(ctx, executionResult.Logs, txHash)
 	if err != nil {
 		return nil, err
 	}
 
+	// log successful execution
+	k.Logger(ctx).Info(executionResult.Result.Log)
+
 	ctx.EventManager().EmitEvents(sdk.Events{
 		sdk.NewEvent(
 			types.EventTypeEthereumTx,
@@ -101,8 +104,8 @@ func handleMsgEthereumTx(ctx sdk.Context, k Keeper, msg types.MsgEthereumTx) (*s
 	}
 
 	// set the events to the result
-	returnData.Result.Events = ctx.EventManager().Events().ToABCIEvents()
-	return returnData.Result, nil
+	executionResult.Result.Events = ctx.EventManager().Events().ToABCIEvents()
+	return executionResult.Result, nil
 }
 
 // handleMsgEthermint handles an sdk.StdTx for an Ethereum state transition
@@ -125,7 +128,7 @@ func handleMsgEthermint(ctx sdk.Context, k Keeper, msg types.MsgEthermint) (*sdk
 		Payload:      msg.Payload,
 		Csdb:         k.CommitStateDB.WithContext(ctx),
 		ChainID:      intChainID,
-		THash:        &ethHash,
+		TxHash:       &ethHash,
 		Simulate:     ctx.IsCheckTx(),
 	}
 
@@ -138,11 +141,23 @@ func handleMsgEthermint(ctx sdk.Context, k Keeper, msg types.MsgEthermint) (*sdk
 	k.CommitStateDB.Prepare(ethHash, common.Hash{}, k.TxCount)
 	k.TxCount++
 
-	returnData, err := st.TransitionCSDB(ctx)
+	executionResult, err := st.TransitionDb(ctx)
 	if err != nil {
 		return nil, err
 	}
 
+	// update block bloom filter
+	k.Bloom.Or(k.Bloom, executionResult.Bloom)
+
+	// update transaction logs in KVStore
+	err = k.SetTransactionLogs(ctx, executionResult.Logs, txHash)
+	if err != nil {
+		return nil, err
+	}
+
+	// log successful execution
+	k.Logger(ctx).Info(executionResult.Result.Log)
+
 	ctx.EventManager().EmitEvents(sdk.Events{
 		sdk.NewEvent(
 			types.EventTypeEthermint,
@@ -165,6 +180,6 @@ func handleMsgEthermint(ctx sdk.Context, k Keeper, msg types.MsgEthermint) (*sdk
 	}
 
 	// set the events to the result
-	returnData.Result.Events = ctx.EventManager().Events().ToABCIEvents()
-	return returnData.Result, nil
+	executionResult.Result.Events = ctx.EventManager().Events().ToABCIEvents()
+	return executionResult.Result, nil
 }

x/evm/keeper/keeper.go

@@ -5,6 +5,8 @@ import (
 	"errors"
 	"fmt"
 
+	"github.com/tendermint/tendermint/libs/log"
+
 	"github.com/cosmos/cosmos-sdk/codec"
 	ethcmn "github.com/ethereum/go-ethereum/common"
 	ethvm "github.com/ethereum/go-ethereum/core/vm"
@@ -44,6 +46,11 @@ func NewKeeper(
 	}
 }
 
+// Logger returns a module-specific logger.
+func (k Keeper) Logger(ctx sdk.Context) log.Logger {
+	return ctx.Logger().With("module", fmt.Sprintf("x/%s", types.ModuleName))
+}
+
 // ----------------------------------------------------------------------------
 // Block hash mapping functions
 // May be removed when using only as module (only required by rpc api)

x/evm/types/state_transition.go

@@ -2,6 +2,7 @@ package types
 
 import (
 	"errors"
+	"fmt"
 	"math/big"
 
 	"github.com/ethereum/go-ethereum/common"
@@ -16,30 +17,58 @@ import (
 
 // StateTransition defines data to transitionDB in evm
 type StateTransition struct {
-	Payload      []byte
-	Recipient    *common.Address
+	// TxData fields
 	AccountNonce uint64
-	GasLimit     uint64
 	Price        *big.Int
+	GasLimit     uint64
+	Recipient    *common.Address
 	Amount       *big.Int
-	ChainID      *big.Int
-	Csdb         *CommitStateDB
-	THash        *common.Hash
-	Sender       common.Address
-	Simulate     bool
+	Payload      []byte
+
+	ChainID  *big.Int
+	Csdb     *CommitStateDB
+	TxHash   *common.Hash
+	Sender   common.Address
+	Simulate bool // i.e CheckTx execution
+}
+
+// GasInfo returns the gas limit, gas consumed and gas refunded from the EVM transition
+// execution
+type GasInfo struct {
+	GasLimit    uint64
+	GasConsumed uint64
+	GasRefunded uint64
 }
 
-// ReturnData represents what's returned from a transition
-type ReturnData struct {
-	Logs   []*ethtypes.Log
-	Bloom  *big.Int
-	Result *sdk.Result
+// ExecutionResult represents what's returned from a transition
+type ExecutionResult struct {
+	Logs    []*ethtypes.Log
+	Bloom   *big.Int
+	Result  *sdk.Result
+	GasInfo GasInfo
+}
+
+func (st StateTransition) newEVM(ctx sdk.Context, csdb *CommitStateDB, gasLimit uint64, gasPrice *big.Int) *vm.EVM {
+	// Create context for evm
+	context := vm.Context{
+		CanTransfer: core.CanTransfer,
+		Transfer:    core.Transfer,
+		Origin:      st.Sender,
+		Coinbase:    common.Address{}, // there's no benefitiary since we're not mining
+		BlockNumber: big.NewInt(ctx.BlockHeight()),
+		Time:        big.NewInt(ctx.BlockHeader().Time.Unix()),
+		Difficulty:  big.NewInt(0), // unused. Only required in PoW context
+		GasLimit:    gasLimit,
+		GasPrice:    gasPrice,
+	}
+
+	return vm.NewEVM(context, csdb, GenerateChainConfig(st.ChainID), vm.Config{})
 }
 
-// TODO: move to keeper
-// TransitionCSDB performs an evm state transition from a transaction
-// TODO: update godoc, it doesn't explain what it does in depth.
-func (st StateTransition) TransitionCSDB(ctx sdk.Context) (*ReturnData, error) {
+// TransitionDb will transition the state by applying the current transaction and
+// returning the evm execution result.
+// NOTE: State transition checks are run during AnteHandler execution.
+func (st StateTransition) TransitionDb(ctx sdk.Context) (*ExecutionResult, error) {
 	contractCreation := st.Recipient == nil
 
 	cost, err := core.IntrinsicGas(st.Payload, contractCreation, true, false)
@@ -78,58 +107,54 @@ func (st StateTransition) TransitionCSDB(ctx sdk.Context) (*ReturnData, error) {
 		return nil, errors.New("gas price cannot be nil")
 	}
 
-	// Create context for evm
-	context := vm.Context{
-		CanTransfer: core.CanTransfer,
-		Transfer:    core.Transfer,
-		Origin:      st.Sender,
-		Coinbase:    common.Address{}, // TODO: explain why this is empty
-		BlockNumber: big.NewInt(ctx.BlockHeight()),
-		Time:        big.NewInt(ctx.BlockHeader().Time.Unix()),
-		Difficulty:  big.NewInt(0), // unused. Only required in PoW context
-		GasLimit:    gasLimit,
-		GasPrice:    gasPrice.BigInt(),
-	}
-
-	evm := vm.NewEVM(context, csdb, GenerateChainConfig(st.ChainID), vm.Config{})
+	evm := st.newEVM(ctx, csdb, gasLimit, gasPrice.BigInt())
 
 	var (
-		ret         []byte
-		leftOverGas uint64
-		addr        common.Address
-		senderRef   = vm.AccountRef(st.Sender)
+		ret          []byte
+		leftOverGas  uint64
+		addr         common.Address
+		recipientLog string
+		senderRef    = vm.AccountRef(st.Sender)
 	)
 
 	// Get nonce of account outside of the EVM
 	currentNonce := st.Csdb.GetNonce(st.Sender)
 	// Set nonce of sender account before evm state transition for usage in generating Create address
 	st.Csdb.SetNonce(st.Sender, st.AccountNonce)
 
+	// create contract or execute call
 	switch contractCreation {
 	case true:
 		ret, addr, leftOverGas, err = evm.Create(senderRef, st.Payload, gasLimit, st.Amount)
+		recipientLog = fmt.Sprintf("contract address %s", addr)
 	default:
 		// Increment the nonce for the next transaction	(just for evm state transition)
 		csdb.SetNonce(st.Sender, csdb.GetNonce(st.Sender)+1)
 		ret, leftOverGas, err = evm.Call(senderRef, *st.Recipient, st.Payload, gasLimit, st.Amount)
+		recipientLog = fmt.Sprintf("recipient address %s", st.Recipient)
 	}
 
+	gasConsumed := gasLimit - leftOverGas
+
 	if err != nil {
+		// Consume gas before returning
+		ctx.GasMeter().ConsumeGas(gasConsumed, "evm execution consumption")
 		return nil, err
 	}
 
-	gasConsumed := gasLimit - leftOverGas
-
 	// Resets nonce to value pre state transition
 	st.Csdb.SetNonce(st.Sender, currentNonce)
 
 	// Generate bloom filter to be saved in tx receipt data
 	bloomInt := big.NewInt(0)
-	var bloomFilter ethtypes.Bloom
-	var logs []*ethtypes.Log
 
-	if st.THash != nil && !st.Simulate {
-		logs, err = csdb.GetLogs(*st.THash)
+	var (
+		bloomFilter ethtypes.Bloom
+		logs        []*ethtypes.Log
+	)
+
+	if st.TxHash != nil && !st.Simulate {
+		logs, err = csdb.GetLogs(*st.TxHash)
 		if err != nil {
 			return nil, err
 		}
@@ -138,55 +163,51 @@ func (st StateTransition) TransitionCSDB(ctx sdk.Context) (*ReturnData, error) {
 		bloomFilter = ethtypes.BytesToBloom(bloomInt.Bytes())
 	}
 
+	if !st.Simulate {
+		// Finalise state if not a simulated transaction
+		// TODO: change to depend on config
+		if err := st.Csdb.Finalise(true); err != nil {
+			return nil, err
+		}
+	}
+
 	// Encode all necessary data into slice of bytes to return in sdk result
-	res := &ResultData{
+	resultData := &ResultData{
 		Address: addr,
 		Bloom:   bloomFilter,
 		Logs:    logs,
 		Ret:     ret,
-		TxHash:  *st.THash,
+		TxHash:  *st.TxHash,
 	}
 
-	resultData, err := EncodeResultData(res)
+	resBz, err := EncodeResultData(resultData)
 	if err != nil {
 		return nil, err
 	}
 
-	// handle errors
-	if err != nil {
-		if err == vm.ErrOutOfGas || err == vm.ErrCodeStoreOutOfGas {
-			return nil, sdkerrors.Wrap(err, "evm execution went out of gas")
-		}
+	resultLog := fmt.Sprintf(
+		"executed EVM state transition; sender address %s; %s", st.Sender, recipientLog,
+	)
 
-		// Consume gas before returning
-		ctx.GasMeter().ConsumeGas(gasConsumed, "EVM execution consumption")
-		return nil, err
+	executionResult := &ExecutionResult{
+		Logs:  logs,
+		Bloom: bloomInt,
+		Result: &sdk.Result{
+			Data: resBz,
+			Log:  resultLog,
+		},
+		GasInfo: GasInfo{
+			GasConsumed: gasConsumed,
+			GasLimit:    gasLimit,
+			GasRefunded: leftOverGas,
+		},
 	}
 
 	// TODO: Refund unused gas here, if intended in future
 
-	if !st.Simulate {
-		// Finalise state if not a simulated transaction
-		// TODO: change to depend on config
-		if err := st.Csdb.Finalise(true); err != nil {
-			return nil, err
-		}
-	}
-
 	// Consume gas from evm execution
 	// Out of gas check does not need to be done here since it is done within the EVM execution
 	ctx.WithGasMeter(currentGasMeter).GasMeter().ConsumeGas(gasConsumed, "EVM execution consumption")
 
-	err = st.Csdb.SetLogs(*st.THash, logs)
-	if err != nil {
-		return nil, err
-	}
-
-	returnData := &ReturnData{
-		Logs:   logs,
-		Bloom:  bloomInt,
-		Result: &sdk.Result{Data: resultData},
-	}
-
-	return returnData, nil
+	return executionResult, nil
 }

x/evm/types/statedb_test.go

@@ -49,7 +49,8 @@ func (suite *StateDBTestSuite) TestBloomFilter() {
 	// Get log from db
 	logs, err := stateDB.GetLogs(tHash)
 	suite.Require().NoError(err)
-	suite.Require().Equal(len(logs), 1)
+	suite.Require().Len(logs, 1)
+	suite.Require().Equal(log, logs[0])
 
 	// get logs bloom from the log
 	bloomInt := ethtypes.LogsBloom(logs)