diff --git a/.gitignore b/.gitignore index d2482dea1fddf517c65e3d27012dfaffb6fcb809..32cda3d9e9fe1a96791e20a1b713a57dfacd6241 100644 --- a/.gitignore +++ b/.gitignore @@ -4,3 +4,4 @@ vendor *.swp debug .idea +.vscode diff --git a/client/cmd/transaction.go b/client/cmd/transaction.go index f2dc52e6eebd8821eed601b1b69df000df0a2b4c..e1cbfdd8f46354052a7a08d008c6beed70cc0c17 100644 --- a/client/cmd/transaction.go +++ b/client/cmd/transaction.go @@ -17,14 +17,12 @@ package commands import ( - "os" - "strings" +"strings" "github.com/spf13/cobra" - log "github.com/eris-ltd/eris-logger" - "github.com/eris-ltd/eris-db/client/methods" + "github.com/eris-ltd/eris-db/util" ) func buildTransactionCommand() *cobra.Command { @@ -180,26 +178,21 @@ func defaultAddress() string { func assertParameters(cmd *cobra.Command, args []string) { if clientDo.ChainidFlag == "" { - log.Fatal(`Please provide a chain id either through the flag --chain-id or environment variable $CHAIN_ID.`) - os.Exit(1) + util.Fatalf(`Please provide a chain id either through the flag --chain-id or environment variable $CHAIN_ID.`) } if !strings.HasPrefix(clientDo.NodeAddrFlag, "tcp://") && - !strings.HasPrefix(clientDo.NodeAddrFlag, "unix://") { + !strings.HasPrefix(clientDo.NodeAddrFlag, "unix://") { // TODO: [ben] go-rpc will deprecate reformatting; also it is bad practice to auto-correct for this; - log.Warn(`Please use fully formed listening address for the node, including the tcp:// or unix:// prefix.`) + // TODO: [Silas] I've made this fatal, but I'm inclined to define the default as tcp:// and normalise as with http + // below + util.Fatalf(`Please use fully formed listening address for the node, including the tcp:// or unix:// prefix.`) } if !strings.HasPrefix(clientDo.SignAddrFlag, "http://") { // NOTE: [ben] we preserve the auto-correction here as it is a simple http request-response to the key server. + // TODO: [Silas] we don't have logging here to log that we've done this. I'm inclined to either urls without a scheme + // and be quiet about it, or to make non-compliance fatal clientDo.SignAddrFlag = "http://" + clientDo.SignAddrFlag - log.WithFields(log.Fields{ - "signing address": clientDo.SignAddrFlag, - }).Warn(`Please use fully formed listening address for the key server; adding http:// prefix`) } - log.WithFields(log.Fields{ - "signing address": clientDo.SignAddrFlag, - "node address": clientDo.NodeAddrFlag, - "chain id": clientDo.ChainidFlag, - }).Debug("Asserted parameters") } diff --git a/client/methods/call.go b/client/methods/call.go index abe2fe91a28dc927bf5714e4caa63bc4d0e8c3fb..7378d6a1904b102ab27686910734ee6bd87f0838 100644 --- a/client/methods/call.go +++ b/client/methods/call.go @@ -17,31 +17,33 @@ package methods import ( - log "github.com/eris-ltd/eris-logger" - "github.com/eris-ltd/eris-db/client" "github.com/eris-ltd/eris-db/client/rpc" "github.com/eris-ltd/eris-db/definitions" "github.com/eris-ltd/eris-db/keys" + "github.com/eris-ltd/eris-db/util" ) func Call(do *definitions.ClientDo) { // construct two clients to call out to keys server and // blockchain node. - erisKeyClient := keys.NewErisKeyClient(do.SignAddrFlag) - erisNodeClient := client.NewErisNodeClient(do.NodeAddrFlag) + logger, err := loggerFromClientDo(do, "Call") + if err != nil { + util.Fatalf("Could not generate logging config from ClientDo: %s", err) + } + erisKeyClient := keys.NewErisKeyClient(do.SignAddrFlag, logger) + erisNodeClient := client.NewErisNodeClient(do.NodeAddrFlag, logger) // form the call transaction callTransaction, err := rpc.Call(erisNodeClient, erisKeyClient, do.PubkeyFlag, do.AddrFlag, do.ToFlag, do.AmtFlag, do.NonceFlag, do.GasFlag, do.FeeFlag, do.DataFlag) if err != nil { - log.Fatalf("Failed on forming Call Transaction: %s", err) - return + util.Fatalf("Failed on forming Call Transaction: %s", err) } // TODO: [ben] we carry over the sign bool, but always set it to true, // as we move away from and deprecate the api that allows sending unsigned // transactions and relying on (our) receiving node to sign it. - unpackSignAndBroadcast( - rpc.SignAndBroadcast(do.ChainidFlag, erisNodeClient, - erisKeyClient, callTransaction, true, do.BroadcastFlag, do.WaitFlag)) + txResult, err := rpc.SignAndBroadcast(do.ChainidFlag, erisNodeClient, erisKeyClient, + callTransaction, true, do.BroadcastFlag, do.WaitFlag) + unpackSignAndBroadcast(txResult, err, logger) } diff --git a/client/methods/helpers.go b/client/methods/helpers.go index 93c34ee51b25a2e227d08894f480f340ffb0d2a3..c357965b71e7cb78832fa6ca91c456c0119a18f3 100644 --- a/client/methods/helpers.go +++ b/client/methods/helpers.go @@ -17,33 +17,44 @@ package methods import ( - "fmt" - "os" - - log "github.com/eris-ltd/eris-logger" - "github.com/eris-ltd/eris-db/client/rpc" + "github.com/eris-ltd/eris-db/core" + "github.com/eris-ltd/eris-db/definitions" + "github.com/eris-ltd/eris-db/logging" + "github.com/eris-ltd/eris-db/logging/lifecycle" + "github.com/eris-ltd/eris-db/logging/loggers" + "github.com/eris-ltd/eris-db/util" ) -func unpackSignAndBroadcast(result *rpc.TxResult, err error) { +func unpackSignAndBroadcast(result *rpc.TxResult, err error, logger loggers.InfoTraceLogger) { if err != nil { - log.Fatalf("Failed on signing (and broadcasting) transaction: %s", err) - os.Exit(1) + util.Fatalf("Failed on signing (and broadcasting) transaction: %s", err) } if result == nil { // if we don't provide --sign or --broadcast return } - printResult := log.Fields{ - "transaction hash": fmt.Sprintf("%X", result.Hash), - } + + logger = logger.With("transaction hash", result.Hash) + if result.Address != nil { - printResult["Contract Address"] = fmt.Sprintf("%X", result.Address) + logger = logger.With("Contract Address", result.Address) } + if result.Return != nil { - printResult["Block Hash"] = fmt.Sprintf("%X", result.BlockHash) - printResult["Return Value"] = fmt.Sprintf("%X", result.Return) - printResult["Exception"] = fmt.Sprintf("%s", result.Exception) + logger = logger.With("Block Hash", result.BlockHash, + "Return Value", result.Return, + "Exception", result.Exception, + ) + } + + logging.InfoMsg(logger, "SignAndBroadcast result") +} + +func loggerFromClientDo(do *definitions.ClientDo, scope string) (loggers.InfoTraceLogger, error) { + lc, err := core.LoadLoggingConfigFromClientDo(do) + if err != nil { + return nil, err } - log.WithFields(printResult).Warn("Result") + return logging.WithScope(lifecycle.NewLoggerFromLoggingConfig(lc), scope), nil } diff --git a/client/methods/send.go b/client/methods/send.go index af393e029f454e43a953aeae759c45575fd8c6ec..900b92e52ba1d73e66b8a34242081604905989e7 100644 --- a/client/methods/send.go +++ b/client/methods/send.go @@ -17,30 +17,32 @@ package methods import ( - log "github.com/eris-ltd/eris-logger" - "github.com/eris-ltd/eris-db/client" "github.com/eris-ltd/eris-db/client/rpc" "github.com/eris-ltd/eris-db/definitions" "github.com/eris-ltd/eris-db/keys" + "github.com/eris-ltd/eris-db/util" ) func Send(do *definitions.ClientDo) { // construct two clients to call out to keys server and // blockchain node. - erisKeyClient := keys.NewErisKeyClient(do.SignAddrFlag) - erisNodeClient := client.NewErisNodeClient(do.NodeAddrFlag) + logger, err := loggerFromClientDo(do, "Send") + if err != nil { + util.Fatalf("Could not generate logging config from ClientDo: %s", err) + } + erisKeyClient := keys.NewErisKeyClient(do.SignAddrFlag, logger) + erisNodeClient := client.NewErisNodeClient(do.NodeAddrFlag, logger) // form the send transaction sendTransaction, err := rpc.Send(erisNodeClient, erisKeyClient, do.PubkeyFlag, do.AddrFlag, do.ToFlag, do.AmtFlag, do.NonceFlag) if err != nil { - log.Fatalf("Failed on forming Send Transaction: %s", err) - return + util.Fatalf("Failed on forming Send Transaction: %s", err) } // TODO: [ben] we carry over the sign bool, but always set it to true, // as we move away from and deprecate the api that allows sending unsigned // transactions and relying on (our) receiving node to sign it. - unpackSignAndBroadcast( - rpc.SignAndBroadcast(do.ChainidFlag, erisNodeClient, - erisKeyClient, sendTransaction, true, do.BroadcastFlag, do.WaitFlag)) + txResult, err := rpc.SignAndBroadcast(do.ChainidFlag, erisNodeClient, erisKeyClient, + sendTransaction, true, do.BroadcastFlag, do.WaitFlag) + unpackSignAndBroadcast(txResult, err, logger) } diff --git a/client/methods/status.go b/client/methods/status.go index ba2470e7645ba0759445daed1042211c8f184401..4346bc24be4002fe567ef27d268498650586b724 100644 --- a/client/methods/status.go +++ b/client/methods/status.go @@ -19,35 +19,35 @@ package methods import ( "fmt" - log "github.com/eris-ltd/eris-logger" - "github.com/eris-ltd/eris-db/client" "github.com/eris-ltd/eris-db/definitions" + "github.com/eris-ltd/eris-db/util" ) func Status(do *definitions.ClientDo) { - erisNodeClient := client.NewErisNodeClient(do.NodeAddrFlag) + logger, err := loggerFromClientDo(do, "Status") + if err != nil { + util.Fatalf("Could not generate logging config from ClientDo: %s", err) + } + erisNodeClient := client.NewErisNodeClient(do.NodeAddrFlag, logger) genesisHash, validatorPublicKey, latestBlockHash, latestBlockHeight, latestBlockTime, err := erisNodeClient.Status() if err != nil { - log.Errorf("Error requesting status from chain at (%s): %s", do.NodeAddrFlag, err) - return + util.Fatalf("Error requesting status from chain at (%s): %s", do.NodeAddrFlag, err) } chainName, chainId, genesisHashfromChainId, err := erisNodeClient.ChainId() if err != nil { - log.Errorf("Error requesting chainId from chain at (%s): %s", do.NodeAddrFlag, err) - return + util.Fatalf("Error requesting chainId from chain at (%s): %s", do.NodeAddrFlag, err) } - log.WithFields(log.Fields{ - "chain": do.NodeAddrFlag, - "genesisHash": fmt.Sprintf("%X", genesisHash), - "chainName": chainName, - "chainId": chainId, - "genesisHash from chainId": fmt.Sprintf("%X", genesisHashfromChainId), - "validator public key": fmt.Sprintf("%X", validatorPublicKey), - "latest block hash": fmt.Sprintf("%X", latestBlockHash), - "latest block height": latestBlockHeight, - "latest block time": latestBlockTime, - }).Info("status") + logger.Info("chain", do.NodeAddrFlag, + "genesisHash", fmt.Sprintf("%X", genesisHash), + "chainName", chainName, + "chainId", chainId, + "genesisHash from chainId", fmt.Sprintf("%X", genesisHashfromChainId), + "validator public key", fmt.Sprintf("%X", validatorPublicKey), + "latest block hash", fmt.Sprintf("%X", latestBlockHash), + "latest block height", latestBlockHeight, + "latest block time", latestBlockTime, + ) } diff --git a/client/mock/client_mock.go b/client/mock/client_mock.go index 12cdd76cf9b15f9575898224889a1528eb8a58b7..197818639d86bdfb8138a24682ca7eb56993c054 100644 --- a/client/mock/client_mock.go +++ b/client/mock/client_mock.go @@ -24,6 +24,7 @@ import ( consensus_types "github.com/eris-ltd/eris-db/consensus/types" core_types "github.com/eris-ltd/eris-db/core/types" "github.com/eris-ltd/eris-db/txs" + "github.com/eris-ltd/eris-db/logging/loggers" ) // NOTE [ben] Compiler check to ensure ErisMockClient successfully implements @@ -117,3 +118,7 @@ func (mock *MockNodeClient) GetName(name string) (owner []byte, data string, exp func (mock *MockNodeClient) ListValidators() (blockHeight int, bondedValidators, unbondingValidators []consensus_types.Validator, err error) { return 0, nil, nil, nil } + +func (mock *MockNodeClient) Logger() loggers.InfoTraceLogger { + return loggers.NewNoopInfoTraceLogger() +} diff --git a/client/node_client.go b/client/node_client.go index 34275c8b2deacc6a10d18d18a496297dd3b44430..302bb968767c1393a8a1f578a7e970dc720c4a29 100644 --- a/client/node_client.go +++ b/client/node_client.go @@ -21,15 +21,12 @@ import ( // "strings" "github.com/tendermint/go-rpc/client" - // Note [ben]: this is included to silence the logger from tendermint/go-rpc/client - // see func init() - tendermint_log "github.com/tendermint/log15" - - log "github.com/eris-ltd/eris-logger" acc "github.com/eris-ltd/eris-db/account" consensus_types "github.com/eris-ltd/eris-db/consensus/types" core_types "github.com/eris-ltd/eris-db/core/types" + "github.com/eris-ltd/eris-db/logging" + "github.com/eris-ltd/eris-db/logging/loggers" tendermint_client "github.com/eris-ltd/eris-db/rpc/tendermint/client" tendermint_types "github.com/eris-ltd/eris-db/rpc/tendermint/core/types" "github.com/eris-ltd/eris-db/txs" @@ -48,6 +45,9 @@ type NodeClient interface { DumpStorage(address []byte) (storage *core_types.Storage, err error) GetName(name string) (owner []byte, data string, expirationBlock int, err error) ListValidators() (blockHeight int, bondedValidators, unbondingValidators []consensus_types.Validator, err error) + + // Logging context for this NodeClient + Logger() loggers.InfoTraceLogger } type NodeWebsocketClient interface { @@ -58,37 +58,31 @@ type NodeWebsocketClient interface { Close() } -// NOTE [ben] Compiler check to ensure ErisNodeClient successfully implements +// NOTE [ben] Compiler check to ensure erisNodeClient successfully implements // eris-db/client.NodeClient -var _ NodeClient = (*ErisNodeClient)(nil) +var _ NodeClient = (*erisNodeClient)(nil) // Eris-Client is a simple struct exposing the client rpc methods - -type ErisNodeClient struct { +type erisNodeClient struct { broadcastRPC string + logger loggers.InfoTraceLogger } // ErisKeyClient.New returns a new eris-keys client for provided rpc location // Eris-keys connects over http request-responses -func NewErisNodeClient(rpcString string) *ErisNodeClient { - return &ErisNodeClient{ +func NewErisNodeClient(rpcString string, logger loggers.InfoTraceLogger) *erisNodeClient { + return &erisNodeClient{ broadcastRPC: rpcString, + logger: logging.WithScope(logger, "ErisNodeClient"), } } -// Note [Ben]: This is a hack to silence Tendermint logger from tendermint/go-rpc -// it needs to be initialised before go-rpc, hence it's placement here. -func init() { - h := tendermint_log.LvlFilterHandler(tendermint_log.LvlWarn, tendermint_log.StdoutHandler) - tendermint_log.Root().SetHandler(h) -} - //------------------------------------------------------------------------------------ // broadcast to blockchain node // NOTE: [ben] Eris Client first continues from tendermint rpc, but will have handshake to negotiate // protocol version for moving towards rpc/v1 -func (erisNodeClient *ErisNodeClient) Broadcast(tx txs.Tx) (*txs.Receipt, error) { +func (erisNodeClient *erisNodeClient) Broadcast(tx txs.Tx) (*txs.Receipt, error) { client := rpcclient.NewClientURI(erisNodeClient.broadcastRPC) receipt, err := tendermint_client.BroadcastTx(client, tx) if err != nil { @@ -97,7 +91,7 @@ func (erisNodeClient *ErisNodeClient) Broadcast(tx txs.Tx) (*txs.Receipt, error) return &receipt, nil } -func (erisNodeClient *ErisNodeClient) DeriveWebsocketClient() (nodeWsClient NodeWebsocketClient, err error) { +func (erisNodeClient *erisNodeClient) DeriveWebsocketClient() (nodeWsClient NodeWebsocketClient, err error) { var wsAddr string // TODO: clean up this inherited mess on dealing with the address prefixes. nodeAddr := erisNodeClient.broadcastRPC @@ -115,16 +109,17 @@ func (erisNodeClient *ErisNodeClient) DeriveWebsocketClient() (nodeWsClient Node // } // wsAddr = "ws://" + wsAddr wsAddr = nodeAddr - log.WithFields(log.Fields{ - "websocket address": wsAddr, - "endpoint": "/websocket", - }).Debug("Subscribing to websocket address") + logging.TraceMsg(erisNodeClient.logger, "Subscribing to websocket address", + "websocket address", wsAddr, + "endpoint", "/websocket", + ) wsClient := rpcclient.NewWSClient(wsAddr, "/websocket") if _, err = wsClient.Start(); err != nil { return nil, err } - derivedErisNodeWebsocketClient := &ErisNodeWebsocketClient{ + derivedErisNodeWebsocketClient := &erisNodeWebsocketClient{ tendermintWebsocket: wsClient, + logger: logging.WithScope(erisNodeClient.logger, "ErisNodeWebsocketClient"), } return derivedErisNodeWebsocketClient, nil } @@ -134,7 +129,7 @@ func (erisNodeClient *ErisNodeClient) DeriveWebsocketClient() (nodeWsClient Node // Status returns the ChainId (GenesisHash), validator's PublicKey, latest block hash // the block height and the latest block time. -func (erisNodeClient *ErisNodeClient) Status() (GenesisHash []byte, ValidatorPublicKey []byte, LatestBlockHash []byte, LatestBlockHeight int, LatestBlockTime int64, err error) { +func (erisNodeClient *erisNodeClient) Status() (GenesisHash []byte, ValidatorPublicKey []byte, LatestBlockHash []byte, LatestBlockHeight int, LatestBlockTime int64, err error) { client := rpcclient.NewClientJSONRPC(erisNodeClient.broadcastRPC) res, err := tendermint_client.Status(client) if err != nil { @@ -152,7 +147,7 @@ func (erisNodeClient *ErisNodeClient) Status() (GenesisHash []byte, ValidatorPub return } -func (erisNodeClient *ErisNodeClient) ChainId() (ChainName, ChainId string, GenesisHash []byte, err error) { +func (erisNodeClient *erisNodeClient) ChainId() (ChainName, ChainId string, GenesisHash []byte, err error) { client := rpcclient.NewClientJSONRPC(erisNodeClient.broadcastRPC) chainIdResult, err := tendermint_client.ChainId(client) if err != nil { @@ -170,7 +165,7 @@ func (erisNodeClient *ErisNodeClient) ChainId() (ChainName, ChainId string, Gene // QueryContract executes the contract code at address with the given data // NOTE: there is no check on the caller; -func (erisNodeClient *ErisNodeClient) QueryContract(callerAddress, calleeAddress, data []byte) (ret []byte, gasUsed int64, err error) { +func (erisNodeClient *erisNodeClient) QueryContract(callerAddress, calleeAddress, data []byte) (ret []byte, gasUsed int64, err error) { client := rpcclient.NewClientJSONRPC(erisNodeClient.broadcastRPC) callResult, err := tendermint_client.Call(client, callerAddress, calleeAddress, data) if err != nil { @@ -182,7 +177,7 @@ func (erisNodeClient *ErisNodeClient) QueryContract(callerAddress, calleeAddress } // QueryContractCode executes the contract code at address with the given data but with provided code -func (erisNodeClient *ErisNodeClient) QueryContractCode(address, code, data []byte) (ret []byte, gasUsed int64, err error) { +func (erisNodeClient *erisNodeClient) QueryContractCode(address, code, data []byte) (ret []byte, gasUsed int64, err error) { client := rpcclient.NewClientJSONRPC(erisNodeClient.broadcastRPC) // TODO: [ben] Call and CallCode have an inconsistent signature; it makes sense for both to only // have a single address that is the contract to query. @@ -196,7 +191,7 @@ func (erisNodeClient *ErisNodeClient) QueryContractCode(address, code, data []by } // GetAccount returns a copy of the account -func (erisNodeClient *ErisNodeClient) GetAccount(address []byte) (*acc.Account, error) { +func (erisNodeClient *erisNodeClient) GetAccount(address []byte) (*acc.Account, error) { client := rpcclient.NewClientJSONRPC(erisNodeClient.broadcastRPC) account, err := tendermint_client.GetAccount(client, address) if err != nil { @@ -213,7 +208,7 @@ func (erisNodeClient *ErisNodeClient) GetAccount(address []byte) (*acc.Account, } // DumpStorage returns the full storage for an account. -func (erisNodeClient *ErisNodeClient) DumpStorage(address []byte) (storage *core_types.Storage, err error) { +func (erisNodeClient *erisNodeClient) DumpStorage(address []byte) (storage *core_types.Storage, err error) { client := rpcclient.NewClientJSONRPC(erisNodeClient.broadcastRPC) resultStorage, err := tendermint_client.DumpStorage(client, address) if err != nil { @@ -231,7 +226,7 @@ func (erisNodeClient *ErisNodeClient) DumpStorage(address []byte) (storage *core //-------------------------------------------------------------------------------------------- // Name registry -func (erisNodeClient *ErisNodeClient) GetName(name string) (owner []byte, data string, expirationBlock int, err error) { +func (erisNodeClient *erisNodeClient) GetName(name string) (owner []byte, data string, expirationBlock int, err error) { client := rpcclient.NewClientJSONRPC(erisNodeClient.broadcastRPC) entryResult, err := tendermint_client.GetName(client, name) if err != nil { @@ -248,7 +243,7 @@ func (erisNodeClient *ErisNodeClient) GetName(name string) (owner []byte, data s //-------------------------------------------------------------------------------------------- -func (erisNodeClient *ErisNodeClient) ListValidators() (blockHeight int, +func (erisNodeClient *erisNodeClient) ListValidators() (blockHeight int, bondedValidators []consensus_types.Validator, unbondingValidators []consensus_types.Validator, err error) { client := rpcclient.NewClientJSONRPC(erisNodeClient.broadcastRPC) validatorsResult, err := tendermint_client.ListValidators(client) @@ -263,3 +258,7 @@ func (erisNodeClient *ErisNodeClient) ListValidators() (blockHeight int, unbondingValidators = validatorsResult.UnbondingValidators return } + +func (erisNodeClient *erisNodeClient) Logger() loggers.InfoTraceLogger { + return erisNodeClient.logger +} diff --git a/client/rpc/client.go b/client/rpc/client.go index b82527ef72e961c05ce876034ed6863f9088495b..77ed13b528cf10853ab790088a456e777ecf910c 100644 --- a/client/rpc/client.go +++ b/client/rpc/client.go @@ -21,11 +21,8 @@ import ( "fmt" "strconv" - log "github.com/eris-ltd/eris-logger" - ptypes "github.com/eris-ltd/eris-db/permission/types" - "github.com/eris-ltd/eris-db/account" "github.com/eris-ltd/eris-db/client" "github.com/eris-ltd/eris-db/keys" "github.com/eris-ltd/eris-db/txs" @@ -268,16 +265,14 @@ type TxResult struct { } // Preserve -func SignAndBroadcast(chainID string, nodeClient client.NodeClient, keyClient keys.KeyClient, tx txs.Tx, sign, broadcast, wait bool) (txResult *TxResult, err error) { +func SignAndBroadcast(chainID string, nodeClient client.NodeClient, keyClient keys.KeyClient, tx txs.Tx, sign, + broadcast, wait bool) (txResult *TxResult, err error) { var inputAddr []byte if sign { inputAddr, tx, err = signTx(keyClient, chainID, tx) if err != nil { return nil, err } - log.WithFields(log.Fields{ - "transaction": string(account.SignBytes(chainID, tx)), - }).Debug("Signed transaction") } if broadcast { @@ -296,23 +291,19 @@ func SignAndBroadcast(chainID string, nodeClient client.NodeClient, keyClient ke // if broadcast threw an error, just return return } - log.Debug("Waiting for transaction to be confirmed.") confirmation := <-confirmationChannel if confirmation.Error != nil { - log.Errorf("Encountered error waiting for event: %s\n", confirmation.Error) - err = confirmation.Error + err = fmt.Errorf("Encountered error waiting for event: %s", confirmation.Error) return } if confirmation.Exception != nil { - log.Errorf("Encountered Exception from chain: %s\n", confirmation.Exception) - err = confirmation.Exception + err = fmt.Errorf("Encountered Exception from chain: %s", confirmation.Exception) return } txResult.BlockHash = confirmation.BlockHash txResult.Exception = "" eventDataTx, ok := confirmation.Event.(*txs.EventDataTx) if !ok { - log.Errorf("Received wrong event type.") err = fmt.Errorf("Received wrong event type.") return } diff --git a/client/rpc/client_util.go b/client/rpc/client_util.go index 3e995a8acf9a9d28366d7b00aa85013457f733f5..df8ffe3f0fe77cd927014794878b6ada6806f421 100644 --- a/client/rpc/client_util.go +++ b/client/rpc/client_util.go @@ -21,13 +21,12 @@ import ( "fmt" "strconv" - log "github.com/eris-ltd/eris-logger" - "github.com/tendermint/go-crypto" acc "github.com/eris-ltd/eris-db/account" "github.com/eris-ltd/eris-db/client" "github.com/eris-ltd/eris-db/keys" + "github.com/eris-ltd/eris-db/logging" ptypes "github.com/eris-ltd/eris-db/permission/types" "github.com/eris-ltd/eris-db/txs" ) @@ -101,10 +100,10 @@ func checkCommon(nodeClient client.NodeClient, keyClient keys.KeyClient, pubkey, return } else if pubkey != "" { if addr != "" { - log.WithFields(log.Fields{ - "public key": pubkey, - "address": addr, - }).Info("you have specified both a pubkey and an address. the pubkey takes precedent") + logging.InfoMsg(nodeClient.Logger(), "Both a public key and an address have been specified. The public key takes precedent.", + "public_key", pubkey, + "address", addr, + ) } pubKeyBytes, err = hex.DecodeString(pubkey) if err != nil { @@ -151,10 +150,10 @@ func checkCommon(nodeClient client.NodeClient, keyClient keys.KeyClient, pubkey, return pub, amt, nonce, err2 } nonce = int64(account.Sequence) + 1 - log.WithFields(log.Fields{ - "nonce": nonce, - "account address": fmt.Sprintf("%X", addrBytes), - }).Debug("Fetch nonce from node") + logging.TraceMsg(nodeClient.Logger(), "Fetch nonce from node", + "nonce", nonce, + "account address", addrBytes, + ) } else { nonce, err = strconv.ParseInt(nonceS, 10, 64) if err != nil { diff --git a/client/websocket_client.go b/client/websocket_client.go index f58f8050dff4bf9c50addd8457b346b90f728d5b..429958aad169eab380d832f83a7b70e868ebde08 100644 --- a/client/websocket_client.go +++ b/client/websocket_client.go @@ -24,8 +24,8 @@ import ( "github.com/tendermint/go-rpc/client" "github.com/tendermint/go-wire" - log "github.com/eris-ltd/eris-logger" - + "github.com/eris-ltd/eris-db/logging" + "github.com/eris-ltd/eris-db/logging/loggers" ctypes "github.com/eris-ltd/eris-db/rpc/tendermint/core/types" "github.com/eris-ltd/eris-db/txs" ) @@ -41,29 +41,30 @@ type Confirmation struct { Error error } -// NOTE [ben] Compiler check to ensure ErisNodeClient successfully implements +// NOTE [ben] Compiler check to ensure erisNodeClient successfully implements // eris-db/client.NodeClient -var _ NodeWebsocketClient = (*ErisNodeWebsocketClient)(nil) +var _ NodeWebsocketClient = (*erisNodeWebsocketClient)(nil) -type ErisNodeWebsocketClient struct { +type erisNodeWebsocketClient struct { // TODO: assert no memory leak on closing with open websocket tendermintWebsocket *rpcclient.WSClient + logger loggers.InfoTraceLogger } // Subscribe to an eventid -func (erisNodeWebsocketClient *ErisNodeWebsocketClient) Subscribe(eventid string) error { +func (erisNodeWebsocketClient *erisNodeWebsocketClient) Subscribe(eventid string) error { // TODO we can in the background listen to the subscription id and remember it to ease unsubscribing later. return erisNodeWebsocketClient.tendermintWebsocket.Subscribe(eventid) } // Unsubscribe from an eventid -func (erisNodeWebsocketClient *ErisNodeWebsocketClient) Unsubscribe(subscriptionId string) error { +func (erisNodeWebsocketClient *erisNodeWebsocketClient) Unsubscribe(subscriptionId string) error { return erisNodeWebsocketClient.tendermintWebsocket.Unsubscribe(subscriptionId) } // Returns a channel that will receive a confirmation with a result or the exception that // has been confirmed; or an error is returned and the confirmation channel is nil. -func (erisNodeWebsocketClient *ErisNodeWebsocketClient) WaitForConfirmation(tx txs.Tx, chainId string, inputAddr []byte) (chan Confirmation, error) { +func (erisNodeWebsocketClient *erisNodeWebsocketClient) WaitForConfirmation(tx txs.Tx, chainId string, inputAddr []byte) (chan Confirmation, error) { // check no errors are reported on the websocket if err := erisNodeWebsocketClient.assertNoErrors(); err != nil { return nil, err @@ -88,7 +89,8 @@ func (erisNodeWebsocketClient *ErisNodeWebsocketClient) WaitForConfirmation(tx t result := new(ctypes.ErisDBResult) if wire.ReadJSONPtr(result, resultBytes, &err); err != nil { // keep calm and carry on - log.Errorf("[eris-client] Failed to unmarshal json bytes for websocket event: %s", err) + logging.InfoMsg(erisNodeWebsocketClient.logger, "Failed to unmarshal json bytes for websocket event", + "error", err) continue } @@ -97,36 +99,41 @@ func (erisNodeWebsocketClient *ErisNodeWebsocketClient) WaitForConfirmation(tx t // Received confirmation of subscription to event streams // TODO: collect subscription IDs, push into channel and on completion // unsubscribe - log.Infof("[eris-client] received confirmation for event (%s) with subscription id (%s).", - subscription.Event, subscription.SubscriptionId) + logging.InfoMsg(erisNodeWebsocketClient.logger, "Received confirmation for event", + "event", subscription.Event, + "subscription_id", subscription.SubscriptionId) continue } event, ok := (*result).(*ctypes.ResultEvent) if !ok { // keep calm and carry on - log.Warnf("[eris-client] Failed to cast to ResultEvent for websocket event: %s", *result) + logging.InfoMsg(erisNodeWebsocketClient.logger, "Failed to cast to ResultEvent for websocket event", + "event", event.Event) continue } blockData, ok := event.Data.(txs.EventDataNewBlock) if ok { latestBlockHash = blockData.Block.Hash() - log.WithFields(log.Fields{ - "new block": blockData.Block, - "latest hash": latestBlockHash, - }).Debug("Registered new block") + logging.TraceMsg(erisNodeWebsocketClient.logger, "Registered new block", + "block", blockData.Block, + "latest_block_hash", latestBlockHash, + ) continue } // we don't accept events unless they came after a new block (ie. in) if latestBlockHash == nil { - log.Infof("[eris-client] no first block has been registered, so ignoring event: %s", event.Event) + logging.InfoMsg(erisNodeWebsocketClient.logger, "First block has not been registered so ignoring event", + "event", event.Event) continue } if event.Event != eid { - log.Warnf("[eris-client] received unsolicited event! Got %s, expected %s\n", event.Event, eid) + logging.InfoMsg(erisNodeWebsocketClient.logger, "Received unsolicited event", + "event_received", event.Event, + "event_expected", eid) continue } @@ -143,10 +150,9 @@ func (erisNodeWebsocketClient *ErisNodeWebsocketClient) WaitForConfirmation(tx t } if !bytes.Equal(txs.TxHash(chainId, data.Tx), txs.TxHash(chainId, tx)) { - log.WithFields(log.Fields{ + logging.TraceMsg(erisNodeWebsocketClient.logger, "Received different event", // TODO: consider re-implementing TxID again, or other more clear debug - "received transaction event": txs.TxHash(chainId, data.Tx), - }).Debug("Received different event") + "received transaction event", txs.TxHash(chainId, data.Tx)) continue } @@ -188,13 +194,13 @@ func (erisNodeWebsocketClient *ErisNodeWebsocketClient) WaitForConfirmation(tx t return confirmationChannel, nil } -func (erisNodeWebsocketClient *ErisNodeWebsocketClient) Close() { +func (erisNodeWebsocketClient *erisNodeWebsocketClient) Close() { if erisNodeWebsocketClient.tendermintWebsocket != nil { erisNodeWebsocketClient.tendermintWebsocket.Stop() } } -func (erisNodeWebsocketClient *ErisNodeWebsocketClient) assertNoErrors() error { +func (erisNodeWebsocketClient *erisNodeWebsocketClient) assertNoErrors() error { if erisNodeWebsocketClient.tendermintWebsocket != nil { select { case err := <-erisNodeWebsocketClient.tendermintWebsocket.ErrorsCh: diff --git a/cmd/serve.go b/cmd/serve.go index 49bc665be308c0a5bbe23deaeba3e7d9f9c97730..29319b1fd815498dae5ac82659211afacc8280c8 100644 --- a/cmd/serve.go +++ b/cmd/serve.go @@ -111,7 +111,7 @@ func NewCoreFromDo(do *definitions.Do) (*core.Core, error) { } // Create a root logger to pass through to dependencies - logger := logging.WithScope(lifecycle.NewLoggerFromLoggingConfig(*loggerConfig), "Serve") + logger := logging.WithScope(lifecycle.NewLoggerFromLoggingConfig(loggerConfig), "Serve") // Capture all logging from tendermint/tendermint and tendermint/go-* // dependencies lifecycle.CaptureTendermintLog15Output(logger) diff --git a/event/event_cache.go b/event/event_cache.go index 3f230ae599fb99e96fa7726b37130409d11ed993..08db30116ea20225cb27875fb79fd103b0165070 100644 --- a/event/event_cache.go +++ b/event/event_cache.go @@ -70,7 +70,7 @@ func reap(es *EventSubscriptions) { defer es.mtx.Unlock() for id, sub := range es.subs { if time.Since(sub.ts) > reaperThreshold { - // Seems like Go is ok with evts.. + // Seems like Go is ok with this.. delete(es.subs, id) es.eventEmitter.Unsubscribe(id) } @@ -116,7 +116,7 @@ func (this *EventSubscriptions) Poll(subId string) ([]interface{}, error) { func (this *EventSubscriptions) Remove(subId string) error { this.mtx.Lock() defer this.mtx.Unlock() - // TODO Check evts. + // TODO Check this. _, ok := this.subs[subId] if !ok { return fmt.Errorf("Subscription not active. ID: " + subId) diff --git a/event/event_cache_test.go b/event/event_cache_test.go index 0ac32fb23ee6d4af3d320ba16169b807bd1fa6f0..35ce6d7ed0cbdc45c3b838d831b993fddfbbb42b 100644 --- a/event/event_cache_test.go +++ b/event/event_cache_test.go @@ -131,7 +131,7 @@ func TestSubReaping(t *testing.T) { // Test that event subscriptions can be added and removed manually. func TestSubManualClose(t *testing.T) { NUM_SUBS := 100 - // Keep the reaper out of evts. + // Keep the reaper out of this. reaperThreshold = 10000 * time.Millisecond reaperTimeout = 10000 * time.Millisecond @@ -178,7 +178,7 @@ func TestSubManualClose(t *testing.T) { // Test that the system doesn't fail under high pressure. func TestSubFlooding(t *testing.T) { NUM_SUBS := 100 - // Keep the reaper out of evts. + // Keep the reaper out of this. reaperThreshold = 10000 * time.Millisecond reaperTimeout = 10000 * time.Millisecond // Crank it up. Now pressure is 10 times higher on each sub. diff --git a/event/events.go b/event/events.go index 87647623f1fa73476ac175f29612afa8e7ffb695..ec790a9ed8b1d120a46ecf1642bec840756fcbdd 100644 --- a/event/events.go +++ b/event/events.go @@ -30,13 +30,13 @@ import ( tm_types "github.com/tendermint/tendermint/types" ) -// TODO: [Silas] evts is a compatibility layer between our event types and +// TODO: [Silas] this is a compatibility layer between our event types and // TODO: go-events. Our ultimate plan is to replace go-events with our own pub-sub // TODO: code that will better allow us to manage and multiplex events from different // TODO: subsystems // Oh for a sum type -// We are using evts as a marker interface for the +// We are using this as a marker interface for the type anyEventData interface{} type EventEmitter interface { @@ -144,7 +144,7 @@ func GenerateSubId() (string, error) { } func mapToOurEventData(eventData anyEventData) (txs.EventData, error) { - // TODO: [Silas] avoid evts with a better event pub-sub system of our own + // TODO: [Silas] avoid this with a better event pub-sub system of our own // TODO: that maybe involves a registry of events switch eventData := eventData.(type) { case txs.EventData: diff --git a/keys/key_client.go b/keys/key_client.go index e841f50abd71f68ce4bdd9fc838acf764e5f3b1f..f10093b831bf9e78c09c41c1fe3e6d2831d5d352 100644 --- a/keys/key_client.go +++ b/keys/key_client.go @@ -19,6 +19,8 @@ package keys import ( "encoding/hex" "fmt" + "github.com/eris-ltd/eris-db/logging/loggers" + "github.com/eris-ltd/eris-db/logging" ) type KeyClient interface { @@ -29,31 +31,33 @@ type KeyClient interface { PublicKey(address []byte) (publicKey []byte, err error) } -// NOTE [ben] Compiler check to ensure ErisKeyClient successfully implements +// NOTE [ben] Compiler check to ensure erisKeyClient successfully implements // eris-db/keys.KeyClient -var _ KeyClient = (*ErisKeyClient)(nil) +var _ KeyClient = (*erisKeyClient)(nil) -type ErisKeyClient struct { +type erisKeyClient struct { rpcString string + logger loggers.InfoTraceLogger } -// ErisKeyClient.New returns a new eris-keys client for provided rpc location +// erisKeyClient.New returns a new eris-keys client for provided rpc location // Eris-keys connects over http request-responses -func NewErisKeyClient(rpcString string) *ErisKeyClient { - return &ErisKeyClient{ +func NewErisKeyClient(rpcString string, logger loggers.InfoTraceLogger) *erisKeyClient { + return &erisKeyClient{ rpcString: rpcString, + logger: logging.WithScope(logger, "ErisKeysClient"), } } // Eris-keys client Sign requests the signature from ErisKeysClient over rpc for the given // bytes to be signed and the address to sign them with. -func (erisKeys *ErisKeyClient) Sign(signBytesString string, signAddress []byte) (signature []byte, err error) { +func (erisKeys *erisKeyClient) Sign(signBytesString string, signAddress []byte) (signature []byte, err error) { args := map[string]string{ "msg": signBytesString, "hash": signBytesString, // TODO:[ben] backwards compatibility "addr": fmt.Sprintf("%X", signAddress), } - sigS, err := RequestResponse(erisKeys.rpcString, "sign", args) + sigS, err := RequestResponse(erisKeys.rpcString, "sign", args, erisKeys.logger) if err != nil { return } @@ -66,11 +70,11 @@ func (erisKeys *ErisKeyClient) Sign(signBytesString string, signAddress []byte) // Eris-keys client PublicKey requests the public key associated with an address from // the eris-keys server. -func (erisKeys *ErisKeyClient) PublicKey(address []byte) (publicKey []byte, err error) { +func (erisKeys *erisKeyClient) PublicKey(address []byte) (publicKey []byte, err error) { args := map[string]string{ "addr": fmt.Sprintf("%X", address), } - pubS, err := RequestResponse(erisKeys.rpcString, "pub", args) + pubS, err := RequestResponse(erisKeys.rpcString, "pub", args, erisKeys.logger) if err != nil { return } diff --git a/keys/key_client_util.go b/keys/key_client_util.go index e9e5f4783d51ce2df4e590cea008535ed5f1a4d7..5fd1cbce41f55d1348584aeb29d55dacf7fcc1d8 100644 --- a/keys/key_client_util.go +++ b/keys/key_client_util.go @@ -26,7 +26,8 @@ import ( "io/ioutil" "net/http" - log "github.com/eris-ltd/eris-logger" + "github.com/eris-ltd/eris-db/logging" + "github.com/eris-ltd/eris-db/logging/loggers" ) // Eris-Keys server connects over http request-response structures @@ -36,17 +37,17 @@ type HTTPResponse struct { Error string } -func RequestResponse(addr, method string, args map[string]string) (string, error) { - b, err := json.Marshal(args) +func RequestResponse(addr, method string, args map[string]string, logger loggers.InfoTraceLogger) (string, error) { + body, err := json.Marshal(args) if err != nil { return "", err } endpoint := fmt.Sprintf("%s/%s", addr, method) - log.WithFields(log.Fields{ - "key server endpoint": endpoint, - "request body": string(b), - }).Debugf("Eris-client: Sending request body to key server") - req, err := http.NewRequest("POST", endpoint, bytes.NewBuffer(b)) + logging.TraceMsg(logger, "Sending request to key server", + "key_server_endpoint", endpoint, + "request_body", string(body), + ) + req, err := http.NewRequest("POST", endpoint, bytes.NewBuffer(body)) if err != nil { return "", err } @@ -58,11 +59,11 @@ func RequestResponse(addr, method string, args map[string]string) (string, error if errS != "" { return "", fmt.Errorf("Error (string) calling eris-keys at %s: %s", endpoint, errS) } - log.WithFields(log.Fields{ - "endpoint": endpoint, - "request body": string(b), - "response": res, - }).Debugf("Received response from key server") + logging.TraceMsg(logger, "Received response from key server", + "endpoint", endpoint, + "request body", string(body), + "response", res, + ) return res, nil } diff --git a/logging/lifecycle/lifecycle.go b/logging/lifecycle/lifecycle.go index 026c07025942d27e6f8da19f52d4ed57eebf1d26..7a2eea701dc2e29bf52d6961302df19df796cf2a 100644 --- a/logging/lifecycle/lifecycle.go +++ b/logging/lifecycle/lifecycle.go @@ -1,7 +1,6 @@ package lifecycle // No package in ./logging/... should depend on lifecycle - import ( "os" @@ -16,8 +15,11 @@ import ( "time" ) +// Lifecycle provides a canonical source for eris loggers. Components should use the functions here +// to set up their root logger and capture any other logging output. + // Obtain a logger from a LoggingConfig -func NewLoggerFromLoggingConfig(LoggingConfig logging.LoggingConfig) loggers.InfoTraceLogger { +func NewLoggerFromLoggingConfig(LoggingConfig *logging.LoggingConfig) loggers.InfoTraceLogger { infoLogger := kitlog.NewLogfmtLogger(os.Stderr) traceLogger := kitlog.NewLogfmtLogger(os.Stderr) return logging.WithMetadata(loggers.NewInfoTraceLogger(infoLogger, traceLogger)) @@ -29,8 +31,12 @@ func NewStdErrLogger() loggers.InfoTraceLogger { return NewLogger(logger, logger) } +// Provided a standard eris logger that outputs to the supplied underlying info and trace +// loggers func NewLogger(infoLogger, traceLogger kitlog.Logger) loggers.InfoTraceLogger { - infoTraceLogger := loggers.NewInfoTraceLogger(infoLogger, traceLogger) + infoTraceLogger := loggers.NewInfoTraceLogger( + loggers.ErisFormatLogger(infoLogger), + loggers.ErisFormatLogger(traceLogger)) // Create a random ID based on start time uuid, _ := simpleuuid.NewTime(time.Now()) var runId string @@ -43,10 +49,10 @@ func NewLogger(infoLogger, traceLogger kitlog.Logger) loggers.InfoTraceLogger { func CaptureTendermintLog15Output(infoTraceLogger loggers.InfoTraceLogger) { tmLog15.Root().SetHandler( tmLog15adapter.InfoTraceLoggerAsLog15Handler(infoTraceLogger. - With(structure.ComponentKey, "tendermint_log15"))) + With(structure.CapturedLoggingSourceKey, "tendermint_log15"))) } func CaptureStdlibLogOutput(infoTraceLogger loggers.InfoTraceLogger) { stdlib.CaptureRootLogger(infoTraceLogger. - With(structure.ComponentKey, "stdlib_log")) + With(structure.CapturedLoggingSourceKey, "stdlib_log")) } diff --git a/logging/loggers/eris_format_logger.go b/logging/loggers/eris_format_logger.go new file mode 100644 index 0000000000000000000000000000000000000000..59f18acec3d1bb96768cef8a00fb272ae6cf4357 --- /dev/null +++ b/logging/loggers/eris_format_logger.go @@ -0,0 +1,38 @@ +package loggers + +import ( + "fmt" + + "github.com/eris-ltd/eris-db/logging/structure" + kitlog "github.com/go-kit/kit/log" +) + +// Logger that implements some formatting conventions for eris-db and eris-client +// This is intended for applying consistent value formatting before the final 'output' logger; +// we should avoid prematurely formatting values here if it is useful to let the output logger +// decide how it wants to display values. Ideal candidates for 'early' formatting here are types that +// we control and generic output loggers are unlikely to know about. +type erisFormatLogger struct { + logger kitlog.Logger +} + +var _ kitlog.Logger = &erisFormatLogger{} + +func (efl *erisFormatLogger) Log(keyvals ...interface{}) error { + return efl.logger.Log(structure.MapKeyValues(keyvals, erisFormatKeyValueMapper)...) +} + +func erisFormatKeyValueMapper(key, value interface{}) (interface{}, interface{}) { + switch key { + default: + switch v := value.(type) { + case []byte: + return key, fmt.Sprintf("%X", v) + } + } + return key, value +} + +func ErisFormatLogger(logger kitlog.Logger) *erisFormatLogger { + return &erisFormatLogger{logger: logger} +} diff --git a/logging/structure/structure.go b/logging/structure/structure.go index 8a81777a2bf3105645f03933724b27d01136b850..96aaa3f54bebb7dbac007b63a630b8ed787853a8 100644 --- a/logging/structure/structure.go +++ b/logging/structure/structure.go @@ -17,6 +17,8 @@ const ( ChannelKey = "channel" // Log message (string) MessageKey = "message" + // Captured logging source (like tendermint_log15, stdlib_log) + CapturedLoggingSourceKey = "captured_logging_source" // Top-level component (choose one) name ComponentKey = "component" // Vector-valued scope @@ -131,3 +133,14 @@ func KeyFromValue(val interface{}) string { return reflect.TypeOf(val).Name() } } + +// Maps key values pairs with a function (key, value) -> (new key, new value) +func MapKeyValues(keyvals []interface{}, fn func(interface{}, interface{}) (interface{}, interface{})) []interface{} { + mappedKeyvals := make([]interface{}, len(keyvals)) + for i := 0; i < 2*(len(keyvals)/2); i += 2 { + key := keyvals[i] + val := keyvals[i+1] + mappedKeyvals[i], mappedKeyvals[i+1]= fn(key, val) + } + return mappedKeyvals +} \ No newline at end of file