diff --git a/account/account.go b/account/account.go index f17ceeaedb32312f0c8a89b3499dce15ed275094..9ed538c5d6ce7f339121c540849443d20cba10a2 100644 --- a/account/account.go +++ b/account/account.go @@ -66,6 +66,8 @@ type Account interface { // Obtain a deterministic serialisation of this account // (i.e. update order and Go runtime independent) Encode() ([]byte, error) + // String representation of the account + String() string } type MutableAccount interface { @@ -266,6 +268,10 @@ func (caw concreteAccountWrapper) Encode() ([]byte, error) { return caw.ConcreteAccount.Encode() } +func (caw concreteAccountWrapper) String() string { + return caw.ConcreteAccount.String() +} + func (caw concreteAccountWrapper) MarshalJSON() ([]byte, error) { return json.Marshal(caw.ConcreteAccount) } diff --git a/account/private_account.go b/account/private_account.go index 59f8245f109f7aed6a2847ee9808af27e50d85a4..9b705a02d518ede77b9047bc4288473259fff961 100644 --- a/account/private_account.go +++ b/account/private_account.go @@ -68,6 +68,10 @@ func (cpaw concretePrivateAccountWrapper) PrivateKey() PrivateKey { return cpaw.ConcretePrivateAccount.PrivateKey } +func (cpaw concretePrivateAccountWrapper) String() string { + return cpaw.ConcretePrivateAccount.String() +} + // ConcretePrivateAccount func (pa ConcretePrivateAccount) PrivateAccount() PrivateAccount { diff --git a/blockchain/blockchain.go b/blockchain/blockchain.go index 6cda8da59ce02519dabb8159ad03a9b1310eac86..dae49f81adc865be17b0c5f4d9d6fc1a9dee0975 100644 --- a/blockchain/blockchain.go +++ b/blockchain/blockchain.go @@ -24,7 +24,6 @@ import ( acm "github.com/hyperledger/burrow/account" "github.com/hyperledger/burrow/genesis" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" dbm "github.com/tendermint/tmlibs/db" ) @@ -99,10 +98,10 @@ type PersistedState struct { } func LoadOrNewBlockchain(db dbm.DB, genesisDoc *genesis.GenesisDoc, - logger logging_types.InfoTraceLogger) (*blockchain, error) { + logger *logging.Logger) (*blockchain, error) { - logger = logging.WithScope(logger, "LoadOrNewBlockchain") - logging.InfoMsg(logger, "Trying to load blockchain state from database", + logger = logger.WithScope("LoadOrNewBlockchain") + logger.InfoMsg("Trying to load blockchain state from database", "database_key", stateKey) blockchain, err := LoadBlockchain(db) if err != nil { @@ -118,7 +117,7 @@ func LoadOrNewBlockchain(db dbm.DB, genesisDoc *genesis.GenesisDoc, return blockchain, nil } - logging.InfoMsg(logger, "No existing blockchain state found in database, making new blockchain") + logger.InfoMsg("No existing blockchain state found in database, making new blockchain") return NewBlockchain(db, genesisDoc), nil } diff --git a/client/methods/helpers.go b/client/methods/helpers.go index 6cdb8b3aedaca504d7ec803c250f9e1265686e0a..6fbf1f46ebc2b2d3c863193f6c5312d4e270d777 100644 --- a/client/methods/helpers.go +++ b/client/methods/helpers.go @@ -20,10 +20,9 @@ import ( "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/config" "github.com/hyperledger/burrow/logging/lifecycle" - logging_types "github.com/hyperledger/burrow/logging/types" ) -func unpackSignAndBroadcast(result *rpc.TxResult, logger logging_types.InfoTraceLogger) { +func unpackSignAndBroadcast(result *rpc.TxResult, logger *logging.Logger) { if result == nil { // if we don't provide --sign or --broadcast return @@ -42,15 +41,15 @@ func unpackSignAndBroadcast(result *rpc.TxResult, logger logging_types.InfoTrace ) } - logging.InfoMsg(logger, "SignAndBroadcast result") + logger.InfoMsg("SignAndBroadcast result") } -func loggerFromClientDo(do *client.Do, scope string) (logging_types.InfoTraceLogger, error) { +func loggerFromClientDo(do *client.Do, scope string) (*logging.Logger, error) { logger, err := lifecycle.NewLoggerFromLoggingConfig(config.DefaultClientLoggingConfig()) if err != nil { return nil, err } - logger = logging.WithScope(logger, scope) + logger = logger.WithScope(scope) lifecycle.CaptureStdlibLogOutput(logger) return logger, nil } diff --git a/client/methods/status.go b/client/methods/status.go index 14a8be609eb100ca2cdecc3652f6af840e45cd6d..7487fdf19bafecda67104aad6a7d4b871ec8f080 100644 --- a/client/methods/status.go +++ b/client/methods/status.go @@ -36,7 +36,7 @@ func Status(do *client.Do) error { return fmt.Errorf("Error requesting chainId from chain at (%s): %s", do.NodeAddrFlag, err) } - logger.Info("chain", do.NodeAddrFlag, + logger.Info.Log("chain", do.NodeAddrFlag, "genesisHash", fmt.Sprintf("%X", genesisHash), "chainName", chainName, "chainId", chainId, diff --git a/client/mock/client_mock.go b/client/mock/client_mock.go index 5e195aefa2a679870b74b0876eb864257cace799..0fb53896ffb2284a7e9d754d75577afae03627b8 100644 --- a/client/mock/client_mock.go +++ b/client/mock/client_mock.go @@ -17,8 +17,7 @@ package mock import ( acm "github.com/hyperledger/burrow/account" . "github.com/hyperledger/burrow/client" - "github.com/hyperledger/burrow/logging/loggers" - logging_types "github.com/hyperledger/burrow/logging/types" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/rpc" "github.com/hyperledger/burrow/txs" "github.com/tendermint/go-crypto" @@ -100,6 +99,6 @@ func (mock *MockNodeClient) ListValidators() (blockHeight uint64, bondedValidato return } -func (mock *MockNodeClient) Logger() logging_types.InfoTraceLogger { - return loggers.NewNoopInfoTraceLogger() +func (mock *MockNodeClient) Logger() *logging.Logger { + return logging.NewNoopLogger() } diff --git a/client/node_client.go b/client/node_client.go index aecfb847894e58657936c61ea40e8d65d31fd1bd..6e19231a2405c1edced4b45d713a968c61851a9c 100644 --- a/client/node_client.go +++ b/client/node_client.go @@ -19,7 +19,6 @@ import ( acm "github.com/hyperledger/burrow/account" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/rpc" tendermint_client "github.com/hyperledger/burrow/rpc/tm/client" "github.com/hyperledger/burrow/txs" @@ -41,7 +40,7 @@ type NodeClient interface { ListValidators() (blockHeight uint64, bondedValidators, unbondingValidators []acm.Validator, err error) // Logging context for this NodeClient - Logger() logging_types.InfoTraceLogger + Logger() *logging.Logger } type NodeWebsocketClient interface { @@ -59,15 +58,15 @@ var _ NodeClient = (*burrowNodeClient)(nil) // burrow-client is a simple struct exposing the client rpc methods type burrowNodeClient struct { broadcastRPC string - logger logging_types.InfoTraceLogger + logger *logging.Logger } // BurrowKeyClient.New returns a new monax-keys client for provided rpc location // Monax-keys connects over http request-responses -func NewBurrowNodeClient(rpcString string, logger logging_types.InfoTraceLogger) *burrowNodeClient { +func NewBurrowNodeClient(rpcString string, logger *logging.Logger) *burrowNodeClient { return &burrowNodeClient{ broadcastRPC: rpcString, - logger: logging.WithScope(logger, "BurrowNodeClient"), + logger: logger.WithScope("BurrowNodeClient"), } } @@ -101,7 +100,7 @@ func (burrowNodeClient *burrowNodeClient) DeriveWebsocketClient() (nodeWsClient // } // wsAddr = "ws://" + wsAddr wsAddr = nodeAddr - logging.TraceMsg(burrowNodeClient.logger, "Subscribing to websocket address", + burrowNodeClient.logger.TraceMsg("Subscribing to websocket address", "websocket address", wsAddr, "endpoint", "/websocket", ) @@ -111,7 +110,7 @@ func (burrowNodeClient *burrowNodeClient) DeriveWebsocketClient() (nodeWsClient } derivedBurrowNodeWebsocketClient := &burrowNodeWebsocketClient{ tendermintWebsocket: wsClient, - logger: logging.WithScope(burrowNodeClient.logger, "BurrowNodeWebsocketClient"), + logger: burrowNodeClient.logger.WithScope("BurrowNodeWebsocketClient"), } return derivedBurrowNodeWebsocketClient, nil } @@ -260,6 +259,6 @@ func (burrowNodeClient *burrowNodeClient) ListValidators() (blockHeight uint64, return } -func (burrowNodeClient *burrowNodeClient) Logger() logging_types.InfoTraceLogger { +func (burrowNodeClient *burrowNodeClient) Logger() *logging.Logger { return burrowNodeClient.logger } diff --git a/client/rpc/client_util.go b/client/rpc/client_util.go index d437a92dae88ef47846e443ecffc93f273f019cf..914ba28f6387d87305d11c694c9f96c416092253 100644 --- a/client/rpc/client_util.go +++ b/client/rpc/client_util.go @@ -22,7 +22,6 @@ import ( acm "github.com/hyperledger/burrow/account" "github.com/hyperledger/burrow/client" "github.com/hyperledger/burrow/keys" - "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/txs" ) @@ -89,7 +88,7 @@ func checkCommon(nodeClient client.NodeClient, keyClient keys.KeyClient, pubkey, return } else if pubkey != "" { if addr != "" { - logging.InfoMsg(nodeClient.Logger(), "Both a public key and an address have been specified. The public key takes precedent.", + nodeClient.Logger().InfoMsg("Both a public key and an address have been specified. The public key takes precedent.", "public_key", pubkey, "address", addr, ) @@ -141,7 +140,7 @@ func checkCommon(nodeClient client.NodeClient, keyClient keys.KeyClient, pubkey, return pub, amt, sequence, err2 } sequence = account.Sequence() + 1 - logging.TraceMsg(nodeClient.Logger(), "Fetch sequence from node", + nodeClient.Logger().TraceMsg("Fetch sequence from node", "sequence", sequence, "account address", address, ) diff --git a/client/websocket_client.go b/client/websocket_client.go index 41ba931c3f689a2ba2a7af65631ae047d9b56f68..fe08dde89d912394e422cccd9e1f33f068f938a0 100644 --- a/client/websocket_client.go +++ b/client/websocket_client.go @@ -25,7 +25,6 @@ import ( exe_events "github.com/hyperledger/burrow/execution/events" "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/rpc" tm_client "github.com/hyperledger/burrow/rpc/tm/client" "github.com/hyperledger/burrow/txs" @@ -51,7 +50,7 @@ var _ NodeWebsocketClient = (*burrowNodeWebsocketClient)(nil) type burrowNodeWebsocketClient struct { // TODO: assert no memory leak on closing with open websocket tendermintWebsocket *rpcclient.WSClient - logger logging_types.InfoTraceLogger + logger *logging.Logger } // Subscribe to an eventid @@ -107,7 +106,7 @@ func (burrowNodeWebsocketClient *burrowNodeWebsocketClient) WaitForConfirmation( case response := <-burrowNodeWebsocketClient.tendermintWebsocket.ResponsesCh: if response.Error != nil { - logging.InfoMsg(burrowNodeWebsocketClient.logger, + burrowNodeWebsocketClient.logger.InfoMsg( "Error received on websocket channel", structure.ErrorKey, err) continue } @@ -117,12 +116,12 @@ func (burrowNodeWebsocketClient *burrowNodeWebsocketClient) WaitForConfirmation( resultSubscribe := new(rpc.ResultSubscribe) err = json.Unmarshal(response.Result, resultSubscribe) if err != nil { - logging.InfoMsg(burrowNodeWebsocketClient.logger, "Unable to unmarshal ResultSubscribe", + burrowNodeWebsocketClient.logger.InfoMsg("Unable to unmarshal ResultSubscribe", structure.ErrorKey, err) continue } // TODO: collect subscription IDs, push into channel and on completion - logging.InfoMsg(burrowNodeWebsocketClient.logger, "Received confirmation for event", + burrowNodeWebsocketClient.logger.InfoMsg("Received confirmation for event", "event", resultSubscribe.EventID, "subscription_id", resultSubscribe.SubscriptionID) @@ -130,14 +129,14 @@ func (burrowNodeWebsocketClient *burrowNodeWebsocketClient) WaitForConfirmation( resultEvent := new(rpc.ResultEvent) err = json.Unmarshal(response.Result, resultEvent) if err != nil { - logging.InfoMsg(burrowNodeWebsocketClient.logger, "Unable to unmarshal ResultEvent", + burrowNodeWebsocketClient.logger.InfoMsg("Unable to unmarshal ResultEvent", structure.ErrorKey, err) continue } blockData := resultEvent.EventDataNewBlock() if blockData != nil { latestBlockHash = blockData.Block.Hash() - logging.TraceMsg(burrowNodeWebsocketClient.logger, "Registered new block", + burrowNodeWebsocketClient.logger.TraceMsg("Registered new block", "block", blockData.Block, "latest_block_hash", latestBlockHash, ) @@ -147,7 +146,7 @@ func (burrowNodeWebsocketClient *burrowNodeWebsocketClient) WaitForConfirmation( resultEvent := new(rpc.ResultEvent) err = json.Unmarshal(response.Result, resultEvent) if err != nil { - logging.InfoMsg(burrowNodeWebsocketClient.logger, "Unable to unmarshal ResultEvent", + burrowNodeWebsocketClient.logger.InfoMsg("Unable to unmarshal ResultEvent", structure.ErrorKey, err) continue } @@ -165,7 +164,7 @@ func (burrowNodeWebsocketClient *burrowNodeWebsocketClient) WaitForConfirmation( } if !bytes.Equal(eventDataTx.Tx.Hash(chainId), tx.Hash(chainId)) { - logging.TraceMsg(burrowNodeWebsocketClient.logger, "Received different event", + burrowNodeWebsocketClient.logger.TraceMsg("Received different event", // TODO: consider re-implementing TxID again, or other more clear debug "received transaction event", eventDataTx.Tx.Hash(chainId)) continue @@ -191,7 +190,7 @@ func (burrowNodeWebsocketClient *burrowNodeWebsocketClient) WaitForConfirmation( return default: - logging.InfoMsg(burrowNodeWebsocketClient.logger, "Received unsolicited response", + burrowNodeWebsocketClient.logger.InfoMsg("Received unsolicited response", "response_id", response.ID, "expected_response_id", tm_client.EventResponseID(eventID)) } diff --git a/cmd/burrow/main.go b/cmd/burrow/main.go index 146a5d64a4adbc6f0542f5399679050e212fbdab..7069d8bcdf8cc1a64649fdd1bc217d3aac855e3f 100644 --- a/cmd/burrow/main.go +++ b/cmd/burrow/main.go @@ -3,6 +3,9 @@ package main import ( "context" "fmt" + "log" + "net/http" + _ "net/http/pprof" "os" "strings" @@ -11,9 +14,9 @@ import ( "github.com/hyperledger/burrow/genesis" "github.com/hyperledger/burrow/genesis/spec" "github.com/hyperledger/burrow/keys" + "github.com/hyperledger/burrow/logging" logging_config "github.com/hyperledger/burrow/logging/config" "github.com/hyperledger/burrow/logging/config/presets" - "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/project" "github.com/jawher/mow.cli" ) @@ -36,6 +39,9 @@ func main() { fmt.Println(project.History.CurrentVersion().String()) os.Exit(0) } + go func() { + log.Println(http.ListenAndServe("localhost:6060", nil)) + }() // We need to reflect on whether this obscures where values are coming from conf := config.DefaultBurrowConfig() // We treat logging a little differently in that if anything is set for logging we will not @@ -172,7 +178,7 @@ func main() { if err != nil { fatalf("could not read GenesisSpec: %v", err) } - keyClient := keys.NewKeyClient(conf.Keys.URL, loggers.NewNoopInfoTraceLogger()) + keyClient := keys.NewKeyClient(conf.Keys.URL, logging.NewNoopLogger()) conf.GenesisDoc, err = genesisSpec.GenesisDoc(keyClient) if err != nil { fatalf("could not realise GenesisSpec: %v", err) diff --git a/consensus/tendermint/abci/app.go b/consensus/tendermint/abci/app.go index ee549575566b2420d0f53214d94f97d6a3ce63c5..1bc0700c3cafbd9a214cbe42350c812fcdd66391 100644 --- a/consensus/tendermint/abci/app.go +++ b/consensus/tendermint/abci/app.go @@ -10,7 +10,6 @@ import ( "github.com/hyperledger/burrow/execution" "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/project" "github.com/hyperledger/burrow/txs" abci_types "github.com/tendermint/abci/types" @@ -30,19 +29,19 @@ type abciApp struct { // Utility txDecoder txs.Decoder // Logging - logger logging_types.InfoTraceLogger + logger *logging.Logger } func NewApp(blockchain bcm.MutableBlockchain, checker execution.BatchExecutor, committer execution.BatchCommitter, - logger logging_types.InfoTraceLogger) abci_types.Application { + logger *logging.Logger) abci_types.Application { return &abciApp{ blockchain: blockchain, checker: checker, committer: committer, txDecoder: txs.NewGoWireCodec(), - logger: logging.WithScope(logger.With(structure.ComponentKey, "ABCI_App"), "abci.NewApp"), + logger: logger.WithScope("abci.NewApp").With(structure.ComponentKey, "ABCI_App"), } } @@ -73,7 +72,7 @@ func (app *abciApp) CheckTx(txBytes []byte) abci_types.ResponseCheckTx { defer app.mtx.Unlock() tx, err := app.txDecoder.DecodeTx(txBytes) if err != nil { - logging.TraceMsg(app.logger, "CheckTx decoding error", + app.logger.TraceMsg("CheckTx decoding error", "tag", "CheckTx", structure.ErrorKey, err) return abci_types.ResponseCheckTx{ @@ -86,7 +85,7 @@ func (app *abciApp) CheckTx(txBytes []byte) abci_types.ResponseCheckTx { err = app.checker.Execute(tx) if err != nil { - logging.TraceMsg(app.logger, "CheckTx execution error", + app.logger.TraceMsg("CheckTx execution error", structure.ErrorKey, err, "tag", "CheckTx", "tx_hash", receipt.TxHash, @@ -98,7 +97,7 @@ func (app *abciApp) CheckTx(txBytes []byte) abci_types.ResponseCheckTx { } receiptBytes := wire.BinaryBytes(receipt) - logging.TraceMsg(app.logger, "CheckTx success", + app.logger.TraceMsg("CheckTx success", "tag", "CheckTx", "tx_hash", receipt.TxHash, "creates_contract", receipt.CreatesContract) @@ -124,7 +123,7 @@ func (app *abciApp) DeliverTx(txBytes []byte) abci_types.ResponseDeliverTx { defer app.mtx.Unlock() tx, err := app.txDecoder.DecodeTx(txBytes) if err != nil { - logging.TraceMsg(app.logger, "DeliverTx decoding error", + app.logger.TraceMsg("DeliverTx decoding error", "tag", "DeliverTx", structure.ErrorKey, err) return abci_types.ResponseDeliverTx{ @@ -136,7 +135,7 @@ func (app *abciApp) DeliverTx(txBytes []byte) abci_types.ResponseDeliverTx { receipt := txs.GenerateReceipt(app.blockchain.ChainID(), tx) err = app.committer.Execute(tx) if err != nil { - logging.TraceMsg(app.logger, "DeliverTx execution error", + app.logger.TraceMsg("DeliverTx execution error", structure.ErrorKey, err, "tag", "DeliverTx", "tx_hash", receipt.TxHash, @@ -147,7 +146,7 @@ func (app *abciApp) DeliverTx(txBytes []byte) abci_types.ResponseDeliverTx { } } - logging.TraceMsg(app.logger, "DeliverTx success", + app.logger.TraceMsg("DeliverTx success", "tag", "DeliverTx", "tx_hash", receipt.TxHash, "creates_contract", receipt.CreatesContract) @@ -168,7 +167,7 @@ func (app *abciApp) Commit() abci_types.ResponseCommit { app.mtx.Lock() defer app.mtx.Unlock() tip := app.blockchain.Tip() - logging.InfoMsg(app.logger, "Committing block", + app.logger.InfoMsg("Committing block", "tag", "Commit", structure.ScopeKey, "Commit()", "block_height", app.block.Header.Height, @@ -204,7 +203,7 @@ func (app *abciApp) Commit() abci_types.ResponseCommit { // Perform a sanity check our block height if app.blockchain.LastBlockHeight() != uint64(app.block.Header.Height) { - logging.InfoMsg(app.logger, "Burrow block height disagrees with Tendermint block height", + app.logger.InfoMsg("Burrow block height disagrees with Tendermint block height", structure.ScopeKey, "Commit()", "burrow_height", app.blockchain.LastBlockHeight(), "tendermint_height", app.block.Header.Height) diff --git a/consensus/tendermint/logger.go b/consensus/tendermint/logger.go index c42f46a4ca679890b6f67c5fd3f3978949bf0f8e..6022f47307eade096ddbd9e92c492cda12c9ae85 100644 --- a/consensus/tendermint/logger.go +++ b/consensus/tendermint/logger.go @@ -2,30 +2,29 @@ package tendermint import ( "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/tendermint/tmlibs/log" ) type tendermintLogger struct { - logger logging_types.InfoTraceLogger + logger *logging.Logger } -func NewLogger(logger logging_types.InfoTraceLogger) *tendermintLogger { +func NewLogger(logger *logging.Logger) *tendermintLogger { return &tendermintLogger{ logger: logger, } } func (tml *tendermintLogger) Info(msg string, keyvals ...interface{}) { - logging.InfoMsg(tml.logger, msg, keyvals...) + tml.logger.InfoMsg(msg, keyvals...) } func (tml *tendermintLogger) Error(msg string, keyvals ...interface{}) { - logging.InfoMsg(tml.logger, msg, keyvals...) + tml.logger.InfoMsg(msg, keyvals...) } func (tml *tendermintLogger) Debug(msg string, keyvals ...interface{}) { - logging.TraceMsg(tml.logger, msg, keyvals...) + tml.logger.TraceMsg(msg, keyvals...) } func (tml *tendermintLogger) With(keyvals ...interface{}) log.Logger { diff --git a/consensus/tendermint/tendermint.go b/consensus/tendermint/tendermint.go index 7a3af288ad8149f76052c1cabbb4ce467e2763c5..27fa18ee4cdcf59e5589edfd7b86c99cae68d627 100644 --- a/consensus/tendermint/tendermint.go +++ b/consensus/tendermint/tendermint.go @@ -10,8 +10,8 @@ import ( "github.com/hyperledger/burrow/event" "github.com/hyperledger/burrow/execution" "github.com/hyperledger/burrow/genesis" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/txs" abci_types "github.com/tendermint/abci/types" "github.com/tendermint/tendermint/config" @@ -49,7 +49,7 @@ func NewNode( blockchain bcm.MutableBlockchain, checker execution.BatchExecutor, committer execution.BatchCommitter, - logger logging_types.InfoTraceLogger) (*Node, error) { + logger *logging.Logger) (*Node, error) { var err error // disable Tendermint's RPC diff --git a/core/kernel.go b/core/kernel.go index e854d62be5f81975239d476ab646ab3420434f32..4c734add643918dd9d2d635cbba792a981e437c4 100644 --- a/core/kernel.go +++ b/core/kernel.go @@ -23,6 +23,7 @@ import ( "syscall" "time" + kitlog "github.com/go-kit/kit/log" bcm "github.com/hyperledger/burrow/blockchain" "github.com/hyperledger/burrow/consensus/tendermint" "github.com/hyperledger/burrow/consensus/tendermint/query" @@ -31,7 +32,6 @@ import ( "github.com/hyperledger/burrow/genesis" "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/process" "github.com/hyperledger/burrow/rpc" "github.com/hyperledger/burrow/rpc/tm" @@ -43,8 +43,11 @@ import ( dbm "github.com/tendermint/tmlibs/db" ) -const CooldownMilliseconds = 1000 -const ServerShutdownTimeoutMilliseconds = 1000 +const ( + CooldownMilliseconds = 1000 + ServerShutdownTimeoutMilliseconds = 1000 + LoggingCallerDepth = 5 +) // Kernel is the root structure of Burrow type Kernel struct { @@ -52,17 +55,18 @@ type Kernel struct { Emitter event.Emitter Service *rpc.Service Launchers []process.Launcher - Logger logging_types.InfoTraceLogger + Logger *logging.Logger processes map[string]process.Process shutdownNotify chan struct{} shutdownOnce sync.Once } func NewKernel(ctx context.Context, privValidator tm_types.PrivValidator, genesisDoc *genesis.GenesisDoc, - tmConf *tm_config.Config, rpcConfig *rpc.RPCConfig, logger logging_types.InfoTraceLogger) (*Kernel, error) { + tmConf *tm_config.Config, rpcConfig *rpc.RPCConfig, logger *logging.Logger) (*Kernel, error) { - logger = logging.WithScope(logger, "NewKernel") - var err error + logger = logger.WithScope("NewKernel()").With(structure.TimeKey, kitlog.DefaultTimestampUTC) + tmLogger := logger.With(structure.CallerKey, kitlog.Caller(LoggingCallerDepth+1)) + logger = logger.WithInfo(structure.CallerKey, kitlog.Caller(LoggingCallerDepth)) stateDB := dbm.NewDB("burrow_state", dbm.GoLevelDBBackendStr, tmConf.DBDir()) blockchain, err := bcm.LoadOrNewBlockchain(stateDB, genesisDoc, logger) @@ -87,7 +91,7 @@ func NewKernel(ctx context.Context, privValidator tm_types.PrivValidator, genesi emitter := event.NewEmitter(logger) committer := execution.NewBatchCommitter(state, tmGenesisDoc.ChainID, blockchain, emitter, logger) - tmNode, err := tendermint.NewNode(tmConf, privValidator, tmGenesisDoc, blockchain, checker, committer, logger) + tmNode, err := tendermint.NewNode(tmConf, privValidator, tmGenesisDoc, blockchain, checker, committer, tmLogger) if err != nil { return nil, err @@ -139,7 +143,7 @@ func NewKernel(ctx context.Context, privValidator tm_types.PrivValidator, genesi case <-ctx.Done(): return ctx.Err() case <-tmNode.Quit: - logging.InfoMsg(logger, "Tendermint Node has quit, closing DB connections...") + logger.InfoMsg("Tendermint Node has quit, closing DB connections...") // Close tendermint database connections using our wrapper tmNode.Close() return nil @@ -216,7 +220,7 @@ func (kern *Kernel) supervise() { signals := make(chan os.Signal, 1) signal.Notify(signals, syscall.SIGINT, syscall.SIGTERM, syscall.SIGKILL) sig := <-signals - logging.InfoMsg(kern.Logger, fmt.Sprintf("Caught %v signal so shutting down", sig), + kern.Logger.InfoMsg(fmt.Sprintf("Caught %v signal so shutting down", sig), "signal", sig.String()) kern.Shutdown(context.Background()) } @@ -224,9 +228,9 @@ func (kern *Kernel) supervise() { // Stop the kernel allowing for a graceful shutdown of components in order func (kern *Kernel) Shutdown(ctx context.Context) (err error) { kern.shutdownOnce.Do(func() { - logger := logging.WithScope(kern.Logger, "Shutdown") - logging.InfoMsg(logger, "Attempting graceful shutdown...") - logging.InfoMsg(logger, "Shutting down servers") + logger := kern.Logger.WithScope("Shutdown") + logger.InfoMsg("Attempting graceful shutdown...") + logger.InfoMsg("Shutting down servers") ctx, cancel := context.WithTimeout(ctx, ServerShutdownTimeoutMilliseconds*time.Millisecond) defer cancel() // Shutdown servers in reverse order to boot @@ -234,10 +238,10 @@ func (kern *Kernel) Shutdown(ctx context.Context) (err error) { name := kern.Launchers[i].Name srvr, ok := kern.processes[name] if ok { - logging.InfoMsg(logger, "Shutting down server", "server_name", name) + logger.InfoMsg("Shutting down server", "server_name", name) sErr := srvr.Shutdown(ctx) if sErr != nil { - logging.InfoMsg(logger, "Failed to shutdown server", + logger.InfoMsg("Failed to shutdown server", "server_name", name, structure.ErrorKey, sErr) if err == nil { @@ -246,8 +250,9 @@ func (kern *Kernel) Shutdown(ctx context.Context) (err error) { } } } - logging.InfoMsg(logger, "Shutdown complete") - logging.Sync(kern.Logger) + logger.InfoMsg("Shutdown complete") + structure.Sync(kern.Logger.Info) + structure.Sync(kern.Logger.Trace) // We don't want to wait for them, but yielding for a cooldown Let other goroutines flush // potentially interesting final output (e.g. log messages) time.Sleep(time.Millisecond * CooldownMilliseconds) diff --git a/core/kernel_test.go b/core/kernel_test.go index 427461075c7118fd5dde4c3364168fa4abe599f0..31f65710d65aeba1692a779a7951e1b068da35b1 100644 --- a/core/kernel_test.go +++ b/core/kernel_test.go @@ -12,8 +12,7 @@ import ( "github.com/hyperledger/burrow/consensus/tendermint" "github.com/hyperledger/burrow/consensus/tendermint/validator" "github.com/hyperledger/burrow/genesis" - "github.com/hyperledger/burrow/logging/loggers" - logging_types "github.com/hyperledger/burrow/logging/types" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/rpc" "github.com/stretchr/testify/assert" tm_config "github.com/tendermint/tendermint/config" @@ -28,7 +27,7 @@ func TestBootThenShutdown(t *testing.T) { os.Chdir(testDir) tmConf := tm_config.DefaultConfig() //logger, _, _ := lifecycle.NewStdErrLogger() - logger := loggers.NewNoopInfoTraceLogger() + logger := logging.NewNoopLogger() genesisDoc, _, privateValidators := genesis.NewDeterministicGenesis(123).GenesisDoc(1, true, 1000, 1, true, 1000) privValidator := validator.NewPrivValidatorMemory(privateValidators[0], privateValidators[0]) assert.NoError(t, bootWaitBlocksShutdown(privValidator, genesisDoc, tmConf, logger, nil)) @@ -40,7 +39,7 @@ func TestBootShutdownResume(t *testing.T) { os.Chdir(testDir) tmConf := tm_config.DefaultConfig() //logger, _, _ := lifecycle.NewStdErrLogger() - logger := loggers.NewNoopInfoTraceLogger() + logger := logging.NewNoopLogger() genesisDoc, _, privateValidators := genesis.NewDeterministicGenesis(123).GenesisDoc(1, true, 1000, 1, true, 1000) privValidator := validator.NewPrivValidatorMemory(privateValidators[0], privateValidators[0]) @@ -62,7 +61,7 @@ func TestBootShutdownResume(t *testing.T) { } func bootWaitBlocksShutdown(privValidator tm_types.PrivValidator, genesisDoc *genesis.GenesisDoc, - tmConf *tm_config.Config, logger logging_types.InfoTraceLogger, + tmConf *tm_config.Config, logger *logging.Logger, blockChecker func(block *tm_types.EventDataNewBlock) (cont bool)) error { kern, err := NewKernel(context.Background(), privValidator, genesisDoc, tmConf, rpc.DefaultRPCConfig(), logger) diff --git a/event/cache_test.go b/event/cache_test.go index 877d04387a2caef15ab0ba135181babf0a7cf44a..276d323c47ce444a505bfec63ef4d131fb0f2ef0 100644 --- a/event/cache_test.go +++ b/event/cache_test.go @@ -6,7 +6,7 @@ import ( "testing" "time" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging" "github.com/stretchr/testify/assert" ) @@ -17,7 +17,7 @@ func TestEventCache_Flush(t *testing.T) { errCh := make(chan error) flushed := false - em := NewEmitter(loggers.NewNoopInfoTraceLogger()) + em := NewEmitter(logging.NewNoopLogger()) SubscribeCallback(ctx, em, "nothingness", NewQueryBuilder(), func(message interface{}) bool { // Check against sending a buffer of zeroed messages if message == nil { @@ -60,7 +60,7 @@ func TestEventCache_Flush(t *testing.T) { } func TestEventCacheGrowth(t *testing.T) { - evc := NewEventCache(NewEmitter(loggers.NewNoopInfoTraceLogger())) + evc := NewEventCache(NewEmitter(logging.NewNoopLogger())) fireNEvents(evc, 100) c := cap(evc.events) diff --git a/event/convention_test.go b/event/convention_test.go index 31e9571b148affcac0639cf02f8533c283c3d496..35c8f7d675cc2ddb870893b5545955e4d1b3d451 100644 --- a/event/convention_test.go +++ b/event/convention_test.go @@ -5,13 +5,13 @@ import ( "testing" "time" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging" "github.com/stretchr/testify/assert" ) func TestSubscribeCallback(t *testing.T) { ctx := context.Background() - em := NewEmitter(loggers.NewNoopInfoTraceLogger()) + em := NewEmitter(logging.NewNoopLogger()) ch := make(chan interface{}) SubscribeCallback(ctx, em, "TestSubscribeCallback", MatchAllQueryable(), func(msg interface{}) bool { ch <- msg diff --git a/event/emitter.go b/event/emitter.go index d41d0fd1b30a4a798db16f000bd099f17fc17f81..a09d158f9fb830511a00a9fb15d5bbb395d72478 100644 --- a/event/emitter.go +++ b/event/emitter.go @@ -21,8 +21,8 @@ import ( "fmt" "strings" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/process" "github.com/tendermint/tmlibs/common" "github.com/tendermint/tmlibs/pubsub" @@ -52,10 +52,10 @@ type Emitter interface { type emitter struct { common.BaseService pubsubServer *pubsub.Server - logger logging_types.InfoTraceLogger + logger *logging.Logger } -func NewEmitter(logger logging_types.InfoTraceLogger) Emitter { +func NewEmitter(logger *logging.Logger) Emitter { pubsubServer := pubsub.NewServer(pubsub.BufferCapacity(DefaultEventBufferCapacity)) pubsubServer.BaseService = *common.NewBaseService(nil, "Emitter", pubsubServer) pubsubServer.Start() diff --git a/event/emitter_test.go b/event/emitter_test.go index 473bf4c5d5b8870a074257fb130cde1dab6ad218..c881cc53f3fede54cef50d2e913a25d158fe91a7 100644 --- a/event/emitter_test.go +++ b/event/emitter_test.go @@ -5,13 +5,13 @@ import ( "testing" "time" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) func TestEmitter(t *testing.T) { - em := NewEmitter(loggers.NewNoopInfoTraceLogger()) + em := NewEmitter(logging.NewNoopLogger()) ctx := context.Background() out := make(chan interface{}) diff --git a/execution/evm/accounts.go b/execution/evm/accounts.go index 618557aaa9aabca3d6f4982ce81ad793f5838521..4f6ce54cdee800f3c1ab7e395b5a7d2a9fa7a1a7 100644 --- a/execution/evm/accounts.go +++ b/execution/evm/accounts.go @@ -3,17 +3,16 @@ package evm import ( acm "github.com/hyperledger/burrow/account" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" ptypes "github.com/hyperledger/burrow/permission/types" ) // Create a new account from a parent 'creator' account. The creator account will have its // sequence number incremented func DeriveNewAccount(creator acm.MutableAccount, permissions ptypes.AccountPermissions, - logger logging_types.InfoTraceLogger) acm.MutableAccount { + logger *logging.Logger) acm.MutableAccount { // Generate an address sequence := creator.Sequence() - logging.TraceMsg(logger, "Incrementing sequence number in DeriveNewAccount()", + logger.TraceMsg("Incrementing sequence number in DeriveNewAccount()", "tag", "sequence", "account", creator.Address(), "old_sequence", sequence, diff --git a/execution/evm/log_event_test.go b/execution/evm/log_event_test.go index 496e4e61068a9a7874fda6545b21623f3c224295..3920a6511794cf2355d95269ec2ea09d52d740fd 100644 --- a/execution/evm/log_event_test.go +++ b/execution/evm/log_event_test.go @@ -26,7 +26,7 @@ import ( "github.com/hyperledger/burrow/event" . "github.com/hyperledger/burrow/execution/evm/asm" "github.com/hyperledger/burrow/execution/evm/events" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging" "github.com/stretchr/testify/require" ) @@ -54,7 +54,7 @@ func TestLog4(t *testing.T) { ourVm := NewVM(st, DefaultDynamicMemoryProvider, newParams(), acm.ZeroAddress, nil, logger) - emitter := event.NewEmitter(loggers.NewNoopInfoTraceLogger()) + emitter := event.NewEmitter(logging.NewNoopLogger()) ch := make(chan *events.EventDataLog) diff --git a/execution/evm/native.go b/execution/evm/native.go index 198977c4ccd3208c5522bd2d9aeaa8143665b0a0..3bf0761944d0a30a9c0ab1191f1241248e6261bb 100644 --- a/execution/evm/native.go +++ b/execution/evm/native.go @@ -19,7 +19,7 @@ import ( acm "github.com/hyperledger/burrow/account" . "github.com/hyperledger/burrow/binary" - logging_types "github.com/hyperledger/burrow/logging/types" + "github.com/hyperledger/burrow/logging" "golang.org/x/crypto/ripemd160" ) @@ -54,7 +54,7 @@ func registerNativeContracts() { //----------------------------------------------------------------------------- type NativeContract func(state acm.StateWriter, caller acm.Account, input []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) + logger *logging.Logger) (output []byte, err error) /* Removed due to C dependency func ecrecoverFunc(state State, caller *acm.Account, input []byte, gas *int64) (output []byte, err error) { @@ -80,7 +80,7 @@ func ecrecoverFunc(state State, caller *acm.Account, input []byte, gas *int64) ( */ func sha256Func(state acm.StateWriter, caller acm.Account, input []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { // Deduct gas gasRequired := uint64((len(input)+31)/32)*GasSha256Word + GasSha256Base if *gas < gasRequired { @@ -96,7 +96,7 @@ func sha256Func(state acm.StateWriter, caller acm.Account, input []byte, gas *ui } func ripemd160Func(state acm.StateWriter, caller acm.Account, input []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { // Deduct gas gasRequired := uint64((len(input)+31)/32)*GasRipemd160Word + GasRipemd160Base if *gas < gasRequired { @@ -112,7 +112,7 @@ func ripemd160Func(state acm.StateWriter, caller acm.Account, input []byte, gas } func identityFunc(state acm.StateWriter, caller acm.Account, input []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { // Deduct gas gasRequired := uint64((len(input)+31)/32)*GasIdentityWord + GasIdentityBase if *gas < gasRequired { diff --git a/execution/evm/snative.go b/execution/evm/snative.go index 4b8ac87cbed5c22a449d034070b256d05c4bb4bb..a172aedc9299e6c30ae27449df08dd381b6cb79a 100644 --- a/execution/evm/snative.go +++ b/execution/evm/snative.go @@ -25,7 +25,6 @@ import ( "github.com/hyperledger/burrow/execution/evm/sha3" "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/permission" ptypes "github.com/hyperledger/burrow/permission/types" ) @@ -230,7 +229,7 @@ func NewSNativeContract(comment, name string, // has been selected. It is also placed in a registry by registerSNativeContracts // So it can be looked up by SNative address func (contract *SNativeContractDescription) Dispatch(state acm.StateWriter, caller acm.Account, - args []byte, gas *uint64, logger logging_types.InfoTraceLogger) (output []byte, err error) { + args []byte, gas *uint64, logger *logging.Logger) (output []byte, err error) { logger = logger.With(structure.ScopeKey, "Dispatch", "contract_name", contract.Name) @@ -244,7 +243,7 @@ func (contract *SNativeContractDescription) Dispatch(state acm.StateWriter, call return nil, err } - logging.TraceMsg(logger, "Dispatching to function", + logger.TraceMsg("Dispatching to function", "caller", caller.Address(), "function_name", function.Name) @@ -342,7 +341,7 @@ func abiReturn(name string, abiTypeName abi.TypeName) abi.Return { // TODO: catch errors, log em, return 0s to the vm (should some errors cause exceptions though?) func hasBase(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { addrWord256, permNum := returnTwoArgs(args) address := acm.AddressFromWord256(addrWord256) @@ -359,7 +358,7 @@ func hasBase(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64 } hasPermission := HasPermission(state, acc, permN) permInt := byteFromBool(hasPermission) - logger.Trace("function", "hasBase", + logger.Trace.Log("function", "hasBase", "address", address.String(), "account_base_permissions", acc.Permissions().Base, "perm_flag", fmt.Sprintf("%b", permN), @@ -368,7 +367,7 @@ func hasBase(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64 } func setBase(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { addrWord256, permNum, permVal := returnThreeArgs(args) address := acm.AddressFromWord256(addrWord256) @@ -388,14 +387,14 @@ func setBase(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64 return nil, err } state.UpdateAccount(acc) - logger.Trace("function", "setBase", "address", address.String(), + logger.Trace.Log("function", "setBase", "address", address.String(), "permission_flag", fmt.Sprintf("%b", permN), "permission_value", permV) return effectivePermBytes(acc.Permissions().Base, globalPerms(state)), nil } func unsetBase(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { addrWord256, permNum := returnTwoArgs(args) address := acm.AddressFromWord256(addrWord256) @@ -414,7 +413,7 @@ func unsetBase(state acm.StateWriter, caller acm.Account, args []byte, gas *uint return nil, err } state.UpdateAccount(acc) - logger.Trace("function", "unsetBase", "address", address.String(), + logger.Trace.Log("function", "unsetBase", "address", address.String(), "perm_flag", fmt.Sprintf("%b", permN), "permission_flag", fmt.Sprintf("%b", permN)) @@ -422,7 +421,7 @@ func unsetBase(state acm.StateWriter, caller acm.Account, args []byte, gas *uint } func setGlobal(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { permNum, permVal := returnTwoArgs(args) acc, err := acm.GetMutableAccount(state, permission.GlobalPermissionsAddress) @@ -441,14 +440,14 @@ func setGlobal(state acm.StateWriter, caller acm.Account, args []byte, gas *uint return nil, err } state.UpdateAccount(acc) - logger.Trace("function", "setGlobal", + logger.Trace.Log("function", "setGlobal", "permission_flag", fmt.Sprintf("%b", permN), "permission_value", permV) return permBytes(acc.Permissions().Base.ResultantPerms()), nil } func hasRole(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { addrWord256, role := returnTwoArgs(args) address := acm.AddressFromWord256(addrWord256) @@ -462,14 +461,14 @@ func hasRole(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64 roleS := string(role.Bytes()) hasRole := acc.Permissions().HasRole(roleS) permInt := byteFromBool(hasRole) - logger.Trace("function", "hasRole", "address", address.String(), + logger.Trace.Log("function", "hasRole", "address", address.String(), "role", roleS, "has_role", hasRole) return LeftPadWord256([]byte{permInt}).Bytes(), nil } func addRole(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { addrWord256, role := returnTwoArgs(args) address := acm.AddressFromWord256(addrWord256) @@ -484,14 +483,14 @@ func addRole(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64 roleAdded := acc.MutablePermissions().AddRole(roleS) permInt := byteFromBool(roleAdded) state.UpdateAccount(acc) - logger.Trace("function", "addRole", "address", address.String(), + logger.Trace.Log("function", "addRole", "address", address.String(), "role", roleS, "role_added", roleAdded) return LeftPadWord256([]byte{permInt}).Bytes(), nil } func removeRole(state acm.StateWriter, caller acm.Account, args []byte, gas *uint64, - logger logging_types.InfoTraceLogger) (output []byte, err error) { + logger *logging.Logger) (output []byte, err error) { addrWord256, role := returnTwoArgs(args) address := acm.AddressFromWord256(addrWord256) @@ -506,7 +505,7 @@ func removeRole(state acm.StateWriter, caller acm.Account, args []byte, gas *uin roleRemoved := acc.MutablePermissions().RmRole(roleS) permInt := byteFromBool(roleRemoved) state.UpdateAccount(acc) - logger.Trace("function", "removeRole", "address", address.String(), + logger.Trace.Log("function", "removeRole", "address", address.String(), "role", roleS, "role_removed", roleRemoved) return LeftPadWord256([]byte{permInt}).Bytes(), nil diff --git a/execution/evm/vm.go b/execution/evm/vm.go index c7c6b6599b26cd1c0959705c2cb92c7213767927..5cb6ed3d172d2ebbdc124e22e7216ec1c012801c 100644 --- a/execution/evm/vm.go +++ b/execution/evm/vm.go @@ -26,9 +26,9 @@ import ( "github.com/hyperledger/burrow/execution/evm/events" "github.com/hyperledger/burrow/execution/evm/sha3" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/permission" ptypes "github.com/hyperledger/burrow/permission/types" + "math/big" ) var ( @@ -48,6 +48,13 @@ var ( ErrExecutionReverted = errors.New("Execution reverted") ) +const ( + dataStackCapacity = 1024 + callStackCapacity = 100 // TODO ensure usage. +) + +var Debug = false + type ErrPermission struct { typ string } @@ -56,10 +63,36 @@ func (err ErrPermission) Error() string { return fmt.Sprintf("Contract does not have permission to %s", err.typ) } -const ( - dataStackCapacity = 1024 - callStackCapacity = 100 // TODO ensure usage. -) +type ErrNestedCall struct { + NestedError error + Caller acm.Address + Callee acm.Address + StackDepth int +} + +func (err ErrNestedCall) Error() string { + return fmt.Sprintf("error in nested call at depth %v: %s (callee) -> %s (caller): %v", + err.StackDepth, err.Callee, err.Caller, err.NestedError) +} + +type ErrCall struct { + CallError error + NestedErrors []ErrNestedCall +} + +func (err ErrCall) Error() string { + buf := new(bytes.Buffer) + buf.WriteString("call error: ") + buf.WriteString(err.CallError.Error()) + if len(err.NestedErrors) > 0 { + buf.WriteString(", nested call errors:\n") + for _, nestedErr := range err.NestedErrors { + buf.WriteString(nestedErr.Error()) + buf.WriteByte('\n') + } + } + return buf.String() +} type Params struct { BlockHeight uint64 @@ -69,31 +102,35 @@ type Params struct { } type VM struct { - state acm.StateWriter - memoryProvider func() Memory - params Params - origin acm.Address - txHash []byte - callDepth int - publisher event.Publisher - logger logging_types.InfoTraceLogger + state acm.StateWriter + memoryProvider func() Memory + params Params + origin acm.Address + txHash []byte + stackDepth int + nestedCallErrors []ErrNestedCall + publisher event.Publisher + logger *logging.Logger } func NewVM(state acm.StateWriter, memoryProvider func() Memory, params Params, origin acm.Address, txid []byte, - logger logging_types.InfoTraceLogger) *VM { + logger *logging.Logger) *VM { return &VM{ state: state, memoryProvider: memoryProvider, params: params, origin: origin, - callDepth: 0, + stackDepth: 0, txHash: txid, - logger: logging.WithScope(logger, "NewVM"), + logger: logger.WithScope("NewVM"), } } func (vm *VM) Debugf(format string, a ...interface{}) { - logging.TraceMsg(vm.logger, fmt.Sprintf(format, a...), "tag", "vm_debug") + if Debug { + //vm.logger.TraceMsg(fmt.Sprintf(format, a...), "tag", "vm_debug") + fmt.Printf(format, a...) + } } // satisfies go_events.Eventable @@ -143,17 +180,25 @@ func (vm *VM) Call(caller, callee acm.MutableAccount, code, input []byte, value } if len(code) > 0 { - vm.callDepth += 1 + vm.stackDepth += 1 output, err = vm.call(caller, callee, code, input, value, gas) - vm.callDepth -= 1 + vm.stackDepth -= 1 if err != nil { + err = ErrCall{ + CallError: err, + NestedErrors: vm.nestedCallErrors, + } *exception = err.Error() - err := transfer(callee, caller, value) - if err != nil { - // data has been corrupted in ram - panic("Could not return value to caller") + transferErr := transfer(callee, caller, value) + if transferErr != nil { + return nil, fmt.Errorf("error transferring value %v %s (callee) -> %s (caller)", + value, callee, caller) } } + if vm.stackDepth == 0 { + // clean up ready for next call + vm.nestedCallErrors = nil + } } return @@ -174,9 +219,9 @@ func (vm *VM) DelegateCall(caller, callee acm.MutableAccount, code, input []byte // DelegateCall does not transfer the value to the callee. if len(code) > 0 { - vm.callDepth += 1 + vm.stackDepth += 1 output, err = vm.call(caller, callee, code, input, value, gas) - vm.callDepth -= 1 + vm.stackDepth -= 1 if err != nil { *exception = err.Error() } @@ -199,10 +244,24 @@ func useGasNegative(gasLeft *uint64, gasToUse uint64, err *error) bool { // Just like Call() but does not transfer 'value' or modify the callDepth. func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value uint64, gas *uint64) (output []byte, err error) { - vm.Debugf("(%d) (%X) %X (code=%d) gas: %v (d) %X\n", vm.callDepth, caller.Address().Bytes()[:4], callee.Address(), + vm.Debugf("(%d) (%X) %X (code=%d) gas: %v (d) %X\n", vm.stackDepth, caller.Address().Bytes()[:4], callee.Address(), len(callee.Code()), *gas, input) logger := vm.logger.With("tx_hash", vm.txHash) + + // TODO: provide this functionality via some debug flagging + //tokens, _ := acm.Bytecode(code).Tokens() + //if err != nil { + // return nil, err + //} + //if len(vm.txHash) >= 4 { + // + //} + //err = ioutil.WriteFile(fmt.Sprintf("tokens-%X.txt", vm.txHash[:4]), []byte(strings.Join(tokens, "\n")), 0777) + //if err != nil { + // return nil, err + //} + var ( pc int64 = 0 stack = NewStack(dataStackCapacity, gas, &err) @@ -222,19 +281,19 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value case ADD: // 0x01 x, y := stack.PopBigInt(), stack.PopBigInt() - sum := x.Add(x, y) + sum := new(big.Int).Add(x, y) res := stack.PushBigInt(sum) vm.Debugf(" %v + %v = %v (%X)\n", x, y, sum, res) case MUL: // 0x02 x, y := stack.PopBigInt(), stack.PopBigInt() - prod := x.Mul(x, y) + prod := new(big.Int).Mul(x, y) res := stack.PushBigInt(prod) vm.Debugf(" %v * %v = %v (%X)\n", x, y, prod, res) case SUB: // 0x03 x, y := stack.PopBigInt(), stack.PopBigInt() - diff := x.Sub(x, y) + diff := new(big.Int).Sub(x, y) res := stack.PushBigInt(diff) vm.Debugf(" %v - %v = %v (%X)\n", x, y, diff, res) @@ -244,7 +303,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value stack.Push(Zero256) vm.Debugf(" %x / %x = %v\n", x, y, 0) } else { - div := x.Div(x, y) + div := new(big.Int).Div(x, y) res := stack.PushBigInt(div) vm.Debugf(" %v / %v = %v (%X)\n", x, y, div, res) } @@ -255,7 +314,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value stack.Push(Zero256) vm.Debugf(" %x / %x = %v\n", x, y, 0) } else { - div := x.Div(x, y) + div := new(big.Int).Div(x, y) res := stack.PushBigInt(div) vm.Debugf(" %v / %v = %v (%X)\n", x, y, div, res) } @@ -266,7 +325,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value stack.Push(Zero256) vm.Debugf(" %v %% %v = %v\n", x, y, 0) } else { - mod := x.Mod(x, y) + mod := new(big.Int).Mod(x, y) res := stack.PushBigInt(mod) vm.Debugf(" %v %% %v = %v (%X)\n", x, y, mod, res) } @@ -277,7 +336,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value stack.Push(Zero256) vm.Debugf(" %v %% %v = %v\n", x, y, 0) } else { - mod := x.Mod(x, y) + mod := new(big.Int).Mod(x, y) res := stack.PushBigInt(mod) vm.Debugf(" %v %% %v = %v (%X)\n", x, y, mod, res) } @@ -288,7 +347,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value stack.Push(Zero256) vm.Debugf(" %v %% %v = %v\n", x, y, 0) } else { - add := x.Add(x, y) + add := new(big.Int).Add(x, y) mod := add.Mod(add, z) res := stack.PushBigInt(mod) vm.Debugf(" %v + %v %% %v = %v (%X)\n", x, y, z, mod, res) @@ -300,7 +359,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value stack.Push(Zero256) vm.Debugf(" %v %% %v = %v\n", x, y, 0) } else { - mul := x.Mul(x, y) + mul := new(big.Int).Mul(x, y) mod := mul.Mod(mul, z) res := stack.PushBigInt(mod) vm.Debugf(" %v * %v %% %v = %v (%X)\n", x, y, z, mod, res) @@ -308,7 +367,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value case EXP: // 0x0A x, y := stack.PopBigInt(), stack.PopBigInt() - pow := x.Exp(x, y, nil) + pow := new(big.Int).Exp(x, y, nil) res := stack.PushBigInt(pow) vm.Debugf(" %v ** %v = %v (%X)\n", x, y, pow, res) @@ -668,7 +727,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value return nil, firstErr(err, errSto) } stack.Push(data) - vm.Debugf(" {0x%X : 0x%X}\n", loc, data) + vm.Debugf("%s {0x%X = 0x%X}\n", callee.Address(), loc, data) case SSTORE: // 0x55 loc, data := stack.Pop(), stack.Pop() @@ -676,7 +735,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value return nil, err } vm.state.SetStorage(callee.Address(), loc, data) - vm.Debugf(" {0x%X : 0x%X}\n", loc, data) + vm.Debugf("%s {0x%X := 0x%X}\n", callee.Address(), loc, data) case JUMP: // 0x56 to, popErr := stack.Pop64() @@ -861,6 +920,7 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value // Begin execution var ret []byte var callErr error + if nativeContract := registeredNativeContracts[addr]; nativeContract != nil { // Native contract ret, callErr = nativeContract(vm.state, callee, args, &gasLimit, vm.logger) @@ -911,9 +971,14 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value // Push result if callErr != nil { - vm.Debugf("error on call: %s\n", callErr.Error()) - // TODO: we probably don't want to return the error - decide - //err = firstErr(err, callErr) + vm.Debugf("error from nested sub-call (depth: %v): %s\n", vm.stackDepth, callErr.Error()) + // So we can return nested error if the top level return is an error + vm.nestedCallErrors = append(vm.nestedCallErrors, ErrNestedCall{ + NestedError: callErr, + StackDepth: vm.stackDepth, + Caller: caller.Address(), + Callee: callee.Address(), + }) stack.Push(Zero256) if callErr == ErrExecutionReverted { @@ -997,7 +1062,6 @@ func (vm *VM) call(caller, callee acm.MutableAccount, code, input []byte, value vm.Debugf("(pc) %-3v Invalid opcode %X\n", pc, op) return nil, fmt.Errorf("invalid opcode %X", op) } - pc++ } } diff --git a/execution/evm/vm_test.go b/execution/evm/vm_test.go index 0d8ee817b750c607189b45a068f276a1baf348c9..9c47c4fd8849d2b95bf1a51fda4619bbb0158eb1 100644 --- a/execution/evm/vm_test.go +++ b/execution/evm/vm_test.go @@ -29,7 +29,7 @@ import ( . "github.com/hyperledger/burrow/execution/evm/asm" . "github.com/hyperledger/burrow/execution/evm/asm/bc" evm_events "github.com/hyperledger/burrow/execution/evm/events" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/permission" ptypes "github.com/hyperledger/burrow/permission/types" "github.com/stretchr/testify/assert" @@ -39,7 +39,7 @@ import ( // Test output is a bit clearer if we /dev/null the logging, but can be re-enabled by uncommenting the below //var logger, _ = lifecycle.NewStdErrLogger() -var logger = loggers.NewNoopInfoTraceLogger() +var logger = logging.NewNoopLogger() func newAppState() *FakeAppState { fas := &FakeAppState{ @@ -434,7 +434,7 @@ func runVM(eventCh chan<- *evm_events.EventDataCall, ourVm *VM, caller, callee a subscribeAddr acm.Address, contractCode []byte, gas uint64) ([]byte, error) { // we need to catch the event from the CALL to check for exceptions - emitter := event.NewEmitter(loggers.NewNoopInfoTraceLogger()) + emitter := event.NewEmitter(logging.NewNoopLogger()) fmt.Printf("subscribe to %s\n", subscribeAddr) err := evm_events.SubscribeAccountCall(context.Background(), emitter, "test", subscribeAddr, nil, eventCh) diff --git a/execution/execution.go b/execution/execution.go index fbe69f4f4fdddacd6e9d2bc68bcfe03d08b91098..2ea8e69b794d19d0da42a5cc050df54898f637d2 100644 --- a/execution/execution.go +++ b/execution/execution.go @@ -26,7 +26,6 @@ import ( "github.com/hyperledger/burrow/execution/evm" "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/permission" ptypes "github.com/hyperledger/burrow/permission/types" "github.com/hyperledger/burrow/txs" @@ -63,7 +62,7 @@ type executor struct { nameRegCache *NameRegCache publisher event.Publisher eventCache *event.Cache - logger logging_types.InfoTraceLogger + logger *logging.Logger } var _ BatchExecutor = (*executor)(nil) @@ -72,18 +71,18 @@ var _ BatchExecutor = (*executor)(nil) func NewBatchChecker(state *State, chainID string, tip bcm.Tip, - logger logging_types.InfoTraceLogger) BatchExecutor { + logger *logging.Logger) BatchExecutor { return newExecutor(false, state, chainID, tip, event.NewNoOpPublisher(), - logging.WithScope(logger, "NewBatchExecutor")) + logger.WithScope("NewBatchExecutor")) } func NewBatchCommitter(state *State, chainID string, tip bcm.Tip, publisher event.Publisher, - logger logging_types.InfoTraceLogger) BatchCommitter { + logger *logging.Logger) BatchCommitter { return newExecutor(true, state, chainID, tip, publisher, - logging.WithScope(logger, "NewBatchCommitter")) + logger.WithScope("NewBatchCommitter")) } func newExecutor(runCall bool, @@ -91,7 +90,7 @@ func newExecutor(runCall bool, chainID string, tip bcm.Tip, eventFireable event.Publisher, - logger logging_types.InfoTraceLogger) *executor { + logger *logging.Logger) *executor { return &executor{ chainID: chainID, tip: tip, @@ -178,11 +177,10 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { }() txHash := tx.Hash(exe.chainID) - logger := logging.WithScope(exe.logger, "executor.Execute(tx txs.Tx)").With( + logger := exe.logger.WithScope("executor.Execute(tx txs.Tx)").With( "run_call", exe.runCall, - "tx", tx.String(), "tx_hash", txHash) - logging.TraceMsg(logger, "Executing transaction", "tx", tx.String()) + logger.TraceMsg("Executing transaction", "tx", tx.String()) // TODO: do something with fees fees := uint64(0) @@ -258,7 +256,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { return err } if inAcc == nil { - logging.InfoMsg(logger, "Cannot find input account", + logger.InfoMsg("Cannot find input account", "tx_input", tx.Input) return txs.ErrTxInvalidAddress } @@ -276,19 +274,19 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { // pubKey should be present in either "inAcc" or "tx.Input" if err := checkInputPubKey(inAcc, tx.Input); err != nil { - logging.InfoMsg(logger, "Cannot find public key for input account", + logger.InfoMsg("Cannot find public key for input account", "tx_input", tx.Input) return err } signBytes := acm.SignBytes(exe.chainID, tx) err = validateInput(inAcc, signBytes, tx.Input) if err != nil { - logging.InfoMsg(logger, "validateInput failed", + logger.InfoMsg("validateInput failed", "tx_input", tx.Input, structure.ErrorKey, err) return err } if tx.Input.Amount < tx.Fee { - logging.InfoMsg(logger, "Sender did not send enough to cover the fee", + logger.InfoMsg("Sender did not send enough to cover the fee", "tx_input", tx.Input) return txs.ErrTxInsufficientFunds } @@ -312,12 +310,12 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { } } - logger.Trace("output_account", outAcc) + logger.Trace.Log("output_account", outAcc) // Good! value := tx.Input.Amount - tx.Fee - logging.TraceMsg(logger, "Incrementing sequence number for CallTx", + logger.TraceMsg("Incrementing sequence number for CallTx", "tag", "sequence", "account", inAcc.Address(), "old_sequence", inAcc.Sequence(), @@ -358,13 +356,15 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { // you have to wait a block to avoid a re-ordering attack // that will take your fees if outAcc == nil { - logging.InfoMsg(logger, "Call to address that does not exist", + logger.InfoMsg("Call to address that does not exist", "caller_address", inAcc.Address(), - "callee_address", tx.Address) + "callee_address", tx.Address, + "out_acc", outAcc.String()) } else { - logging.InfoMsg(logger, "Call to address that holds no code", + logger.InfoMsg("Call to address that holds no code", "caller_address", inAcc.Address(), - "callee_address", tx.Address) + "callee_address", tx.Address, + "out_acc", outAcc.String()) } err = txs.ErrTxInvalidAddress goto CALL_COMPLETE @@ -380,18 +380,18 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { "run_call", exe.runCall, )) code = tx.Data - logging.TraceMsg(logger, "Creating new contract", + logger.TraceMsg("Creating new contract", "contract_address", callee.Address(), "init_code", code) } else { callee = acm.AsMutableAccount(outAcc) code = callee.Code() - logging.TraceMsg(logger, "Calling existing contract", + logger.TraceMsg("Calling existing contract", "contract_address", callee.Address(), "input", tx.Data, "contract_code", code) } - logger.Trace("callee", callee.Address().String()) + logger.Trace.Log("callee", callee.Address().String()) // Run VM call and sync txCache to exe.blockCache. { // Capture scope for goto. @@ -405,12 +405,12 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { ret, err = vmach.Call(caller, callee, code, tx.Data, value, &gas) if err != nil { // Failure. Charge the gas fee. The 'value' was otherwise not transferred. - logging.InfoMsg(logger, "Error on execution", + logger.InfoMsg("Error on execution", structure.ErrorKey, err) goto CALL_COMPLETE } - logging.TraceMsg(logger, "Successful execution") + logger.TraceMsg("Successful execution") if createContract { callee.SetCode(ret) } @@ -420,7 +420,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { CALL_COMPLETE: // err may or may not be nil. // Create a receipt from the ret and whether it erred. - logging.TraceMsg(logger, "VM call complete", + logger.TraceMsg("VM call complete", "caller", caller, "callee", callee, "return", ret, @@ -450,7 +450,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { } if createContract { // This is done by DeriveNewAccount when runCall == true - logging.TraceMsg(logger, "Incrementing sequence number since creates contract", + logger.TraceMsg("Incrementing sequence number since creates contract", "tag", "sequence", "account", inAcc.Address(), "old_sequence", inAcc.Sequence(), @@ -469,7 +469,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { return err } if inAcc == nil { - logging.InfoMsg(logger, "Cannot find input account", + logger.InfoMsg("Cannot find input account", "tx_input", tx.Input) return txs.ErrTxInvalidAddress } @@ -479,19 +479,19 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { } // pubKey should be present in either "inAcc" or "tx.Input" if err := checkInputPubKey(inAcc, tx.Input); err != nil { - logging.InfoMsg(logger, "Cannot find public key for input account", + logger.InfoMsg("Cannot find public key for input account", "tx_input", tx.Input) return err } signBytes := acm.SignBytes(exe.chainID, tx) err = validateInput(inAcc, signBytes, tx.Input) if err != nil { - logging.InfoMsg(logger, "validateInput failed", + logger.InfoMsg("validateInput failed", "tx_input", tx.Input, structure.ErrorKey, err) return err } if tx.Input.Amount < tx.Fee { - logging.InfoMsg(logger, "Sender did not send enough to cover the fee", + logger.InfoMsg("Sender did not send enough to cover the fee", "tx_input", tx.Input) return txs.ErrTxInsufficientFunds } @@ -508,7 +508,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { expiresIn := value / uint64(costPerBlock) lastBlockHeight := exe.tip.LastBlockHeight() - logging.TraceMsg(logger, "New NameTx", + logger.TraceMsg("New NameTx", "value", value, "cost_per_block", costPerBlock, "expires_in", expiresIn, @@ -538,7 +538,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { if value == 0 && len(tx.Data) == 0 { // maybe we reward you for telling us we can delete this crap // (owners if not expired, anyone if expired) - logging.TraceMsg(logger, "Removing NameReg entry (no value and empty data in tx requests this)", + logger.TraceMsg("Removing NameReg entry (no value and empty data in tx requests this)", "name", entry.Name) err := exe.nameRegCache.RemoveNameRegEntry(entry.Name) if err != nil { @@ -553,7 +553,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { } entry.Expires = lastBlockHeight + expiresIn entry.Owner = tx.Input.Address - logging.TraceMsg(logger, "An old NameReg entry has expired and been reclaimed", + logger.TraceMsg("An old NameReg entry has expired and been reclaimed", "name", entry.Name, "expires_in", expiresIn, "owner", entry.Owner) @@ -567,7 +567,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { return fmt.Errorf("names must be registered for at least %d blocks", txs.MinNameRegistrationPeriod) } entry.Expires = lastBlockHeight + expiresIn - logging.TraceMsg(logger, "Updated NameReg entry", + logger.TraceMsg("Updated NameReg entry", "name", entry.Name, "expires_in", expiresIn, "old_credit", oldCredit, @@ -591,7 +591,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { Data: tx.Data, Expires: lastBlockHeight + expiresIn, } - logging.TraceMsg(logger, "Creating NameReg entry", + logger.TraceMsg("Creating NameReg entry", "name", entry.Name, "expires_in", expiresIn) err := exe.nameRegCache.UpdateNameRegEntry(entry) @@ -603,7 +603,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { // TODO: something with the value sent? // Good! - logging.TraceMsg(logger, "Incrementing sequence number for NameTx", + logger.TraceMsg("Incrementing sequence number for NameTx", "tag", "sequence", "account", inAcc.Address(), "old_sequence", inAcc.Sequence(), @@ -771,7 +771,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { return err } if inAcc == nil { - logging.InfoMsg(logger, "Cannot find input account", + logger.InfoMsg("Cannot find input account", "tx_input", tx.Input) return txs.ErrTxInvalidAddress } @@ -790,14 +790,14 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { // pubKey should be present in either "inAcc" or "tx.Input" if err := checkInputPubKey(inAcc, tx.Input); err != nil { - logging.InfoMsg(logger, "Cannot find public key for input account", + logger.InfoMsg("Cannot find public key for input account", "tx_input", tx.Input) return err } signBytes := acm.SignBytes(exe.chainID, tx) err = validateInput(inAcc, signBytes, tx.Input) if err != nil { - logging.InfoMsg(logger, "validateInput failed", + logger.InfoMsg("validateInput failed", "tx_input", tx.Input, structure.ErrorKey, err) return err @@ -805,7 +805,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { value := tx.Input.Amount - logging.TraceMsg(logger, "New PermissionsTx", + logger.TraceMsg("New PermissionsTx", "perm_args", tx.PermArgs.String()) var permAcc acm.Account @@ -858,7 +858,7 @@ func (exe *executor) Execute(tx txs.Tx) (err error) { } // Good! - logging.TraceMsg(logger, "Incrementing sequence number for PermissionsTx", + logger.TraceMsg("Incrementing sequence number for PermissionsTx", "tag", "sequence", "account", inAcc.Address(), "old_sequence", inAcc.Sequence(), @@ -1061,7 +1061,7 @@ func getInputs(accountGetter acm.Getter, } func getOrMakeOutputs(accountGetter acm.Getter, accs map[acm.Address]acm.MutableAccount, - outs []*txs.TxOutput, logger logging_types.InfoTraceLogger) (map[acm.Address]acm.MutableAccount, error) { + outs []*txs.TxOutput, logger *logging.Logger) (map[acm.Address]acm.MutableAccount, error) { if accs == nil { accs = make(map[acm.Address]acm.MutableAccount) } @@ -1173,7 +1173,7 @@ func validateOutputs(outs []*txs.TxOutput) (uint64, error) { return total, nil } -func adjustByInputs(accs map[acm.Address]acm.MutableAccount, ins []*txs.TxInput, logger logging_types.InfoTraceLogger) error { +func adjustByInputs(accs map[acm.Address]acm.MutableAccount, ins []*txs.TxInput, logger *logging.Logger) error { for _, in := range ins { acc := accs[in.Address] if acc == nil { @@ -1188,7 +1188,7 @@ func adjustByInputs(accs map[acm.Address]acm.MutableAccount, ins []*txs.TxInput, if err != nil { return err } - logging.TraceMsg(logger, "Incrementing sequence number for SendTx (adjustByInputs)", + logger.TraceMsg("Incrementing sequence number for SendTx (adjustByInputs)", "tag", "sequence", "account", acc.Address(), "old_sequence", acc.Sequence(), @@ -1216,9 +1216,9 @@ func adjustByOutputs(accs map[acm.Address]acm.MutableAccount, outs []*txs.TxOutp //--------------------------------------------------------------- // Get permission on an account or fall back to global value -func HasPermission(accountGetter acm.Getter, acc acm.Account, perm ptypes.PermFlag, logger logging_types.InfoTraceLogger) bool { +func HasPermission(accountGetter acm.Getter, acc acm.Account, perm ptypes.PermFlag, logger *logging.Logger) bool { if perm > permission.AllPermFlags { - logging.InfoMsg(logger, + logger.InfoMsg( fmt.Sprintf("HasPermission called on invalid permission 0b%b (invalid) > 0b%b (maximum) ", perm, permission.AllPermFlags), "invalid_permission", perm, @@ -1230,17 +1230,17 @@ func HasPermission(accountGetter acm.Getter, acc acm.Account, perm ptypes.PermFl v, err := acc.Permissions().Base.Compose(permission.GlobalAccountPermissions(accountGetter).Base).Get(perm) if err != nil { - logging.TraceMsg(logger, "Error obtaining permission value (will default to false/deny)", + logger.TraceMsg("Error obtaining permission value (will default to false/deny)", "perm_flag", permString, structure.ErrorKey, err) } if v { - logging.TraceMsg(logger, "Account has permission", + logger.TraceMsg("Account has permission", "account_address", acc.Address, "perm_flag", permString) } else { - logging.TraceMsg(logger, "Account does not have permission", + logger.TraceMsg("Account does not have permission", "account_address", acc.Address, "perm_flag", permString) } @@ -1249,7 +1249,7 @@ func HasPermission(accountGetter acm.Getter, acc acm.Account, perm ptypes.PermFl // TODO: for debug log the failed accounts func hasSendPermission(accountGetter acm.Getter, accs map[acm.Address]acm.MutableAccount, - logger logging_types.InfoTraceLogger) bool { + logger *logging.Logger) bool { for _, acc := range accs { if !HasPermission(accountGetter, acc, permission.Send, logger) { return false @@ -1259,22 +1259,22 @@ func hasSendPermission(accountGetter acm.Getter, accs map[acm.Address]acm.Mutabl } func hasNamePermission(accountGetter acm.Getter, acc acm.Account, - logger logging_types.InfoTraceLogger) bool { + logger *logging.Logger) bool { return HasPermission(accountGetter, acc, permission.Name, logger) } func hasCallPermission(accountGetter acm.Getter, acc acm.Account, - logger logging_types.InfoTraceLogger) bool { + logger *logging.Logger) bool { return HasPermission(accountGetter, acc, permission.Call, logger) } func hasCreateContractPermission(accountGetter acm.Getter, acc acm.Account, - logger logging_types.InfoTraceLogger) bool { + logger *logging.Logger) bool { return HasPermission(accountGetter, acc, permission.CreateContract, logger) } func hasCreateAccountPermission(accountGetter acm.Getter, accs map[acm.Address]acm.MutableAccount, - logger logging_types.InfoTraceLogger) bool { + logger *logging.Logger) bool { for _, acc := range accs { if !HasPermission(accountGetter, acc, permission.CreateAccount, logger) { return false @@ -1284,12 +1284,12 @@ func hasCreateAccountPermission(accountGetter acm.Getter, accs map[acm.Address]a } func hasBondPermission(accountGetter acm.Getter, acc acm.Account, - logger logging_types.InfoTraceLogger) bool { + logger *logging.Logger) bool { return HasPermission(accountGetter, acc, permission.Bond, logger) } func hasBondOrSendPermission(accountGetter acm.Getter, accs map[acm.Address]acm.Account, - logger logging_types.InfoTraceLogger) bool { + logger *logging.Logger) bool { for _, acc := range accs { if !HasPermission(accountGetter, acc, permission.Bond, logger) { if !HasPermission(accountGetter, acc, permission.Send, logger) { diff --git a/execution/execution_test.go b/execution/execution_test.go index 47e913ce9e727a98a0a835a18a6491be7f23c13a..622667a17417f6af89922ff8e5b84c51382717e9 100644 --- a/execution/execution_test.go +++ b/execution/execution_test.go @@ -33,7 +33,7 @@ import ( evm_events "github.com/hyperledger/burrow/execution/evm/events" "github.com/hyperledger/burrow/execution/evm/sha3" "github.com/hyperledger/burrow/genesis" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/permission" ptypes "github.com/hyperledger/burrow/permission/types" "github.com/hyperledger/burrow/txs" @@ -111,7 +111,7 @@ x - roles: has, add, rm // keys var users = makeUsers(10) -var logger = loggers.NewNoopInfoTraceLogger() +var logger = logging.NewNoopLogger() var deterministicGenesis = genesis.NewDeterministicGenesis(34059836243380576) var testGenesisDoc, testPrivAccounts, _ = deterministicGenesis. GenesisDoc(3, true, 1000, 1, true, 1000) diff --git a/execution/state.go b/execution/state.go index 7385267b3be6395b0b17dd6decddb9a4b0d4b01a..73a443bc4622d2beb9e050ae192267265aa2b854 100644 --- a/execution/state.go +++ b/execution/state.go @@ -24,7 +24,7 @@ import ( acm "github.com/hyperledger/burrow/account" "github.com/hyperledger/burrow/binary" "github.com/hyperledger/burrow/genesis" - logging_types "github.com/hyperledger/burrow/logging/types" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/permission" ptypes "github.com/hyperledger/burrow/permission" "github.com/hyperledger/burrow/txs" @@ -62,7 +62,7 @@ type State struct { version uint64 // TODO: tree *iavl.VersionedTree - logger logging_types.InfoTraceLogger + logger *logging.Logger } func NewState(db dbm.DB) *State { diff --git a/execution/transactor.go b/execution/transactor.go index 9b6d3cd0af7d43c7653bac661e3e887fce2e9ea6..31e1971cf45896d13fa9d9a80b4f3bfe87af2e3e 100644 --- a/execution/transactor.go +++ b/execution/transactor.go @@ -32,7 +32,6 @@ import ( evm_events "github.com/hyperledger/burrow/execution/evm/events" "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/txs" abci_types "github.com/tendermint/abci/types" "github.com/tendermint/go-wire" @@ -65,14 +64,14 @@ type transactor struct { state acm.StateIterable eventEmitter event.Emitter broadcastTxAsync func(tx txs.Tx, callback func(res *abci_types.Response)) error - logger logging_types.InfoTraceLogger + logger *logging.Logger } var _ Transactor = &transactor{} func NewTransactor(blockchain blockchain.Blockchain, state acm.StateIterable, eventEmitter event.Emitter, broadcastTxAsync func(tx txs.Tx, callback func(res *abci_types.Response)) error, - logger logging_types.InfoTraceLogger) *transactor { + logger *logging.Logger) *transactor { return &transactor{ blockchain: blockchain, @@ -104,7 +103,7 @@ func (trans *transactor) Call(fromAddress, toAddress acm.Address, data []byte) ( params := vmParams(trans.blockchain) vmach := evm.NewVM(txCache, evm.DefaultDynamicMemoryProvider, params, caller.Address(), nil, - logging.WithScope(trans.logger, "Call")) + trans.logger.WithScope("Call")) vmach.SetPublisher(trans.eventEmitter) gas := params.GasLimit @@ -131,7 +130,7 @@ func (trans *transactor) CallCode(fromAddress acm.Address, code, data []byte) (* params := vmParams(trans.blockchain) vmach := evm.NewVM(txCache, evm.DefaultDynamicMemoryProvider, params, caller.Address(), nil, - logging.WithScope(trans.logger, "CallCode")) + trans.logger.WithScope("CallCode")) gas := params.GasLimit ret, err := vmach.Call(caller, callee, code, data, 0, &gas) if err != nil { @@ -147,7 +146,7 @@ func (trans *transactor) BroadcastTxAsync(tx txs.Tx, callback func(res *abci_typ // Broadcast a transaction. func (trans *transactor) BroadcastTx(tx txs.Tx) (*txs.Receipt, error) { - trans.logger.Trace("method", "BroadcastTx", + trans.logger.Trace.Log("method", "BroadcastTx", "tx_hash", tx.Hash(trans.blockchain.ChainID()), "tx", tx.String()) responseCh := make(chan *abci_types.Response, 1) diff --git a/keys/integration/key_client_test.go b/keys/integration/key_client_test.go index f165074bc0a99f8115abd956dab5e51622234ecc..83f5d4b6282521292a2326b1d76ee41599b53d47 100644 --- a/keys/integration/key_client_test.go +++ b/keys/integration/key_client_test.go @@ -13,13 +13,13 @@ import ( acm "github.com/hyperledger/burrow/account" "github.com/hyperledger/burrow/keys" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) //var logger, _ = lifecycle.NewStdErrLogger() -var logger = loggers.NewNoopInfoTraceLogger() +var logger = logging.NewNoopLogger() const monaxKeysBin = "monax-keys" const keysHost = "localhost" diff --git a/keys/key_client.go b/keys/key_client.go index e53a30ba7093f5741daa4d30f3ae8fca4ca90674..c70cb4aecca9af987937d6f50675c5def19f4bce 100644 --- a/keys/key_client.go +++ b/keys/key_client.go @@ -20,7 +20,6 @@ import ( acm "github.com/hyperledger/burrow/account" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" ) type KeyClient interface { @@ -61,7 +60,7 @@ var _ KeyClient = (*keyClient)(nil) type keyClient struct { requester Requester - logger logging_types.InfoTraceLogger + logger *logging.Logger } type signer struct { @@ -71,8 +70,8 @@ type signer struct { // keyClient.New returns a new monax-keys client for provided rpc location // Monax-keys connects over http request-responses -func NewKeyClient(rpcAddress string, logger logging_types.InfoTraceLogger) *keyClient { - logger = logging.WithScope(logger, "NewKeyClient") +func NewKeyClient(rpcAddress string, logger *logging.Logger) *keyClient { + logger = logger.WithScope("NewKeyClient") return &keyClient{ requester: DefaultRequester(rpcAddress, logger), logger: logger, diff --git a/keys/key_client_util.go b/keys/key_client_util.go index ea30faef9a2cc317a099835d18219af1173e74fa..89a41a366d359b1fc2cc90377fa20f5c9e004e08 100644 --- a/keys/key_client_util.go +++ b/keys/key_client_util.go @@ -22,7 +22,6 @@ import ( "net/http" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" ) // Monax-Keys server connects over http request-response structures @@ -34,14 +33,14 @@ type HTTPResponse struct { type Requester func(method string, args map[string]string) (response string, err error) -func DefaultRequester(rpcAddress string, logger logging_types.InfoTraceLogger) Requester { +func DefaultRequester(rpcAddress string, logger *logging.Logger) Requester { return func(method string, args map[string]string) (string, error) { body, err := json.Marshal(args) if err != nil { return "", err } endpoint := fmt.Sprintf("%s/%s", rpcAddress, method) - logging.TraceMsg(logger, "Sending request to key server", + logger.TraceMsg("Sending request to key server", "key_server_endpoint", endpoint, "request_body", string(body), ) @@ -57,7 +56,7 @@ func DefaultRequester(rpcAddress string, logger logging_types.InfoTraceLogger) R if res.Error != "" { return "", fmt.Errorf("response error when calling monax-keys at %s: %s", endpoint, res.Error) } - logging.TraceMsg(logger, "Received response from key server", + logger.TraceMsg("Received response from key server", "endpoint", endpoint, "request_body", string(body), "response", res, diff --git a/logging/adapters/stdlib/capture.go b/logging/adapters/stdlib/capture.go index 599a19a70aa36bc2107029ef12df1075055726c3..07512b75da0db9826fb82fbb127c02a78b8f034a 100644 --- a/logging/adapters/stdlib/capture.go +++ b/logging/adapters/stdlib/capture.go @@ -19,22 +19,21 @@ import ( "log" kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/logging/types" + "github.com/hyperledger/burrow/logging" ) -func Capture(stdLibLogger log.Logger, - logger types.InfoTraceLogger) io.Writer { +func Capture(stdLibLogger log.Logger, logger *logging.Logger) io.Writer { adapter := newAdapter(logger) stdLibLogger.SetOutput(adapter) return adapter } -func CaptureRootLogger(logger types.InfoTraceLogger) io.Writer { +func CaptureRootLogger(logger *logging.Logger) io.Writer { adapter := newAdapter(logger) log.SetOutput(adapter) return adapter } -func newAdapter(logger types.InfoTraceLogger) io.Writer { - return kitlog.NewStdlibAdapter(logger) +func newAdapter(logger *logging.Logger) io.Writer { + return kitlog.NewStdlibAdapter(logger.Trace) } diff --git a/logging/config/presets/instructions.go b/logging/config/presets/instructions.go index 2844ae8bc19f8453033e536c611d3e8039580ec9..9077d9e8242dc19423e5f1faf913ca97a9e650ec 100644 --- a/logging/config/presets/instructions.go +++ b/logging/config/presets/instructions.go @@ -6,7 +6,6 @@ import ( "github.com/hyperledger/burrow/logging/config" "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/logging/structure" - "github.com/hyperledger/burrow/logging/types" ) // Function to generate part of a tree of Sinks (e.g. append a single child node, or an entire subtree). @@ -64,7 +63,7 @@ var instructions = []Instruction{ return push(stack, config.Sink().SetTransform(config.PruneTransform(structure.TraceKey, structure.RunId)), config.Sink().SetTransform(config.FilterTransform(config.IncludeWhenAllMatch, - structure.ChannelKey, types.InfoChannelName)), + structure.ChannelKey, structure.InfoChannelName)), config.Sink().SetTransform(config.FilterTransform(config.ExcludeWhenAnyMatches, structure.ComponentKey, "Tendermint", "module", "p2p", @@ -88,7 +87,7 @@ var instructions = []Instruction{ builder: func(stack []*config.SinkConfig, ops []string) ([]*config.SinkConfig, []string, error) { sink := peek(stack) ensureFilter(sink) - sink.Transform.FilterConfig.AddPredicate(structure.ChannelKey, types.InfoChannelName) + sink.Transform.FilterConfig.AddPredicate(structure.ChannelKey, structure.InfoChannelName) return stack, ops, nil }, }, diff --git a/logging/config/presets/instructions_test.go b/logging/config/presets/instructions_test.go index c1da2f87b96d1c4eb84afe20de2da7a97a4f9dfb..adbfe1b0a5fd4bc6863c372c4a61a60a33f0f25c 100644 --- a/logging/config/presets/instructions_test.go +++ b/logging/config/presets/instructions_test.go @@ -6,7 +6,6 @@ import ( "github.com/hyperledger/burrow/logging/config" "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/logging/structure" - "github.com/hyperledger/burrow/logging/types" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -16,11 +15,11 @@ func TestBuildSinkConfig(t *testing.T) { require.NoError(t, err) expectedSink := config.Sink(). SetTransform(config.FilterTransform(config.IncludeWhenAnyMatches, - structure.ChannelKey, types.InfoChannelName)).SetOutput(config.StdoutOutput().SetFormat(loggers.TerminalFormat)).AddSinks( + structure.ChannelKey, structure.InfoChannelName)).SetOutput(config.StdoutOutput().SetFormat(loggers.TerminalFormat)).AddSinks( config.Sink().SetTransform(config.FilterTransform(config.NoFilterMode, - structure.ChannelKey, types.InfoChannelName)).SetOutput(config.StderrOutput()).AddSinks( + structure.ChannelKey, structure.InfoChannelName)).SetOutput(config.StderrOutput()).AddSinks( config.Sink().SetTransform(config.FilterTransform(config.NoFilterMode, - structure.ChannelKey, types.InfoChannelName)).SetOutput(config.StdoutOutput()))) + structure.ChannelKey, structure.InfoChannelName)).SetOutput(config.StdoutOutput()))) //fmt.Println(config.JSONString(expectedSink), "\n", config.JSONString(builtSink)) assert.Equal(t, config.JSONString(expectedSink), config.JSONString(builtSink)) @@ -32,7 +31,7 @@ func TestMinimalPreset(t *testing.T) { expectedSink := config.Sink(). AddSinks(config.Sink().SetTransform(config.PruneTransform(structure.TraceKey, structure.RunId)). AddSinks(config.Sink().SetTransform(config.FilterTransform(config.IncludeWhenAllMatch, - structure.ChannelKey, types.InfoChannelName)). + structure.ChannelKey, structure.InfoChannelName)). AddSinks(config.Sink().SetTransform(config.FilterTransform(config.ExcludeWhenAnyMatches, structure.ComponentKey, "Tendermint", "module", "p2p", diff --git a/logging/config/sinks.go b/logging/config/sinks.go index 169e886f68fa075bcd0d34fc54b792f609c7d95b..aa30a69e1e07172d6e9751b7a21cd8515ded60ed 100644 --- a/logging/config/sinks.go +++ b/logging/config/sinks.go @@ -6,7 +6,6 @@ import ( "github.com/eapache/channels" kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/logging/structure" ) @@ -32,9 +31,10 @@ const ( // Remove key-val pairs from each log line Prune transformType = "prune" // Add key value pairs to each log line - Label transformType = "label" - Capture transformType = "capture" - Sort transformType = "sort" + Label transformType = "label" + Capture transformType = "capture" + Sort transformType = "sort" + Vectorise transformType = "vectorise" // TODO [Silas]: add 'flush on exit' transform which flushes the buffer of // CaptureLogger to its OutputLogger a non-passthrough capture when an exit @@ -199,6 +199,8 @@ func FileOutput(path string) *OutputConfig { } } +// Transforms + func CaptureTransform(name string, bufferCap int, passthrough bool) *TransformConfig { return &TransformConfig{ TransformType: Capture, @@ -275,6 +277,12 @@ func SortTransform(keys ...string) *TransformConfig { } } +func VectoriseTransform() *TransformConfig { + return &TransformConfig{ + TransformType: Vectorise, + } +} + // Logger formation func (sinkConfig *SinkConfig) BuildLogger() (kitlog.Logger, map[string]*loggers.CaptureLogger, error) { return BuildLoggerFromSinkConfig(sinkConfig, make(map[string]*loggers.CaptureLogger)) @@ -404,6 +412,8 @@ func BuildTransformLogger(transformConfig *TransformConfig, captures map[string] return nil, nil, fmt.Errorf("sort transform specified but no SortConfig provided") } return loggers.SortLogger(outputLogger, transformConfig.SortConfig.Keys...), captures, nil + case Vectorise: + return loggers.VectorValuedLogger(outputLogger), captures, nil default: return nil, captures, fmt.Errorf("could not build logger for transform: '%s'", transformConfig.TransformType) } @@ -411,7 +421,7 @@ func BuildTransformLogger(transformConfig *TransformConfig, captures map[string] func signalPassthroughLogger(ifSignalLogger kitlog.Logger, otherwiseLogger kitlog.Logger) kitlog.Logger { return kitlog.LoggerFunc(func(keyvals ...interface{}) error { - if logging.Signal(keyvals) != "" { + if structure.Signal(keyvals) != "" { return ifSignalLogger.Log(keyvals...) } return otherwiseLogger.Log(keyvals...) diff --git a/logging/convention.go b/logging/convention.go deleted file mode 100644 index 65dc2e5b98106caa86768139dbf509e0c321e92d..0000000000000000000000000000000000000000 --- a/logging/convention.go +++ /dev/null @@ -1,69 +0,0 @@ -// Copyright 2017 Monax Industries Limited -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package logging - -import ( - kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/logging/structure" - "github.com/hyperledger/burrow/logging/types" -) - -// Helper functions for InfoTraceLoggers, sort of extension methods to loggers -// to centralise and establish logging conventions on top of in with the base -// logging interface - -// Record structured Info log line with a message -func InfoMsg(logger types.InfoTraceLogger, message string, keyvals ...interface{}) error { - return Msg(kitlog.LoggerFunc(logger.Info), message, keyvals...) -} - -// Record structured Trace log line with a message -func TraceMsg(logger types.InfoTraceLogger, message string, keyvals ...interface{}) error { - return Msg(kitlog.LoggerFunc(logger.Trace), message, keyvals...) -} - -// Establish or extend the scope of this logger by appending scopeName to the Scope vector. -// Like With the logging scope is append only but can be used to provide parenthetical scopes by hanging on to the -// parent scope and using once the scope has been exited. The scope mechanism does is agnostic to the type of scope -// so can be used to identify certain segments of the call stack, a lexical scope, or any other nested scope. -func WithScope(logger types.InfoTraceLogger, scopeName string) types.InfoTraceLogger { - // InfoTraceLogger will collapse successive (ScopeKey, scopeName) pairs into a vector in the order which they appear - return logger.With(structure.ScopeKey, scopeName) -} - -// Record a structured log line with a message -func Msg(logger kitlog.Logger, message string, keyvals ...interface{}) error { - prepended := structure.CopyPrepend(keyvals, structure.MessageKey, message) - return logger.Log(prepended...) -} - -// Sends the sync signal which causes any syncing loggers to sync. -// loggers receiving the signal should drop the signal logline from output -func Sync(logger kitlog.Logger) error { - return logger.Log(structure.SignalKey, structure.SyncSignal) -} - -// Tried to interpret the logline as a signal by matching the last key-value pair as a signal, returns empty string if -// no match -func Signal(keyvals []interface{}) string { - last := len(keyvals) - 1 - if last > 0 && keyvals[last-1] == structure.SignalKey { - signal, ok := keyvals[last].(string) - if ok { - return signal - } - } - return "" -} diff --git a/logging/lifecycle/lifecycle.go b/logging/lifecycle/lifecycle.go index e68a26021c129b918d8ea1b3d142d6fe441e6341..4a88f03413391e9fdca6ddc2fb5a96985d914592 100644 --- a/logging/lifecycle/lifecycle.go +++ b/logging/lifecycle/lifecycle.go @@ -30,7 +30,6 @@ import ( "github.com/eapache/channels" kitlog "github.com/go-kit/kit/log" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/types" "github.com/streadway/simpleuuid" ) @@ -38,8 +37,8 @@ import ( // to set up their root logger and capture any other logging output. // Obtain a logger from a LoggingConfig -func NewLoggerFromLoggingConfig(loggingConfig *config.LoggingConfig) (types.InfoTraceLogger, error) { - var logger types.InfoTraceLogger +func NewLoggerFromLoggingConfig(loggingConfig *config.LoggingConfig) (*logging.Logger, error) { + var logger *logging.Logger var errCh channels.Channel var err error if loggingConfig == nil { @@ -66,8 +65,7 @@ func NewLoggerFromLoggingConfig(loggingConfig *config.LoggingConfig) (types.Info // Hot swap logging config by replacing output loggers of passed InfoTraceLogger // with those built from loggingConfig -func SwapOutputLoggersFromLoggingConfig(logger types.InfoTraceLogger, - loggingConfig *config.LoggingConfig) error { +func SwapOutputLoggersFromLoggingConfig(logger *logging.Logger, loggingConfig *config.LoggingConfig) error { outputLogger, err := infoTraceLoggerFromLoggingConfig(loggingConfig) if err != nil { return err @@ -76,32 +74,32 @@ func SwapOutputLoggersFromLoggingConfig(logger types.InfoTraceLogger, return nil } -func NewStdErrLogger() (types.InfoTraceLogger, channels.Channel, error) { - logger, err := loggers.NewStreamLogger(os.Stderr, loggers.TerminalFormat) +func NewStdErrLogger() (*logging.Logger, channels.Channel, error) { + outputLogger, err := loggers.NewStreamLogger(os.Stderr, loggers.TerminalFormat) if err != nil { return nil, nil, err } - itLogger, errCh := NewLogger(logger) - return itLogger, errCh, nil + logger, errCh := NewLogger(outputLogger) + return logger, errCh, nil } // Provided a standard logger that outputs to the supplied underlying outputLogger -func NewLogger(outputLogger kitlog.Logger) (types.InfoTraceLogger, channels.Channel) { - infoTraceLogger, errCh := loggers.NewInfoTraceLogger(outputLogger) +func NewLogger(outputLogger kitlog.Logger) (*logging.Logger, channels.Channel) { + logger, errCh := logging.NewLogger(outputLogger) // Create a random ID based on start time uuid, _ := simpleuuid.NewTime(time.Now()) var runId string if uuid != nil { runId = uuid.String() } - return logging.WithMetadata(infoTraceLogger.With(structure.RunId, runId)), errCh + return logger.With(structure.RunId, runId), errCh } -func JustLogger(logger types.InfoTraceLogger, _ channels.Channel) types.InfoTraceLogger { +func JustLogger(logger *logging.Logger, _ channels.Channel) *logging.Logger { return logger } -func CaptureStdlibLogOutput(infoTraceLogger types.InfoTraceLogger) { +func CaptureStdlibLogOutput(infoTraceLogger *logging.Logger) { stdlib.CaptureRootLogger(infoTraceLogger. With(structure.CapturedLoggingSourceKey, "stdlib_log")) } diff --git a/logging/lifecycle/lifecycle_test.go b/logging/lifecycle/lifecycle_test.go index c38e6491406a376edd1c962ecf89aadf2405bff9..91ae8a16cbf995a751657ffe4074cc5f818dc968 100644 --- a/logging/lifecycle/lifecycle_test.go +++ b/logging/lifecycle/lifecycle_test.go @@ -13,7 +13,7 @@ func TestNewLoggerFromLoggingConfig(t *testing.T) { reader := CaptureStderr(t, func() { logger, err := NewLoggerFromLoggingConfig(nil) assert.NoError(t, err) - logger.Info("Quick", "Test") + logger.Info.Log("Quick", "Test") }) line, _, err := reader.ReadLine() assert.NoError(t, err) diff --git a/logging/logger.go b/logging/logger.go new file mode 100644 index 0000000000000000000000000000000000000000..995c60f1dcbea261833a2d40522d711de5a779cd --- /dev/null +++ b/logging/logger.go @@ -0,0 +1,153 @@ +// Copyright 2017 Monax Industries Limited +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package logging + +import ( + "github.com/eapache/channels" + kitlog "github.com/go-kit/kit/log" + "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging/structure" +) + +// InfoTraceLogger maintains provides two logging 'channels' that are interlaced +// to provide a coarse grained filter to distinguish human-consumable 'Info' +// messages and execution level 'Trace' messages. +type Logger struct { + // Send a log message to the Info channel, formed of a sequence of key value + // pairs. Info messages should be operationally interesting to a human who is + // monitoring the logs. But not necessarily a human who is trying to + // understand or debug the system. Any handled errors or warnings should be + // sent to the Info channel (where you may wish to tag them with a suitable + // key-value pair to categorise them as such). + Info kitlog.Logger + // Send an log message to the Trace channel, formed of a sequence of key-value + // pairs. Trace messages can be used for any state change in the system that + // may be of interest to a machine consumer or a human who is trying to debug + // the system or trying to understand the system in detail. If the messages + // are very point-like and contain little structure, consider using a metric + // instead. + Trace kitlog.Logger + Output *kitlog.SwapLogger +} + +// Create an InfoTraceLogger by passing the initial outputLogger. +func NewLogger(outputLogger kitlog.Logger) (*Logger, channels.Channel) { + // We will never halt the progress of a log emitter. If log output takes too + // long will start dropping log lines by using a ring buffer. + swapLogger := new(kitlog.SwapLogger) + swapLogger.Swap(outputLogger) + wrappedOutputLogger, errCh := wrapOutputLogger(swapLogger) + return &Logger{ + Output: swapLogger, + // logging contexts + Info: kitlog.With(wrappedOutputLogger, + structure.ChannelKey, structure.InfoChannelName, + ), + Trace: kitlog.With(wrappedOutputLogger, + structure.ChannelKey, structure.TraceChannelName, + ), + }, errCh +} + +func NewNoopLogger() *Logger { + return &Logger{ + Info: kitlog.NewNopLogger(), + Trace: kitlog.NewNopLogger(), + Output: new(kitlog.SwapLogger), + } +} + +// A logging context (see go-kit log's Context). Takes a sequence key values +// via With or WithPrefix and ensures future calls to log will have those +// contextual values appended to the call to an underlying logger. +// Values can be dynamic by passing an instance of the kitlog.Valuer interface +// This provides an interface version of the kitlog.Context struct to be used +// For implementations that wrap a kitlog.Context. In addition it makes no +// assumption about the name or signature of the logging method(s). +// See InfoTraceLogger +func (l *Logger) With(keyvals ...interface{}) *Logger { + return &Logger{ + Output: l.Output, + Info: kitlog.With(l.Info, keyvals...), + Trace: kitlog.With(l.Trace, keyvals...), + } +} + +// Establish a context on the Info channel keeping Trace the same +func (l *Logger) WithInfo(keyvals ...interface{}) *Logger { + return &Logger{ + Output: l.Output, + Info: kitlog.With(l.Info, keyvals...), + Trace: l.Trace, + } +} + +// Establish a context on the Trace channel keeping Info the same +func (l *Logger) WithTrace(keyvals ...interface{}) *Logger { + return &Logger{ + Output: l.Output, + Info: l.Info, + Trace: kitlog.With(l.Trace, keyvals...), + } +} + +func (l *Logger) WithPrefix(keyvals ...interface{}) *Logger { + return &Logger{ + Output: l.Output, + Info: kitlog.WithPrefix(l.Info, keyvals...), + Trace: kitlog.WithPrefix(l.Trace, keyvals...), + } +} + +// Hot swap the underlying outputLogger with another one to re-route messages +func (l *Logger) SwapOutput(infoLogger kitlog.Logger) { + l.Output.Swap(infoLogger) +} + +// Record structured Info lo`g line with a message +func (l *Logger) InfoMsg(message string, keyvals ...interface{}) error { + return Msg(l.Info, message, keyvals...) +} + +// Record structured Trace log line with a message +func (l *Logger) TraceMsg(message string, keyvals ...interface{}) error { + return Msg(l.Trace, message, keyvals...) +} + +// Establish or extend the scope of this logger by appending scopeName to the Scope vector. +// Like With the logging scope is append only but can be used to provide parenthetical scopes by hanging on to the +// parent scope and using once the scope has been exited. The scope mechanism does is agnostic to the type of scope +// so can be used to identify certain segments of the call stack, a lexical scope, or any other nested scope. +func (l *Logger) WithScope(scopeName string) *Logger { + // InfoTraceLogger will collapse successive (ScopeKey, scopeName) pairs into a vector in the order which they appear + return l.With(structure.ScopeKey, scopeName) +} + +// Record a structured log line with a message +func Msg(logger kitlog.Logger, message string, keyvals ...interface{}) error { + prepended := structure.CopyPrepend(keyvals, structure.MessageKey, message) + return logger.Log(prepended...) +} + +// Wrap the output loggers with a a set of standard transforms, a non-blocking +// ChannelLogger and an outer context +func wrapOutputLogger(outputLogger kitlog.Logger) (kitlog.Logger, channels.Channel) { + //return outputLogger, channels.NewDeadChannel() + return loggers.NonBlockingLogger(loggers.BurrowFormatLogger(outputLogger)) + //return NonBlockingLogger(VectorValuedLogger(SortLogger(BurrowFormatLogger(outputLogger), + // structure.ChannelKey, structure.MessageKey, structure.TimeKey, structure.ComponentKey))) + //return VectorValuedLogger(SortLogger(BurrowFormatLogger(outputLogger), + // structure.ChannelKey, structure.MessageKey, structure.TimeKey, structure.ComponentKey)), channels.NewDeadChannel() +} diff --git a/logging/loggers/info_trace_logger_test.go b/logging/logger_test.go similarity index 82% rename from logging/loggers/info_trace_logger_test.go rename to logging/logger_test.go index 2356748dc102e873c86d02a327c0da1c0fa984cf..05c0858c1764171c1776ca9be766e5aed6ab3c7f 100644 --- a/logging/loggers/info_trace_logger_test.go +++ b/logging/logger_test.go @@ -12,7 +12,7 @@ // See the License for the specific language governing permissions and // limitations under the License. -package loggers +package logging import ( "os" @@ -23,11 +23,11 @@ import ( func TestLogger(t *testing.T) { stderrLogger := kitlog.NewLogfmtLogger(os.Stderr) - logger, _ := NewInfoTraceLogger(stderrLogger) - logger.Trace("hello", "barry") + logger, _ := NewLogger(stderrLogger) + logger.Trace.Log("hello", "barry") } func TestNewNoopInfoTraceLogger(t *testing.T) { - logger := NewNoopInfoTraceLogger() - logger.Trace("goodbye", "trevor") + logger := NewNoopLogger() + logger.Trace.Log("goodbye", "trevor") } diff --git a/logging/loggers/burrow_format_logger.go b/logging/loggers/burrow_format_logger.go index 51f025e73434f2cfdd4c46a146f503dc30acbd72..f32d0933de7c18fd8abe6d640f529460158253a1 100644 --- a/logging/loggers/burrow_format_logger.go +++ b/logging/loggers/burrow_format_logger.go @@ -45,6 +45,8 @@ func (bfl *burrowFormatLogger) Log(keyvals ...interface{}) error { func(key interface{}, value interface{}) (interface{}, interface{}) { switch v := value.(type) { case string: + case fmt.Stringer: + value = v.String() case []byte: value = fmt.Sprintf("%X", v) case time.Time: diff --git a/logging/loggers/capture_logger.go b/logging/loggers/capture_logger.go index e195c3a454c24fdd9d8056cf937197a27642b7a5..a470582afd0093fe7bdfe53b87ff7de951da92a4 100644 --- a/logging/loggers/capture_logger.go +++ b/logging/loggers/capture_logger.go @@ -16,13 +16,12 @@ type CaptureLogger struct { var _ kitlog.Logger = (*CaptureLogger)(nil) -// Capture logger captures output set to it into a buffer logger and retains -// a reference to an output logger (the logger whose input it is capturing). -// It can optionally passthrough logs to the output logger. +// Capture logger captures output sent to it in a buffer retaining +// a reference to its output logger (the logger whose input it is capturing). +// It can optionally pass logs through to the output logger. // Because it holds a reference to its output it can also be used to coordinate -// Flushing of the buffer to the output logger in exceptional circumstances only -func NewCaptureLogger(outputLogger kitlog.Logger, bufferCap channels.BufferCap, - passthrough bool) *CaptureLogger { +// Flushing of the buffer to the output logger in special circumstances. +func NewCaptureLogger(outputLogger kitlog.Logger, bufferCap channels.BufferCap, passthrough bool) *CaptureLogger { return &CaptureLogger{ bufferLogger: NewChannelLogger(bufferCap), outputLogger: outputLogger, @@ -41,17 +40,17 @@ func (cl *CaptureLogger) Log(keyvals ...interface{}) error { // Sets whether the CaptureLogger is forwarding log lines sent to it through // to its output logger. Concurrently safe. func (cl *CaptureLogger) SetPassthrough(passthrough bool) { - cl.RWMutex.Lock() + cl.Lock() cl.passthrough = passthrough - cl.RWMutex.Unlock() + cl.Unlock() } // Gets whether the CaptureLogger is forwarding log lines sent to through to its // OutputLogger. Concurrently Safe. func (cl *CaptureLogger) Passthrough() bool { - cl.RWMutex.RLock() + cl.RLock() passthrough := cl.passthrough - cl.RWMutex.RUnlock() + cl.RUnlock() return passthrough } diff --git a/logging/loggers/info_trace_logger.go b/logging/loggers/info_trace_logger.go deleted file mode 100644 index df51014787d13d90075847869a52f0a01b7d9955..0000000000000000000000000000000000000000 --- a/logging/loggers/info_trace_logger.go +++ /dev/null @@ -1,103 +0,0 @@ -// Copyright 2017 Monax Industries Limited -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package loggers - -import ( - "github.com/eapache/channels" - kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/logging/structure" - "github.com/hyperledger/burrow/logging/types" -) - -type infoTraceLogger struct { - infoContext kitlog.Logger - traceContext kitlog.Logger - outputLogger *kitlog.SwapLogger - outputLoggerErrors channels.Channel -} - -// Interface assertions -var _ types.InfoTraceLogger = (*infoTraceLogger)(nil) -var _ kitlog.Logger = (types.InfoTraceLogger)(nil) - -// Create an InfoTraceLogger by passing the initial outputLogger. -func NewInfoTraceLogger(outputLogger kitlog.Logger) (types.InfoTraceLogger, channels.Channel) { - // We will never halt the progress of a log emitter. If log output takes too - // long will start dropping log lines by using a ring buffer. - swapLogger := new(kitlog.SwapLogger) - swapLogger.Swap(outputLogger) - wrappedOutputLogger, errCh := wrapOutputLogger(swapLogger) - return &infoTraceLogger{ - outputLogger: swapLogger, - outputLoggerErrors: errCh, - // logging contexts - infoContext: kitlog.With(wrappedOutputLogger, - structure.ChannelKey, types.InfoChannelName, - ), - traceContext: kitlog.With(wrappedOutputLogger, - structure.ChannelKey, types.TraceChannelName, - ), - }, errCh -} - -func NewNoopInfoTraceLogger() types.InfoTraceLogger { - logger, _ := NewInfoTraceLogger(nil) - return logger -} - -func (l *infoTraceLogger) With(keyvals ...interface{}) types.InfoTraceLogger { - return &infoTraceLogger{ - outputLogger: l.outputLogger, - infoContext: kitlog.With(l.infoContext, keyvals...), - traceContext: kitlog.With(l.traceContext, keyvals...), - } -} - -func (l *infoTraceLogger) WithPrefix(keyvals ...interface{}) types.InfoTraceLogger { - return &infoTraceLogger{ - outputLogger: l.outputLogger, - infoContext: kitlog.WithPrefix(l.infoContext, keyvals...), - traceContext: kitlog.WithPrefix(l.traceContext, keyvals...), - } -} - -func (l *infoTraceLogger) Info(keyvals ...interface{}) error { - return l.infoContext.Log(keyvals...) -} - -func (l *infoTraceLogger) Trace(keyvals ...interface{}) error { - return l.traceContext.Log(keyvals...) -} - -func (l *infoTraceLogger) SwapOutput(infoLogger kitlog.Logger) { - l.outputLogger.Swap(infoLogger) -} - -// If logged to as a plain kitlog logger presume the message is for Trace -// This favours keeping Info reasonably quiet. Note that an InfoTraceLogger -// aware adapter can make its own choices, but we tend to think of logs from -// dependencies as less interesting than logs generated by us or specifically -// routed by us. -func (l *infoTraceLogger) Log(keyvals ...interface{}) error { - return l.Trace(keyvals...) -} - -// Wrap the output loggers with a a set of standard transforms, a non-blocking -// ChannelLogger and an outer context -func wrapOutputLogger(outputLogger kitlog.Logger) (kitlog.Logger, channels.Channel) { - //return outputLogger, channels.NewDeadChannel() - return VectorValuedLogger(SortLogger(BurrowFormatLogger(outputLogger), - structure.ChannelKey, structure.MessageKey, structure.TimeKey, structure.ComponentKey)), channels.NewDeadChannel() -} diff --git a/logging/loggers/output_loggers.go b/logging/loggers/output_loggers.go index c39d3873cfaf21d424e1bba17509f21e43c253eb..d22f77f8bfc446a4f79ff78466738ab9e88c472f 100644 --- a/logging/loggers/output_loggers.go +++ b/logging/loggers/output_loggers.go @@ -8,9 +8,7 @@ import ( kitlog "github.com/go-kit/kit/log" "github.com/go-kit/kit/log/term" - "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - "github.com/hyperledger/burrow/logging/types" ) const ( @@ -37,7 +35,7 @@ func NewStreamLogger(writer io.Writer, format string) (kitlog.Logger, error) { case TerminalFormat: logger = term.NewLogger(writer, kitlog.NewLogfmtLogger, func(keyvals ...interface{}) term.FgBgColor { switch structure.Value(keyvals, structure.ChannelKey) { - case types.TraceChannelName: + case structure.TraceChannelName: return term.FgBgColor{Fg: term.DarkGreen} default: return term.FgBgColor{Fg: term.Yellow} @@ -52,7 +50,7 @@ func NewStreamLogger(writer io.Writer, format string) (kitlog.Logger, error) { } // Don't log signals return kitlog.LoggerFunc(func(keyvals ...interface{}) error { - if logging.Signal(keyvals) != "" { + if structure.Signal(keyvals) != "" { return nil } return logger.Log(keyvals...) @@ -69,7 +67,7 @@ func NewFileLogger(path string, formatName string) (kitlog.Logger, error) { return nil, err } return kitlog.LoggerFunc(func(keyvals ...interface{}) error { - if logging.Signal(keyvals) == structure.SyncSignal { + if structure.Signal(keyvals) == structure.SyncSignal { return f.Sync() } return streamLogger.Log(keyvals...) diff --git a/logging/loggers/output_loggers_test.go b/logging/loggers/output_loggers_test.go index 77e948fc07c0f765fa6b3d8210de3a71c49943ac..6e3d83817f923a24fb698cb226aa5fc7d8e81ac3 100644 --- a/logging/loggers/output_loggers_test.go +++ b/logging/loggers/output_loggers_test.go @@ -5,7 +5,7 @@ import ( "io/ioutil" "testing" - "github.com/hyperledger/burrow/logging" + "github.com/hyperledger/burrow/logging/structure" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -21,7 +21,7 @@ func TestNewFileLogger(t *testing.T) { err = fileLogger.Log("foo", "bar") require.NoError(t, err) - err = logging.Sync(fileLogger) + err = structure.Sync(fileLogger) require.NoError(t, err) bs, err := ioutil.ReadFile(logPath) @@ -37,7 +37,7 @@ func TestNewStreamLogger(t *testing.T) { err = logger.Log("oh", "my") require.NoError(t, err) - err = logging.Sync(logger) + err = structure.Sync(logger) require.NoError(t, err) assert.Equal(t, "oh=my\n", string(buf.Bytes())) diff --git a/logging/metadata.go b/logging/metadata.go index 1699fb1a2c08e43997673ecf6789d7bc1a501262..485c8f2be568d20c70c0d9041c44d035401d4ce2 100644 --- a/logging/metadata.go +++ b/logging/metadata.go @@ -15,12 +15,9 @@ package logging import ( - "time" - kitlog "github.com/go-kit/kit/log" "github.com/go-stack/stack" "github.com/hyperledger/burrow/logging/structure" - "github.com/hyperledger/burrow/logging/types" ) const ( @@ -32,15 +29,12 @@ const ( infoTraceLoggerCallDepth = 5 ) -var defaultTimestampUTCValuer kitlog.Valuer = func() interface{} { - return time.Now() -} - -func WithMetadata(infoTraceLogger types.InfoTraceLogger) types.InfoTraceLogger { - return infoTraceLogger.With(structure.TimeKey, defaultTimestampUTCValuer, - structure.TraceKey, TraceValuer()) +func WithMetadata(logger *Logger) *Logger { + return logger.With(structure.TimeKey, kitlog.DefaultTimestampUTC, + structure.TraceKey, TraceValuer(), + structure.CallerKey, kitlog.Caller(infoTraceLoggerCallDepth)) } func TraceValuer() kitlog.Valuer { - return func() interface{} { return stack.Trace().TrimBelow(stack.Caller(infoTraceLoggerCallDepth - 1)) } + return func() interface{} { return stack.Trace() } } diff --git a/logging/structure/structure.go b/logging/structure/structure.go index 97cfd7d3b11925ee940f6518e0e6ad7e34bf7777..41fc03128b496f5ef24d535bb0a1e1939ff86c9d 100644 --- a/logging/structure/structure.go +++ b/logging/structure/structure.go @@ -17,6 +17,8 @@ package structure import ( "encoding/json" "fmt" + + kitlog "github.com/go-kit/kit/log" ) const ( @@ -46,7 +48,9 @@ const ( // Provides special instructions (that may be ignored) to downstream loggers SignalKey = "__signal__" // The sync signal instructs sync-able loggers to sync - SyncSignal = "__sync__" + SyncSignal = "__sync__" + InfoChannelName = "Info" + TraceChannelName = "Trace" ) // Pull the specified values from a structured log line into a map. @@ -247,3 +251,22 @@ func StringifyKey(key interface{}) string { } } } + +// Sends the sync signal which causes any syncing loggers to sync. +// loggers receiving the signal should drop the signal logline from output +func Sync(logger kitlog.Logger) error { + return logger.Log(SignalKey, SyncSignal) +} + +// Tried to interpret the logline as a signal by matching the last key-value pair as a signal, returns empty string if +// no match +func Signal(keyvals []interface{}) string { + last := len(keyvals) - 1 + if last > 0 && keyvals[last-1] == SignalKey { + signal, ok := keyvals[last].(string) + if ok { + return signal + } + } + return "" +} diff --git a/logging/types/info_trace_logger.go b/logging/types/info_trace_logger.go deleted file mode 100644 index 613cf07ca00f6bc307998dcddee092938280e40f..0000000000000000000000000000000000000000 --- a/logging/types/info_trace_logger.go +++ /dev/null @@ -1,58 +0,0 @@ -package types - -import kitlog "github.com/go-kit/kit/log" - -const ( - InfoChannelName = "Info" - TraceChannelName = "Trace" - - InfoLevelName = InfoChannelName - TraceLevelName = TraceChannelName -) - -// InfoTraceLogger maintains provides two logging 'channels' that are interlaced -// to provide a coarse grained filter to distinguish human-consumable 'Info' -// messages and execution level 'Trace' messages. -type InfoTraceLogger interface { - // Send a log message to the default channel of the implementation - kitlog.Logger - - // Send an log message to the Info channel, formed of a sequence of key value - // pairs. Info messages should be operationally interesting to a human who is - // monitoring the logs. But not necessarily a human who is trying to - // understand or debug the system. Any handled errors or warnings should be - // sent to the Info channel (where you may wish to tag them with a suitable - // key-value pair to categorise them as such). - Info(keyvals ...interface{}) error - - // Send an log message to the Trace channel, formed of a sequence of key-value - // pairs. Trace messages can be used for any state change in the system that - // may be of interest to a machine consumer or a human who is trying to debug - // the system or trying to understand the system in detail. If the messages - // are very point-like and contain little structure, consider using a metric - // instead. - Trace(keyvals ...interface{}) error - - // A logging context (see go-kit log's Context). Takes a sequence key values - // via With or WithPrefix and ensures future calls to log will have those - // contextual values appended to the call to an underlying logger. - // Values can be dynamic by passing an instance of the kitlog.Valuer interface - // This provides an interface version of the kitlog.Context struct to be used - // For implementations that wrap a kitlog.Context. In addition it makes no - // assumption about the name or signature of the logging method(s). - // See InfoTraceLogger - - // Establish a context by appending contextual key-values to any existing - // contextual values - With(keyvals ...interface{}) InfoTraceLogger - - // Establish a context by prepending contextual key-values to any existing - // contextual values - WithPrefix(keyvals ...interface{}) InfoTraceLogger - - // Hot swap the underlying outputLogger with another one to re-route messages - SwapOutput(outputLogger kitlog.Logger) -} - -// Interface assertions -var _ kitlog.Logger = (InfoTraceLogger)(nil) diff --git a/rpc/service.go b/rpc/service.go index 35a2bec61a75c115ba21fb3241d41f7c10caeace..c0bf15de5811244473777548240bcf3b33937d4f 100644 --- a/rpc/service.go +++ b/rpc/service.go @@ -26,7 +26,6 @@ import ( "github.com/hyperledger/burrow/execution" "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/permission" "github.com/hyperledger/burrow/project" "github.com/hyperledger/burrow/txs" @@ -47,12 +46,12 @@ type Service struct { blockchain bcm.Blockchain transactor execution.Transactor nodeView query.NodeView - logger logging_types.InfoTraceLogger + logger *logging.Logger } func NewService(ctx context.Context, state acm.StateIterable, nameReg execution.NameRegIterable, subscribable event.Subscribable, blockchain bcm.Blockchain, transactor execution.Transactor, - nodeView query.NodeView, logger logging_types.InfoTraceLogger) *Service { + nodeView query.NodeView, logger *logging.Logger) *Service { return &Service{ ctx: ctx, @@ -67,7 +66,7 @@ func NewService(ctx context.Context, state acm.StateIterable, nameReg execution. } // Provides a sub-service with only the subscriptions methods -func NewSubscribableService(subscribable event.Subscribable, logger logging_types.InfoTraceLogger) *Service { +func NewSubscribableService(subscribable event.Subscribable, logger *logging.Logger) *Service { return &Service{ ctx: context.Background(), subscribable: subscribable, @@ -101,7 +100,7 @@ func (s *Service) Subscribe(ctx context.Context, subscriptionID string, eventID callback func(resultEvent *ResultEvent) bool) error { queryBuilder := event.QueryForEventID(eventID) - logging.InfoMsg(s.logger, "Subscribing to events", + s.logger.InfoMsg("Subscribing to events", "query", queryBuilder.String(), "subscription_id", subscriptionID, "event_id", eventID) @@ -109,7 +108,7 @@ func (s *Service) Subscribe(ctx context.Context, subscriptionID string, eventID func(message interface{}) bool { resultEvent, err := NewResultEvent(eventID, message) if err != nil { - logging.InfoMsg(s.logger, "Received event that could not be mapped to ResultEvent", + s.logger.InfoMsg("Received event that could not be mapped to ResultEvent", structure.ErrorKey, err, "subscription_id", subscriptionID, "event_id", eventID) @@ -120,7 +119,7 @@ func (s *Service) Subscribe(ctx context.Context, subscriptionID string, eventID } func (s *Service) Unsubscribe(ctx context.Context, subscriptionID string) error { - logging.InfoMsg(s.logger, "Unsubscribing from events", + s.logger.InfoMsg("Unsubscribing from events", "subscription_id", subscriptionID) err := s.subscribable.UnsubscribeAll(ctx, subscriptionID) if err != nil { @@ -207,7 +206,7 @@ func (s *Service) GetAccount(address acm.Address) (*ResultGetAccount, error) { if err != nil { return nil, err } - s.logger.Trace("method", "GetAccount", + s.logger.Trace.Log("method", "GetAccount", "address", address, "sequence", acc.Sequence()) return &ResultGetAccount{Account: acm.AsConcreteAccount(acc)}, nil diff --git a/rpc/tm/integration/shared.go b/rpc/tm/integration/shared.go index d7ad492993dc992d02412d5b61ba299fcd514d73..a84ed02d27ceecdf6ea693a068c89dd5be7508a8 100644 --- a/rpc/tm/integration/shared.go +++ b/rpc/tm/integration/shared.go @@ -35,9 +35,9 @@ import ( "github.com/hyperledger/burrow/core" "github.com/hyperledger/burrow/execution" "github.com/hyperledger/burrow/genesis" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/config" "github.com/hyperledger/burrow/logging/lifecycle" - "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/permission" "github.com/hyperledger/burrow/rpc" tm_client "github.com/hyperledger/burrow/rpc/tm/client" @@ -80,7 +80,7 @@ func TestWrapper(runner func() int) int { os.Chdir(testDir) tmConf := tm_config.DefaultConfig() - logger := loggers.NewNoopInfoTraceLogger() + logger := logging.NewNoopLogger() if debugLogging { var err error // Change config as needed diff --git a/rpc/tm/methods.go b/rpc/tm/methods.go index 9ddf00ee35ecbb31f3ea8a302a77369991d9a9fb..719f8cd1e4c927a6e98c6649db5b77327eff61fd 100644 --- a/rpc/tm/methods.go +++ b/rpc/tm/methods.go @@ -9,7 +9,6 @@ import ( "github.com/hyperledger/burrow/event" "github.com/hyperledger/burrow/execution" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/rpc" "github.com/hyperledger/burrow/txs" gorpc "github.com/tendermint/tendermint/rpc/lib/server" @@ -59,8 +58,8 @@ const ( const SubscriptionTimeoutSeconds = 5 * time.Second -func GetRoutes(service *rpc.Service, logger logging_types.InfoTraceLogger) map[string]*gorpc.RPCFunc { - logger = logging.WithScope(logger, "GetRoutes") +func GetRoutes(service *rpc.Service, logger *logging.Logger) map[string]*gorpc.RPCFunc { + logger = logger.WithScope("GetRoutes") return map[string]*gorpc.RPCFunc{ // Transact BroadcastTx: gorpc.NewRPCFunc(func(tx txs.Wrapper) (*rpc.ResultBroadcastTx, error) { @@ -108,7 +107,7 @@ func GetRoutes(service *rpc.Service, logger logging_types.InfoTraceLogger) map[s keepAlive := wsCtx.TryWriteRPCResponse(rpctypes.NewRPCSuccessResponse( EventResponseID(wsCtx.Request.ID, eventID), resultEvent)) if !keepAlive { - logging.InfoMsg(logger, "dropping subscription because could not write to websocket", + logger.InfoMsg("dropping subscription because could not write to websocket", "subscription_id", subscriptionID, "event_id", eventID) } diff --git a/rpc/tm/server.go b/rpc/tm/server.go index e6ede8a34869c333c354e6a41768e78a2a20a9bd..4df1e3db5a9114ace449ddd5e6ba112788513aea 100644 --- a/rpc/tm/server.go +++ b/rpc/tm/server.go @@ -20,14 +20,14 @@ import ( "github.com/hyperledger/burrow/consensus/tendermint" "github.com/hyperledger/burrow/event" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/rpc" "github.com/tendermint/tendermint/rpc/lib/server" ) func StartServer(service *rpc.Service, pattern, listenAddress string, emitter event.Emitter, - logger logging_types.InfoTraceLogger) (net.Listener, error) { + logger *logging.Logger) (net.Listener, error) { logger = logger.With(structure.ComponentKey, "RPC_TM") routes := GetRoutes(service, logger) diff --git a/rpc/v0/json_service.go b/rpc/v0/json_service.go index 223e927daea4e5a83dfc469fb6a6a390fe20be11..cac693d2a0bd5960aed26ec0cd223e5687ef858f 100644 --- a/rpc/v0/json_service.go +++ b/rpc/v0/json_service.go @@ -21,7 +21,6 @@ import ( "github.com/gin-gonic/gin" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/rpc" "github.com/hyperledger/burrow/rpc/v0/server" ) @@ -85,17 +84,17 @@ type JSONService struct { service *rpc.Service eventSubs *Subscriptions defaultHandlers map[string]RequestHandlerFunc - logger logging_types.InfoTraceLogger + logger *logging.Logger } // Create a new JSON-RPC 2.0 service for burrow (tendermint). -func NewJSONService(codec rpc.Codec, service *rpc.Service, logger logging_types.InfoTraceLogger) server.HttpService { +func NewJSONService(codec rpc.Codec, service *rpc.Service, logger *logging.Logger) server.HttpService { tmhttps := &JSONService{ codec: codec, service: service, eventSubs: NewSubscriptions(service), - logger: logging.WithScope(logger, "NewJSONService"), + logger: logger.WithScope("NewJSONService"), } dhMap := GetMethods(codec, service, tmhttps.logger) @@ -132,7 +131,7 @@ func (js *JSONService) Process(r *http.Request, w http.ResponseWriter) { mName := req.Method if handler, ok := js.defaultHandlers[mName]; ok { - logging.TraceMsg(js.logger, "Request received", + js.logger.TraceMsg("Request received", "id", req.Id, "method", req.Method, "params", string(req.Params)) diff --git a/rpc/v0/methods.go b/rpc/v0/methods.go index e3925f8b496d16e8817b5c448f5da6d7461f9d18..ef994e04dc76916301f9428fdf6255948c7cf2c2 100644 --- a/rpc/v0/methods.go +++ b/rpc/v0/methods.go @@ -17,7 +17,7 @@ package v0 import ( acm "github.com/hyperledger/burrow/account" "github.com/hyperledger/burrow/execution" - logging_types "github.com/hyperledger/burrow/logging/types" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/rpc" "github.com/hyperledger/burrow/rpc/filters" "github.com/hyperledger/burrow/txs" @@ -63,7 +63,7 @@ const ( type RequestHandlerFunc func(request *rpc.RPCRequest, requester interface{}) (interface{}, int, error) // Private. Create a method name -> method handler map. -func GetMethods(codec rpc.Codec, service *rpc.Service, logger logging_types.InfoTraceLogger) map[string]RequestHandlerFunc { +func GetMethods(codec rpc.Codec, service *rpc.Service, logger *logging.Logger) map[string]RequestHandlerFunc { accountFilterFactory := filters.NewAccountFilterFactory() nameRegFilterFactory := filters.NewNameRegFilterFactory() diff --git a/rpc/v0/server/server.go b/rpc/v0/server/server.go index e79e717be00ee8aaab75fe4fd9bc4796af7c7317..9edc900f03d42fe5640e2edf8108dc1a11b2cfdc 100644 --- a/rpc/v0/server/server.go +++ b/rpc/v0/server/server.go @@ -24,7 +24,6 @@ import ( "github.com/gin-gonic/gin" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/tommy351/gin-cors" "gopkg.in/tylerb/graceful.v1" ) @@ -59,7 +58,7 @@ type ServeProcess struct { startListenChans []chan struct{} stopListenChans []chan struct{} srv *graceful.Server - logger logging_types.InfoTraceLogger + logger *logging.Logger } // Initializes all the servers and starts listening for connections. @@ -120,7 +119,7 @@ func (serveProcess *ServeProcess) Start() error { lst = l } serveProcess.srv = srv - logging.InfoMsg(serveProcess.logger, "Server started.", + serveProcess.logger.InfoMsg("Server started.", "chain_id", serveProcess.config.ChainId, "address", serveProcess.config.Bind.Address, "port", serveProcess.config.Bind.Port) @@ -139,14 +138,14 @@ func (serveProcess *ServeProcess) Start() error { // calls 'Stop' on the process. go func() { <-serveProcess.stopChan - logging.InfoMsg(serveProcess.logger, "Close signal sent to server.") + serveProcess.logger.InfoMsg("Close signal sent to server.") serveProcess.srv.Stop(killTime) }() // Listen to the servers stop event. It is triggered when // the server has been fully shut down. go func() { <-serveProcess.srv.StopChan() - logging.InfoMsg(serveProcess.logger, "Server stop event fired. Good bye.") + serveProcess.logger.InfoMsg("Server stop event fired. Good bye.") for _, c := range serveProcess.stopListenChans { c <- struct{}{} } @@ -198,7 +197,7 @@ func (serveProcess *ServeProcess) StopEventChannel() <-chan struct{} { } // Creates a new serve process. -func NewServeProcess(config *ServerConfig, logger logging_types.InfoTraceLogger, +func NewServeProcess(config *ServerConfig, logger *logging.Logger, servers ...Server) (*ServeProcess, error) { var scfg ServerConfig if config == nil { @@ -216,14 +215,14 @@ func NewServeProcess(config *ServerConfig, logger logging_types.InfoTraceLogger, startListenChans: startListeners, stopListenChans: stopListeners, srv: nil, - logger: logging.WithScope(logger, "ServeProcess"), + logger: logger.WithScope("ServeProcess"), } return sp, nil } // Used to enable log15 logging instead of the default Gin logging. -func logHandler(logger logging_types.InfoTraceLogger) gin.HandlerFunc { - logger = logging.WithScope(logger, "ginLogHandler") +func logHandler(logger *logging.Logger) gin.HandlerFunc { + logger = logger.WithScope("ginLogHandler") return func(c *gin.Context) { path := c.Request.URL.Path @@ -236,7 +235,7 @@ func logHandler(logger logging_types.InfoTraceLogger) gin.HandlerFunc { statusCode := c.Writer.Status() comment := c.Errors.String() - logger.Info("client_ip", clientIP, + logger.Info.Log("client_ip", clientIP, "status_code", statusCode, "method", method, "path", path, diff --git a/rpc/v0/server/websocket.go b/rpc/v0/server/websocket.go index b54e84ea827517a3781e6f6ed7a301db4ae868fe..cda4f7def80b26957378e6d789db9a1e4e735f9c 100644 --- a/rpc/v0/server/websocket.go +++ b/rpc/v0/server/websocket.go @@ -24,7 +24,6 @@ import ( "github.com/gin-gonic/gin" "github.com/gorilla/websocket" "github.com/hyperledger/burrow/logging" - logging_types "github.com/hyperledger/burrow/logging/types" ) // TODO too much fluff. Should probably phase gorilla out and move closer @@ -55,7 +54,7 @@ type WebSocketServer struct { sessionManager *SessionManager config *ServerConfig allOrigins bool - logger logging_types.InfoTraceLogger + logger *logging.Logger } // Create a new server. @@ -64,11 +63,11 @@ type WebSocketServer struct { // upgraded to websockets. Requesting a websocket connection will fail with a 503 if // the server is at capacity. func NewWebSocketServer(maxSessions uint16, service WebSocketService, - logger logging_types.InfoTraceLogger) *WebSocketServer { + logger *logging.Logger) *WebSocketServer { return &WebSocketServer{ maxSessions: maxSessions, sessionManager: NewSessionManager(maxSessions, service, logger), - logger: logging.WithScope(logger, "WebSocketServer"), + logger: logger.WithScope("WebSocketServer"), } } @@ -114,7 +113,7 @@ func (wsServer *WebSocketServer) handleFunc(c *gin.Context) { if uErr != nil { errMsg := "Failed to upgrade to websocket connection" http.Error(w, fmt.Sprintf("%s: %s", errMsg, uErr.Error()), 400) - logging.InfoMsg(wsServer.logger, errMsg, "error", uErr) + wsServer.logger.InfoMsg(errMsg, "error", uErr) return } @@ -123,12 +122,12 @@ func (wsServer *WebSocketServer) handleFunc(c *gin.Context) { if cErr != nil { errMsg := "Failed to establish websocket connection" http.Error(w, fmt.Sprintf("%s: %s", errMsg, cErr.Error()), 503) - logging.InfoMsg(wsServer.logger, errMsg, "error", cErr) + wsServer.logger.InfoMsg(errMsg, "error", cErr) return } // Start the connection. - logging.InfoMsg(wsServer.logger, "New websocket connection", + wsServer.logger.InfoMsg("New websocket connection", "session_id", session.id) session.Open() } @@ -152,13 +151,13 @@ type WSSession struct { service WebSocketService opened bool closed bool - logger logging_types.InfoTraceLogger + logger *logging.Logger } // Write a text message to the client. func (wsSession *WSSession) Write(msg []byte) error { if wsSession.closed { - logging.InfoMsg(wsSession.logger, "Attempting to write to closed session.") + wsSession.logger.InfoMsg("Attempting to write to closed session.") return fmt.Errorf("Session is closed") } wsSession.writeChan <- msg @@ -191,7 +190,7 @@ func (wsSession *WSSession) Close() { wsSession.closed = true wsSession.wsConn.Close() wsSession.sessionManager.removeSession(wsSession.id) - logging.InfoMsg(wsSession.logger, "Closing websocket connection.", + wsSession.logger.InfoMsg("Closing websocket connection.", "remaining_active_sessions", len(wsSession.sessionManager.activeSessions)) wsSession.sessionManager.notifyClosed(wsSession) } @@ -240,14 +239,14 @@ func (wsSession *WSSession) readPump() { // Read error. if err != nil { // Socket could have been gracefully closed, so not really an error. - logging.InfoMsg(wsSession.logger, + wsSession.logger.InfoMsg( "Socket closed. Removing.", "error", err) wsSession.writeCloseChan <- struct{}{} return } if msgType != websocket.TextMessage { - logging.InfoMsg(wsSession.logger, + wsSession.logger.InfoMsg( "Receiving non text-message from client, closing.") wsSession.writeCloseChan <- struct{}{} return @@ -292,7 +291,7 @@ func (wsSession *WSSession) writePump() { err := wsSession.wsConn.WriteMessage(websocket.TextMessage, msg) if err != nil { // Could be due to the socket being closed so not really an error. - logging.InfoMsg(wsSession.logger, + wsSession.logger.InfoMsg( "Writing to socket failed. Closing.") return } @@ -320,12 +319,12 @@ type SessionManager struct { service WebSocketService openEventChans []chan *WSSession closeEventChans []chan *WSSession - logger logging_types.InfoTraceLogger + logger *logging.Logger } // Create a new WebsocketManager. func NewSessionManager(maxSessions uint16, wss WebSocketService, - logger logging_types.InfoTraceLogger) *SessionManager { + logger *logging.Logger) *SessionManager { return &SessionManager{ maxSessions: maxSessions, activeSessions: make(map[uint]*WSSession), @@ -334,7 +333,7 @@ func NewSessionManager(maxSessions uint16, wss WebSocketService, service: wss, openEventChans: []chan *WSSession{}, closeEventChans: []chan *WSSession{}, - logger: logging.WithScope(logger, "SessionManager"), + logger: logger.WithScope("SessionManager"), } } @@ -417,8 +416,7 @@ func (sessionManager *SessionManager) createSession(wsConn *websocket.Conn) (*WS writeChan: make(chan []byte, maxMessageSize), writeCloseChan: make(chan struct{}), service: sessionManager.service, - logger: logging.WithScope(sessionManager.logger, "WSSession"). - With("session_id", newId), + logger: sessionManager.logger.WithScope("WSSession").With("session_id", newId), } sessionManager.activeSessions[conn.id] = conn return conn, nil diff --git a/rpc/v0/subscriptions_test.go b/rpc/v0/subscriptions_test.go index 45d2130a32a97804c7391a02cc5bdb2371b69de4..c3032dd6f861a394a2caa3388f51c2f89b83a7dd 100644 --- a/rpc/v0/subscriptions_test.go +++ b/rpc/v0/subscriptions_test.go @@ -22,7 +22,7 @@ import ( "time" "github.com/hyperledger/burrow/event" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/rpc" "github.com/stretchr/testify/assert" ) @@ -36,8 +36,8 @@ func TestSubReaping(t *testing.T) { reaperThreshold = 200 * time.Millisecond reaperTimeout = 100 * time.Millisecond - mee := event.NewEmitter(loggers.NewNoopInfoTraceLogger()) - eSubs := NewSubscriptions(rpc.NewSubscribableService(mee, loggers.NewNoopInfoTraceLogger())) + mee := event.NewEmitter(logging.NewNoopLogger()) + eSubs := NewSubscriptions(rpc.NewSubscribableService(mee, logging.NewNoopLogger())) doneChan := make(chan error) go func() { for i := 0; i < NUM_SUBS; i++ { @@ -80,8 +80,8 @@ func TestSubManualClose(t *testing.T) { reaperThreshold = 10000 * time.Millisecond reaperTimeout = 10000 * time.Millisecond - mee := event.NewEmitter(loggers.NewNoopInfoTraceLogger()) - eSubs := NewSubscriptions(rpc.NewSubscribableService(mee, loggers.NewNoopInfoTraceLogger())) + mee := event.NewEmitter(logging.NewNoopLogger()) + eSubs := NewSubscriptions(rpc.NewSubscribableService(mee, logging.NewNoopLogger())) doneChan := make(chan error) go func() { for i := 0; i < NUM_SUBS; i++ { @@ -128,8 +128,8 @@ func TestSubFlooding(t *testing.T) { reaperTimeout = 10000 * time.Millisecond // Crank it up. Now pressure is 10 times higher on each sub. mockInterval = 1 * time.Millisecond - mee := event.NewEmitter(loggers.NewNoopInfoTraceLogger()) - eSubs := NewSubscriptions(rpc.NewSubscribableService(mee, loggers.NewNoopInfoTraceLogger())) + mee := event.NewEmitter(logging.NewNoopLogger()) + eSubs := NewSubscriptions(rpc.NewSubscribableService(mee, logging.NewNoopLogger())) doneChan := make(chan error) go func() { for i := 0; i < NUM_SUBS; i++ { diff --git a/rpc/v0/websocket_service.go b/rpc/v0/websocket_service.go index 8c3c5e5d3138e9faf20eeed87e36eaaa085a19d4..ed75f1ce0cd0ce3bb22373468a6dcb59fbee2519 100644 --- a/rpc/v0/websocket_service.go +++ b/rpc/v0/websocket_service.go @@ -22,7 +22,6 @@ import ( "github.com/hyperledger/burrow/event" "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" - logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/rpc" "github.com/hyperledger/burrow/rpc/v0/server" ) @@ -32,15 +31,15 @@ type WebsocketService struct { codec rpc.Codec service *rpc.Service defaultHandlers map[string]RequestHandlerFunc - logger logging_types.InfoTraceLogger + logger *logging.Logger } // Create a new websocket service. -func NewWebsocketService(codec rpc.Codec, service *rpc.Service, logger logging_types.InfoTraceLogger) server.WebSocketService { +func NewWebsocketService(codec rpc.Codec, service *rpc.Service, logger *logging.Logger) server.WebSocketService { tmwss := &WebsocketService{ codec: codec, service: service, - logger: logging.WithScope(logger, "NewWebsocketService"), + logger: logger.WithScope("NewWebsocketService"), } dhMap := GetMethods(codec, service, tmwss.logger) // Events @@ -55,7 +54,7 @@ func (ws *WebsocketService) Process(msg []byte, session *server.WSSession) { defer func() { if r := recover(); r != nil { err := fmt.Errorf("panic in WebsocketService.Process(): %v", r) - logging.InfoMsg(ws.logger, "Panic in WebsocketService.Process()", structure.ErrorKey, err) + ws.logger.InfoMsg("Panic in WebsocketService.Process()", structure.ErrorKey, err) if !session.Closed() { ws.writeError(err.Error(), "", rpc.INTERNAL_ERROR, session) }