diff --git a/client/methods/helpers.go b/client/methods/helpers.go index 15b0a4fee09ac67b9f63d5c6e9a3d844de154cac..2e8bc6fcaddb11eac66c55f8992039a9beec8feb 100644 --- a/client/methods/helpers.go +++ b/client/methods/helpers.go @@ -20,10 +20,10 @@ import ( "github.com/hyperledger/burrow/definitions" "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/lifecycle" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" ) -func unpackSignAndBroadcast(result *rpc.TxResult, logger loggers.InfoTraceLogger) { +func unpackSignAndBroadcast(result *rpc.TxResult, logger logging_types.InfoTraceLogger) { if result == nil { // if we don't provide --sign or --broadcast return @@ -45,10 +45,17 @@ func unpackSignAndBroadcast(result *rpc.TxResult, logger loggers.InfoTraceLogger logging.InfoMsg(logger, "SignAndBroadcast result") } -func loggerFromClientDo(do *definitions.ClientDo, scope string) (loggers.InfoTraceLogger, error) { +func loggerFromClientDo(do *definitions.ClientDo, scope string) (logging_types.InfoTraceLogger, error) { lc, err := core.LoadLoggingConfigFromClientDo(do) if err != nil { return nil, err } - return logging.WithScope(lifecycle.NewLoggerFromLoggingConfig(lc), scope), nil + logger, err := lifecycle.NewLoggerFromLoggingConfig(lc) + if err != nil { + return nil, err + } + logger = logging.WithScope(logger, scope) + lifecycle.CaptureStdlibLogOutput(logger) + lifecycle.CaptureTendermintLog15Output(logger) + return logger, nil } diff --git a/client/mock/client_mock.go b/client/mock/client_mock.go index 08ba2641c625a6925d41d3981e2b65148c7dd422..0460d63894f4d13d51ee3c26b1e1ee10f412799e 100644 --- a/client/mock/client_mock.go +++ b/client/mock/client_mock.go @@ -22,6 +22,7 @@ import ( consensus_types "github.com/hyperledger/burrow/consensus/types" core_types "github.com/hyperledger/burrow/core/types" "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/txs" ) @@ -115,6 +116,6 @@ func (mock *MockNodeClient) ListValidators() (blockHeight int, bondedValidators, return 0, nil, nil, nil } -func (mock *MockNodeClient) Logger() loggers.InfoTraceLogger { +func (mock *MockNodeClient) Logger() logging_types.InfoTraceLogger { return loggers.NewNoopInfoTraceLogger() } diff --git a/client/node_client.go b/client/node_client.go index 775e29fda8eeb33ae83868cf22436166e94b6de7..eb03fd77fb22300419bba16696e8e06f96e17c13 100644 --- a/client/node_client.go +++ b/client/node_client.go @@ -24,7 +24,7 @@ import ( consensus_types "github.com/hyperledger/burrow/consensus/types" core_types "github.com/hyperledger/burrow/core/types" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" tendermint_client "github.com/hyperledger/burrow/rpc/tendermint/client" tendermint_types "github.com/hyperledger/burrow/rpc/tendermint/core/types" "github.com/hyperledger/burrow/txs" @@ -46,7 +46,7 @@ type NodeClient interface { ListValidators() (blockHeight int, bondedValidators, unbondingValidators []consensus_types.Validator, err error) // Logging context for this NodeClient - Logger() loggers.InfoTraceLogger + Logger() logging_types.InfoTraceLogger } type NodeWebsocketClient interface { @@ -64,12 +64,12 @@ var _ NodeClient = (*burrowNodeClient)(nil) // burrow-client is a simple struct exposing the client rpc methods type burrowNodeClient struct { broadcastRPC string - logger loggers.InfoTraceLogger + logger logging_types.InfoTraceLogger } // BurrowKeyClient.New returns a new monax-keys client for provided rpc location // Monax-keys connects over http request-responses -func NewBurrowNodeClient(rpcString string, logger loggers.InfoTraceLogger) *burrowNodeClient { +func NewBurrowNodeClient(rpcString string, logger logging_types.InfoTraceLogger) *burrowNodeClient { return &burrowNodeClient{ broadcastRPC: rpcString, logger: logging.WithScope(logger, "BurrowNodeClient"), @@ -263,6 +263,6 @@ func (burrowNodeClient *burrowNodeClient) ListValidators() (blockHeight int, return } -func (burrowNodeClient *burrowNodeClient) Logger() loggers.InfoTraceLogger { +func (burrowNodeClient *burrowNodeClient) Logger() logging_types.InfoTraceLogger { return burrowNodeClient.logger } diff --git a/client/websocket_client.go b/client/websocket_client.go index 2c84ecba54dcc629d1439e8359bae948d60ebb08..9e6484265e646d72a4d345025c30d70260dc2657 100644 --- a/client/websocket_client.go +++ b/client/websocket_client.go @@ -19,11 +19,11 @@ import ( "fmt" "time" + logging_types "github.com/hyperledger/burrow/logging/types" "github.com/tendermint/go-rpc/client" "github.com/tendermint/go-wire" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" ctypes "github.com/hyperledger/burrow/rpc/tendermint/core/types" "github.com/hyperledger/burrow/txs" ) @@ -46,7 +46,7 @@ var _ NodeWebsocketClient = (*burrowNodeWebsocketClient)(nil) type burrowNodeWebsocketClient struct { // TODO: assert no memory leak on closing with open websocket tendermintWebsocket *rpcclient.WSClient - logger loggers.InfoTraceLogger + logger logging_types.InfoTraceLogger } // Subscribe to an eventid diff --git a/cmd/serve.go b/cmd/serve.go index a0c65d4b56948b5ba632c20d683cc11878c7e5d0..c4373db68d71c555667b91aa3ea38a78890421a6 100644 --- a/cmd/serve.go +++ b/cmd/serve.go @@ -109,8 +109,12 @@ func NewCoreFromDo(do *definitions.Do) (*core.Core, error) { return nil, fmt.Errorf("Failed to load logging config: %s", err) } + logger, err := lifecycle.NewLoggerFromLoggingConfig(loggerConfig) + if err != nil { + return nil, fmt.Errorf("Failed to build logger from logging config: %s", err) + } // Create a root logger to pass through to dependencies - logger := logging.WithScope(lifecycle.NewLoggerFromLoggingConfig(loggerConfig), "Serve") + logger = logging.WithScope(logger, "Serve") // Capture all logging from tendermint/tendermint and tendermint/go-* // dependencies lifecycle.CaptureTendermintLog15Output(logger) diff --git a/config/config.go b/config/config.go index fb6f1260059d04013d9d02786fa5346567c192eb..8d002743fc0c474c50d2c655f2bee568ec7bbb03 100644 --- a/config/config.go +++ b/config/config.go @@ -18,6 +18,8 @@ import ( "bytes" "fmt" "text/template" + + lconfig "github.com/hyperledger/burrow/logging/config" ) type ConfigServiceGeneral struct { @@ -170,6 +172,9 @@ func GetConfigurationFileBytes(chainId, moniker, seeds string, chainImageName st // write static section burrowmint buffer.WriteString(sectionBurrowMint) + buffer.WriteString(sectionLoggingHeader) + buffer.WriteString(lconfig.DefaultNodeLoggingConfig().RootTOMLString()) + return buffer.Bytes(), nil } diff --git a/config/templates.go b/config/templates.go index c53c43f0ce00a0b0bf50d21b75c8cf25c2202baa..fc3a80e55c3fda36735adf9c80c9df30c7591ad3 100644 --- a/config/templates.go +++ b/config/templates.go @@ -162,11 +162,6 @@ const sectionServers = `[servers] rpc_local_address = "0.0.0.0:46657" endpoint = "/websocket" - [servers.logging] - console_log_level = "info" - file_log_level = "warn" - log_file = "" - ` const separatorModules = ` @@ -296,3 +291,17 @@ db_backend = "leveldb" tendermint_host = "0.0.0.0:46657" ` + +const sectionLoggingHeader = ` +################################################################################ +## +## System-wide logging configuration +## +## Log messages are sent to one of two 'channels': info or trace +## +## They are delivered on two independent streams: 'info' or 'info and trace'. +## Each of these streams has a root +## +################################################################################ + +` diff --git a/config/viper.go b/config/viper.go index cefd2f2a8f5ec3b0abc89dd83f0dafa0f6b60951..1b4c96b6caae6d840c26b2667ee499a1be1b643e 100644 --- a/config/viper.go +++ b/config/viper.go @@ -23,7 +23,7 @@ import ( // Safely get the subtree from a viper config, returning an error if it could not // be obtained for any reason. func ViperSubConfig(conf *viper.Viper, configSubtreePath string) (subConfig *viper.Viper, err error) { - // Viper internally panics if `moduleName` contains an unallowed + // Viper internally panics if `moduleName` contains an disallowed // character (eg, a dash). defer func() { if r := recover(); r != nil { diff --git a/consensus/tendermint/tendermint.go b/consensus/tendermint/tendermint.go index c11a7c508cd1c1817eefc99652d1323df2b21bf4..7029fe0406909ed72941a0027f46c1683ee27c8f 100644 --- a/consensus/tendermint/tendermint.go +++ b/consensus/tendermint/tendermint.go @@ -35,7 +35,7 @@ import ( blockchain_types "github.com/hyperledger/burrow/blockchain/types" consensus_types "github.com/hyperledger/burrow/consensus/types" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/txs" "github.com/tendermint/go-wire" ) @@ -44,7 +44,7 @@ type Tendermint struct { tmintNode *node.Node tmintConfig *TendermintConfig chainId string - logger loggers.InfoTraceLogger + logger logging_types.InfoTraceLogger } // Compiler checks to ensure Tendermint successfully implements @@ -54,7 +54,7 @@ var _ blockchain_types.Blockchain = (*Tendermint)(nil) func NewTendermint(moduleConfig *config.ModuleConfig, application manager_types.Application, - logger loggers.InfoTraceLogger) (*Tendermint, error) { + logger logging_types.InfoTraceLogger) (*Tendermint, error) { // re-assert proper configuration for module if moduleConfig.Version != GetTendermintVersion().GetMinorVersionString() { return nil, fmt.Errorf("Version string %s did not match %s", diff --git a/core/config.go b/core/config.go index 30d21034f725508b5252a8993db218e314b536f4..0bc07bf8ce5aa185fa83adbcdd5fe2a8dd16abc0 100644 --- a/core/config.go +++ b/core/config.go @@ -26,7 +26,7 @@ import ( "github.com/hyperledger/burrow/config" "github.com/hyperledger/burrow/consensus" "github.com/hyperledger/burrow/definitions" - "github.com/hyperledger/burrow/logging" + lconfig "github.com/hyperledger/burrow/logging/config" "github.com/hyperledger/burrow/manager" "github.com/hyperledger/burrow/server" "github.com/hyperledger/burrow/util" @@ -113,14 +113,13 @@ func LoadServerConfig(do *definitions.Do) (*server.ServerConfig, error) { return serverConfig, err } -func LoadLoggingConfigFromDo(do *definitions.Do) (*logging.LoggingConfig, error) { - //subConfig, err := SubConfig(conf, "logging") - loggingConfig := &logging.LoggingConfig{} - return loggingConfig, nil +func LoadLoggingConfigFromDo(do *definitions.Do) (*lconfig.LoggingConfig, error) { + loggingConfigMap := do.Config.GetStringMap("logging") + return lconfig.LoggingConfigFromMap(loggingConfigMap) } -func LoadLoggingConfigFromClientDo(do *definitions.ClientDo) (*logging.LoggingConfig, error) { - loggingConfig := &logging.LoggingConfig{} +func LoadLoggingConfigFromClientDo(do *definitions.ClientDo) (*lconfig.LoggingConfig, error) { + loggingConfig := lconfig.DefaultClientLoggingConfig() return loggingConfig, nil } diff --git a/core/core.go b/core/core.go index 6e6189829fb949314a8e2cbb90eff27691eff64c..b6f515e0f8af69208aa708f569634975929b151a 100644 --- a/core/core.go +++ b/core/core.go @@ -30,7 +30,7 @@ import ( // rpc_tendermint is carried over from burrowv0.11 and before on port 46657 "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" rpc_tendermint "github.com/hyperledger/burrow/rpc/tendermint/core" "github.com/hyperledger/burrow/server" ) @@ -41,12 +41,13 @@ type Core struct { evsw events.EventSwitch pipe definitions.Pipe tendermintPipe definitions.TendermintPipe + logger logging_types.InfoTraceLogger } func NewCore(chainId string, consensusConfig *config.ModuleConfig, managerConfig *config.ModuleConfig, - logger loggers.InfoTraceLogger) (*Core, error) { + logger logging_types.InfoTraceLogger) (*Core, error) { // start new event switch, TODO: [ben] replace with burrow/event evsw := events.NewEventSwitch() evsw.Start() @@ -73,6 +74,7 @@ func NewCore(chainId string, evsw: evsw, pipe: pipe, tendermintPipe: tendermintPipe, + logger: logger, }, nil } @@ -99,9 +101,9 @@ func (core *Core) NewGatewayV0(config *server.ServerConfig) (*server.ServeProces jsonServer := rpc_v0.NewJsonRpcServer(tmjs) restServer := rpc_v0.NewRestServer(codec, core.pipe, eventSubscriptions) wsServer := server.NewWebSocketServer(config.WebSocket.MaxWebSocketSessions, - tmwss) + tmwss, core.logger) // Create a server process. - proc, err := server.NewServeProcess(config, jsonServer, restServer, wsServer) + proc, err := server.NewServeProcess(config, core.logger, jsonServer, restServer, wsServer) if err != nil { return nil, fmt.Errorf("Failed to load gateway: %v", err) } diff --git a/definitions/pipe.go b/definitions/pipe.go index 7c1fddd9ef501dc11d7a89bf4eee661121ef99b3..286a0623a000e792e37e32c595f5296cdf02ced2 100644 --- a/definitions/pipe.go +++ b/definitions/pipe.go @@ -29,7 +29,7 @@ import ( core_types "github.com/hyperledger/burrow/core/types" types "github.com/hyperledger/burrow/core/types" event "github.com/hyperledger/burrow/event" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" manager_types "github.com/hyperledger/burrow/manager/types" "github.com/hyperledger/burrow/txs" ) @@ -42,7 +42,7 @@ type Pipe interface { Transactor() Transactor // Hash of Genesis state GenesisHash() []byte - Logger() loggers.InfoTraceLogger + Logger() logging_types.InfoTraceLogger // NOTE: [ben] added to Pipe interface on 0.12 refactor GetApplication() manager_types.Application SetConsensusEngine(consensusEngine consensus_types.ConsensusEngine) error diff --git a/event/events.go b/event/events.go index a198dc51a490b9450fe7b6716a00cdd1981a12b6..f93b1b643eb56d75af899995f5b732fa964532d1 100644 --- a/event/events.go +++ b/event/events.go @@ -22,7 +22,7 @@ import ( "fmt" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/txs" go_events "github.com/tendermint/go-events" tm_types "github.com/tendermint/tendermint/types" @@ -42,7 +42,7 @@ type EventEmitter interface { Unsubscribe(subId string) error } -func NewEvents(eventSwitch go_events.EventSwitch, logger loggers.InfoTraceLogger) *events { +func NewEvents(eventSwitch go_events.EventSwitch, logger logging_types.InfoTraceLogger) *events { return &events{eventSwitch: eventSwitch, logger: logging.WithScope(logger, "Events")} } @@ -56,7 +56,7 @@ func Multiplex(events ...EventEmitter) *multiplexedEvents { // The events struct has methods for working with events. type events struct { eventSwitch go_events.EventSwitch - logger loggers.InfoTraceLogger + logger logging_types.InfoTraceLogger } // Subscribe to an event. diff --git a/glide.lock b/glide.lock index 10bcdcad4c5ac8966a9786a9952e5f7194b471b1..303601c905a60a2161e377ce2f06f15280c3ad9a 100644 --- a/glide.lock +++ b/glide.lock @@ -31,6 +31,8 @@ imports: version: c1eddaa09da2b4017351245b0d43234955276798 - name: github.com/fsnotify/fsnotify version: 30411dbcefb7a1da7e84f75530ad3abe4011b4f8 +- name: github.com/Graylog2/go-gelf + version: 5bfd5bbbfe86489017c268bf86539fcec7e28d8e - name: github.com/gin-gonic/gin version: f931d1ea80ae95a6fc739213cdd9399bd2967fb6 subpackages: @@ -84,7 +86,7 @@ imports: - name: github.com/mattn/go-isatty version: 30a891c33c7cde7b02a981314b4228ec99380cca - name: github.com/mitchellh/mapstructure - version: d2dd0262208475919e1a362f675cfc0e7c10e905 + version: db1efb556f84b25a0a13a04aad883943538ad2e0 - name: github.com/naoina/toml version: 751171607256bb66e64c9f0220c00662420c38e9 - name: github.com/pmezard/go-difflib diff --git a/glide.yaml b/glide.yaml index aa29fb5b21bd58c975f388d8d711a9f5ccf932f4..43dd7879a00769a4e33011634df7600943cb8630 100644 --- a/glide.yaml +++ b/glide.yaml @@ -32,3 +32,4 @@ import: - package: github.com/streadway/simpleuuid - package: github.com/Masterminds/glide version: ~0.12.3 +- package: github.com/Graylog2/go-gelf diff --git a/keys/key_client.go b/keys/key_client.go index 184ca2f8caae811ead93681e8657e78f9a552d4f..99046e5e316960de264d56b3041ec9491e136236 100644 --- a/keys/key_client.go +++ b/keys/key_client.go @@ -19,7 +19,7 @@ import ( "fmt" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" ) type KeyClient interface { @@ -36,12 +36,12 @@ var _ KeyClient = (*monaxKeyClient)(nil) type monaxKeyClient struct { rpcString string - logger loggers.InfoTraceLogger + logger logging_types.InfoTraceLogger } // monaxKeyClient.New returns a new monax-keys client for provided rpc location // Monax-keys connects over http request-responses -func NewBurrowKeyClient(rpcString string, logger loggers.InfoTraceLogger) *monaxKeyClient { +func NewBurrowKeyClient(rpcString string, logger logging_types.InfoTraceLogger) *monaxKeyClient { return &monaxKeyClient{ rpcString: rpcString, logger: logging.WithScope(logger, "BurrowKeyClient"), diff --git a/keys/key_client_util.go b/keys/key_client_util.go index 6046945aac9489122366999eb14abcad47fa4eb0..c0677f993cb841526a5a3527b028daffe9aef4f0 100644 --- a/keys/key_client_util.go +++ b/keys/key_client_util.go @@ -22,7 +22,7 @@ import ( "net/http" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" ) // Monax-Keys server connects over http request-response structures @@ -32,7 +32,7 @@ type HTTPResponse struct { Error string } -func RequestResponse(addr, method string, args map[string]string, logger loggers.InfoTraceLogger) (string, error) { +func RequestResponse(addr, method string, args map[string]string, logger logging_types.InfoTraceLogger) (string, error) { body, err := json.Marshal(args) if err != nil { return "", err diff --git a/logging/adapters/logrus/logrus.go b/logging/adapters/logrus/logrus.go deleted file mode 100644 index 84b6837188e6c6712ef05461227b658372ccd0bb..0000000000000000000000000000000000000000 --- a/logging/adapters/logrus/logrus.go +++ /dev/null @@ -1,36 +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 adapters - -import ( - "github.com/Sirupsen/logrus" - kitlog "github.com/go-kit/kit/log" -) - -type logrusLogger struct { - logger logrus.Logger -} - -var _ kitlog.Logger = (*logrusLogger)(nil) - -func NewLogrusLogger(logger logrus.Logger) *logrusLogger { - return &logrusLogger{ - logger: logger, - } -} - -func (ll *logrusLogger) Log(keyvals ...interface{}) error { - return nil -} diff --git a/logging/adapters/stdlib/capture.go b/logging/adapters/stdlib/capture.go index ceeaaf9a6304cd266541f329e4cc22efedc56d39..599a19a70aa36bc2107029ef12df1075055726c3 100644 --- a/logging/adapters/stdlib/capture.go +++ b/logging/adapters/stdlib/capture.go @@ -19,22 +19,22 @@ import ( "log" kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging/types" ) func Capture(stdLibLogger log.Logger, - logger loggers.InfoTraceLogger) io.Writer { + logger types.InfoTraceLogger) io.Writer { adapter := newAdapter(logger) stdLibLogger.SetOutput(adapter) return adapter } -func CaptureRootLogger(logger loggers.InfoTraceLogger) io.Writer { +func CaptureRootLogger(logger types.InfoTraceLogger) io.Writer { adapter := newAdapter(logger) log.SetOutput(adapter) return adapter } -func newAdapter(logger loggers.InfoTraceLogger) io.Writer { +func newAdapter(logger types.InfoTraceLogger) io.Writer { return kitlog.NewStdlibAdapter(logger) } diff --git a/logging/adapters/tendermint_log15/capture.go b/logging/adapters/tendermint_log15/capture.go index f29ca76cd96e2169775480f9309d683f0663e26c..3534ca3eeffd61e99ac61acad5fe41e8669733bc 100644 --- a/logging/adapters/tendermint_log15/capture.go +++ b/logging/adapters/tendermint_log15/capture.go @@ -12,16 +12,16 @@ // See the License for the specific language governing permissions and // limitations under the License. -package adapters +package tendermint_log15 import ( kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging/types" "github.com/tendermint/log15" ) type infoTraceLoggerAsLog15Handler struct { - logger loggers.InfoTraceLogger + logger types.InfoTraceLogger } var _ log15.Handler = (*infoTraceLoggerAsLog15Handler)(nil) @@ -54,7 +54,7 @@ func Log15HandlerAsKitLogger(handler log15.Handler) kitlog.Logger { } } -func InfoTraceLoggerAsLog15Handler(logger loggers.InfoTraceLogger) log15.Handler { +func InfoTraceLoggerAsLog15Handler(logger types.InfoTraceLogger) log15.Handler { return &infoTraceLoggerAsLog15Handler{ logger: logger, } diff --git a/logging/adapters/tendermint_log15/convert.go b/logging/adapters/tendermint_log15/convert.go index a9a8e69a39eb85b2bb7eccafd7806accb95ac78a..d64607628b0a8b22ebfd3b88bbe19aec39db8800 100644 --- a/logging/adapters/tendermint_log15/convert.go +++ b/logging/adapters/tendermint_log15/convert.go @@ -12,14 +12,14 @@ // See the License for the specific language governing permissions and // limitations under the License. -package adapters +package tendermint_log15 import ( "time" "github.com/go-stack/stack" - "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/logging/structure" + "github.com/hyperledger/burrow/logging/types" . "github.com/hyperledger/burrow/util/slice" "github.com/tendermint/log15" ) @@ -70,9 +70,9 @@ func Log15LvlFromString(level string) log15.Lvl { return log15.LvlDebug } switch level { - case loggers.InfoLevelName: + case types.InfoLevelName: return log15.LvlInfo - case loggers.TraceLevelName: + case types.TraceLevelName: return log15.LvlDebug default: lvl, err := log15.LvlFromString(level) diff --git a/logging/config.go b/logging/config.go deleted file mode 100644 index 5123b93695f9ee60ecb38e50ef58ad040fd6780c..0000000000000000000000000000000000000000 --- a/logging/config.go +++ /dev/null @@ -1,25 +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 - -type ( - SinkConfig struct { - Channels []string - } - - LoggingConfig struct { - Sinks []SinkConfig - } -) diff --git a/logging/config/config.go b/logging/config/config.go new file mode 100644 index 0000000000000000000000000000000000000000..fb84f43bd01f357eb7ede8f84df8d08905c47df6 --- /dev/null +++ b/logging/config/config.go @@ -0,0 +1,80 @@ +package config + +import ( + "bytes" + "fmt" + + "github.com/hyperledger/burrow/logging/structure" + + "github.com/BurntSushi/toml" +) + +type LoggingConfig struct { + InfoSink *SinkConfig `toml:"info_sink"` + InfoAndTraceSink *SinkConfig `toml:"info_and_trace_sink"` +} + +// For encoding a top-level '[logging]' TOML table +type LoggingConfigWrapper struct { + Logging *LoggingConfig `toml:"logging"` +} + +func DefaultNodeLoggingConfig() *LoggingConfig { + return &LoggingConfig{ + InfoSink: Sink(), + InfoAndTraceSink: Sink().SetOutput(StderrOutput()), + } +} + +func DefaultClientLoggingConfig() *LoggingConfig { + return &LoggingConfig{ + // No output + InfoSink: Sink(). + SetTransform(FilterTransform(ExcludeWhenAnyMatches, + structure.CapturedLoggingSourceKey, "")). + SetOutput(StderrOutput()), + InfoAndTraceSink: Sink(), + } +} + +// Returns the TOML for a top-level logging config wrapped with [logging] +func (lc *LoggingConfig) RootTOMLString() string { + return tomlString(LoggingConfigWrapper{lc}) +} + +func (lc *LoggingConfig) TOMLString() string { + return tomlString(lc) +} + +func LoggingConfigFromMap(loggingRootMap map[string]interface{}) (*LoggingConfig, error) { + lc := new(LoggingConfig) + buf := new(bytes.Buffer) + enc := toml.NewEncoder(buf) + // TODO: [Silas] consider using strongly typed config/struct mapping everywhere + // (!! unfortunately the way we are using viper + // to pass around a untyped bag of config means that we don't get keys mapped + // according to their metadata `toml:"Name"` tags. So we are re-encoding to toml + // and then decoding into the strongly type struct as a work-around) + // Encode the map back to TOML + err := enc.Encode(loggingRootMap) + if err != nil { + return nil, err + } + // Decode into struct into the LoggingConfig struct + _, err = toml.Decode(buf.String(), lc) + if err != nil { + return nil, err + } + return lc, nil +} + +func tomlString(v interface{}) string { + buf := new(bytes.Buffer) + encoder := toml.NewEncoder(buf) + err := encoder.Encode(v) + if err != nil { + // Seems like a reasonable compromise to make the string function clean + return fmt.Sprintf("Error encoding TOML: %s", err) + } + return buf.String() +} diff --git a/logging/config/config_test.go b/logging/config/config_test.go new file mode 100644 index 0000000000000000000000000000000000000000..5e30c7510dbcf0a497ad9eef36fc7b192ac6e058 --- /dev/null +++ b/logging/config/config_test.go @@ -0,0 +1,44 @@ +package config + +import ( + "strings" + "testing" + + "github.com/BurntSushi/toml" + "github.com/spf13/viper" + "github.com/stretchr/testify/assert" +) + +var complexConfig *LoggingConfig = &LoggingConfig{ + InfoSink: Sink(). + SetOutput(StderrOutput()), + InfoAndTraceSink: Sink(). + SetTransform(LabelTransform(false, "Info", "Trace")). + AddSinks( + Sink(). + SetOutput(StdoutOutput()). + SetTransform(FilterTransform(ExcludeWhenAnyMatches, + "Foo", "Bars")). + AddSinks( + Sink(). + SetOutput(RemoteSyslogOutput("Eris-db", "tcp://example.com:6514")), + Sink(). + SetOutput(StdoutOutput()), + ), + ), +} + +func TestLoggingConfig_String(t *testing.T) { + lc := new(LoggingConfig) + toml.Decode(complexConfig.TOMLString(), lc) + assert.Equal(t, complexConfig, lc) +} + +func TestReadViperConfig(t *testing.T) { + conf := viper.New() + conf.SetConfigType("toml") + conf.ReadConfig(strings.NewReader(complexConfig.TOMLString())) + lc, err := LoggingConfigFromMap(conf.AllSettings()) + assert.NoError(t, err) + assert.Equal(t, complexConfig, lc) +} diff --git a/logging/config/filter.go b/logging/config/filter.go new file mode 100644 index 0000000000000000000000000000000000000000..1ddf35ff6a1339776f6793c63dc2a7aea19b5a4a --- /dev/null +++ b/logging/config/filter.go @@ -0,0 +1,107 @@ +package config + +import ( + "fmt" + + "regexp" + + "github.com/hyperledger/burrow/common/math/integral" +) + +func BuildFilterPredicate(filterConfig *FilterConfig) (func([]interface{}) bool, error) { + predicate, err := BuildKeyValuesPredicate(filterConfig.Predicates, + filterConfig.FilterMode.MatchAll()) + if err != nil { + return nil, err + } + include := filterConfig.FilterMode.Include() + return func(keyvals []interface{}) bool { + // XOR the predicate with include. If include is true then negate the match. + return predicate(keyvals) != include + }, nil +} + +func BuildKeyValuesPredicate(kvpConfigs []*KeyValuePredicateConfig, + matchAll bool) (func([]interface{}) bool, error) { + length := len(kvpConfigs) + keyRegexes := make([]*regexp.Regexp, length) + valueRegexes := make([]*regexp.Regexp, length) + + // Compile all KV regexes + for i, kvpConfig := range kvpConfigs { + // Store a nil regex to indicate no key match should occur + if kvpConfig.KeyRegex != "" { + keyRegex, err := regexp.Compile(kvpConfig.KeyRegex) + if err != nil { + return nil, err + } + keyRegexes[i] = keyRegex + } + // Store a nil regex to indicate no value match should occur + if kvpConfig.ValueRegex != "" { + valueRegex, err := regexp.Compile(kvpConfig.ValueRegex) + if err != nil { + return nil, err + } + valueRegexes[i] = valueRegex + } + } + + return func(keyvals []interface{}) bool { + return matchLogLine(keyvals, keyRegexes, valueRegexes, matchAll) + }, nil +} + +// matchLogLine tries to match a log line by trying to match each key value pair with each pair of key value regexes +// if matchAll is true then matchLogLine returns true iff every key value regexes finds a match or the line or regexes +// are empty +func matchLogLine(keyvals []interface{}, keyRegexes, valueRegexes []*regexp.Regexp, matchAll bool) bool { + all := matchAll + // We should be passed an aligned list of keyRegexes and valueRegexes, but since we can't error here we'll guard + // against a failure of the caller to pass valid arguments + length := integral.MinInt(len(keyRegexes), len(valueRegexes)) + for i := 0; i < length; i++ { + matched := findMatchInLogLine(keyvals, keyRegexes[i], valueRegexes[i]) + if matchAll { + all = all && matched + } else if matched { + return true + } + } + return all +} + +func findMatchInLogLine(keyvals []interface{}, keyRegex, valueRegex *regexp.Regexp) bool { + for i := 0; i < 2*(len(keyvals)/2); i += 2 { + key := convertToString(keyvals[i]) + val := convertToString(keyvals[i+1]) + if key == nil && val == nil { + continue + } + // At least one of key or val could be converted from string, only match on either if the conversion worked + // Try to match on both key and value, falling back to a positive match if either or both or not supplied + if match(keyRegex, key) && match(valueRegex, val) { + return true + } + } + return false +} + +func match(regex *regexp.Regexp, text *string) bool { + // Always match on a nil regex (indicating no constraint on text), + // and otherwise never match on nil text (indicating a non-string convertible type) + return regex == nil || (text != nil && regex.MatchString(*text)) +} + +func convertToString(value interface{}) *string { + // We have the option of returning nil here to indicate a conversion was + // not possible/does not make sense. Although we are not opting to use it + // currently + switch v := value.(type) { + case string: + return &v + default: + s := fmt.Sprintf("%v", v) + return &s + } +} diff --git a/logging/config/filter_test.go b/logging/config/filter_test.go new file mode 100644 index 0000000000000000000000000000000000000000..3c5edf5ad4df8c54e999c33792c70e10f4a99c62 --- /dev/null +++ b/logging/config/filter_test.go @@ -0,0 +1,119 @@ +package config + +import ( + "testing" + + . "github.com/hyperledger/burrow/util/slice" + "github.com/stretchr/testify/assert" +) + +func TestBuildKeyValuesPredicateMatchAll(t *testing.T) { + conf := []*KeyValuePredicateConfig{ + { + KeyRegex: "Foo", + ValueRegex: "bar", + }, + } + kvp, err := BuildKeyValuesPredicate(conf, true) + assert.NoError(t, err) + assert.True(t, kvp(Slice("Foo", "bar", "Bosh", "Bish"))) +} + +func TestBuildKeyValuesPredicateMatchAny(t *testing.T) { + conf := []*KeyValuePredicateConfig{ + { + KeyRegex: "Bosh", + ValueRegex: "Bish", + }, + } + kvp, err := BuildKeyValuesPredicate(conf, false) + assert.NoError(t, err) + assert.True(t, kvp(Slice("Foo", "bar", "Bosh", "Bish"))) +} + +func TestExcludeAllFilterPredicate(t *testing.T) { + fc := &FilterConfig{ + FilterMode: ExcludeWhenAllMatch, + Predicates: []*KeyValuePredicateConfig{ + { + KeyRegex: "Bosh", + ValueRegex: "Bish", + }, + { + KeyRegex: "Bosh", + ValueRegex: "Bash", + }, + }, + } + fp, err := BuildFilterPredicate(fc) + assert.NoError(t, err) + assert.False(t, fp(Slice("Bosh", "Bash", "Shoes", 42))) + assert.True(t, fp(Slice("Bosh", "Bash", "Foo", "bar", "Shoes", 42, "Bosh", "Bish"))) + assert.False(t, fp(Slice("Food", 0.2, "Shoes", 42))) + +} +func TestExcludeAnyFilterPredicate(t *testing.T) { + fc := &FilterConfig{ + FilterMode: ExcludeWhenAnyMatches, + Predicates: []*KeyValuePredicateConfig{ + { + KeyRegex: "Bosh", + ValueRegex: "Bish", + }, + { + KeyRegex: "Bosh", + ValueRegex: "Bash", + }, + }, + } + fp, err := BuildFilterPredicate(fc) + assert.NoError(t, err) + assert.False(t, fp(Slice("Foo", "bar", "Shoes", 42))) + assert.True(t, fp(Slice("Foo", "bar", "Shoes", 42, "Bosh", "Bish"))) + assert.True(t, fp(Slice("Food", 0.2, "Shoes", 42, "Bosh", "Bish"))) + +} + +func TestIncludeAllFilterPredicate(t *testing.T) { + fc := &FilterConfig{ + FilterMode: IncludeWhenAllMatch, + Predicates: []*KeyValuePredicateConfig{ + { + KeyRegex: "Bosh", + ValueRegex: "Bish", + }, + { + KeyRegex: "Planks", + ValueRegex: "^0.2$", + }, + }, + } + fp, err := BuildFilterPredicate(fc) + assert.NoError(t, err) + assert.True(t, fp(Slice("Foo", "bar", "Shoes", 42))) + // Don't filter, it has all the required key values + assert.False(t, fp(Slice("Foo", "bar", "Planks", 0.2, "Shoes", 42, "Bosh", "Bish"))) + assert.True(t, fp(Slice("Food", 0.2, "Shoes", 42))) +} + +func TestIncludeAnyFilterPredicate(t *testing.T) { + fc := &FilterConfig{ + FilterMode: IncludeWhenAnyMatches, + Predicates: []*KeyValuePredicateConfig{ + { + KeyRegex: "Bosh", + ValueRegex: "Bish", + }, + { + KeyRegex: "^Shoes$", + ValueRegex: "42", + }, + }, + } + fp, err := BuildFilterPredicate(fc) + assert.NoError(t, err) + assert.False(t, fp(Slice("Foo", "bar", "Shoes", 3427))) + assert.False(t, fp(Slice("Foo", "bar", "Shoes", 42, "Bosh", "Bish"))) + assert.False(t, fp(Slice("Food", 0.2, "Shoes", 42))) + +} diff --git a/logging/config/sinks.go b/logging/config/sinks.go new file mode 100644 index 0000000000000000000000000000000000000000..7eaea511a39371da16ded5a48b3eb624389b83a5 --- /dev/null +++ b/logging/config/sinks.go @@ -0,0 +1,382 @@ +package config + +import ( + "fmt" + "os" + + "net/url" + + "github.com/eapache/channels" + kitlog "github.com/go-kit/kit/log" + "github.com/hyperledger/burrow/logging/loggers" + "github.com/hyperledger/burrow/logging/structure" +) + +// This file contains definitions for a configurable output graph for the +// logging system. + +type source string +type outputType string +type transformType string +type filterMode string + +const ( + // OutputType + NoOutput outputType = "" + Graylog outputType = "graylog" + Syslog outputType = "syslog" + File outputType = "file" + Stdout outputType = "stdout" + Stderr outputType = "stderr" + + // TransformType + NoTransform transformType = "" + // Filter log lines + Filter transformType = "filter" + // 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" + // TODO [Silas]: add 'flush on exit' transform which flushes the buffer of + // CaptureLogger to its OutputLogger a non-passthrough capture when an exit + // signal is detected or some other exceptional thing happens + + IncludeWhenAllMatch filterMode = "include_when_all_match" + IncludeWhenAnyMatches filterMode = "include_when_any_matches" + ExcludeWhenAllMatch filterMode = "exclude_when_all_match" + ExcludeWhenAnyMatches filterMode = "exclude_when_any_matches" +) + +// Only include log lines matching the filter so negate the predicate in filter +func (mode filterMode) Include() bool { + switch mode { + case IncludeWhenAllMatch, IncludeWhenAnyMatches: + return true + default: + return false + } +} + +// The predicate should only evaluate true if all the key value predicates match +func (mode filterMode) MatchAll() bool { + switch mode { + case IncludeWhenAllMatch, ExcludeWhenAllMatch: + return true + default: + return false + } +} + +// Exclude log lines that match the predicate +func (mode filterMode) Exclude() bool { + return !mode.Include() +} + +// The predicate should evaluate true if at least one of the key value predicates matches +func (mode filterMode) MatchAny() bool { + return !mode.MatchAny() +} + +// Sink configuration types +type ( + // Outputs + GraylogConfig struct { + } + + SyslogConfig struct { + Url string `toml:"url"` + Tag string `toml:"tag"` + } + + FileConfig struct { + Path string `toml:"path"` + } + + OutputConfig struct { + OutputType outputType `toml:"output_type"` + Format string `toml:"format,omitempty"` + *GraylogConfig + *FileConfig + *SyslogConfig + } + + // Transforms + LabelConfig struct { + Labels map[string]string `toml:"labels"` + Prefix bool `toml:"prefix"` + } + + PruneConfig struct { + Keys []string `toml:"keys"` + } + + CaptureConfig struct { + Name string `toml:"name"` + BufferCap int `toml:"buffer_cap"` + Passthrough bool `toml:"passthrough"` + } + + // Generates true if KeyRegex matches a log line key and ValueRegex matches that key's value. + // If ValueRegex is empty then returns true if any key matches + // If KeyRegex is empty then returns true if any value matches + KeyValuePredicateConfig struct { + KeyRegex string `toml:"key_regex"` + ValueRegex string `toml:"value_regex"` + } + + // Filter types + FilterConfig struct { + FilterMode filterMode `toml:"filter_mode"` + // Predicates to match a log line against using FilterMode + Predicates []*KeyValuePredicateConfig `toml:"predicates"` + } + + TransformConfig struct { + TransformType transformType `toml:"transform_type"` + *LabelConfig + *PruneConfig + *CaptureConfig + *FilterConfig + } + + // Sink + // A Sink describes a logger that logs to zero or one output and logs to zero or more child sinks. + // before transmitting its log it applies zero or one transforms to the stream of log lines. + // by chaining together many Sinks arbitrary transforms to and multi + SinkConfig struct { + Transform *TransformConfig `toml:"transform"` + Sinks []*SinkConfig `toml:"sinks"` + Output *OutputConfig `toml:"output"` + } +) + +// Builders +func Sink() *SinkConfig { + return &SinkConfig{} +} + +func (sinkConfig *SinkConfig) AddSinks(sinks ...*SinkConfig) *SinkConfig { + sinkConfig.Sinks = append(sinkConfig.Sinks, sinks...) + return sinkConfig +} + +func (sinkConfig *SinkConfig) SetTransform(transform *TransformConfig) *SinkConfig { + sinkConfig.Transform = transform + return sinkConfig +} + +func (sinkConfig *SinkConfig) SetOutput(output *OutputConfig) *SinkConfig { + sinkConfig.Output = output + return sinkConfig +} + +func StdoutOutput() *OutputConfig { + return &OutputConfig{ + OutputType: Stdout, + } +} + +func StderrOutput() *OutputConfig { + return &OutputConfig{ + OutputType: Stderr, + } +} + +func SyslogOutput(tag string) *OutputConfig { + return RemoteSyslogOutput(tag, "") +} + +func FileOutput(path string) *OutputConfig { + return &OutputConfig{ + OutputType: File, + FileConfig: &FileConfig{ + Path: path, + }, + } +} + +func RemoteSyslogOutput(tag, remoteUrl string) *OutputConfig { + return &OutputConfig{ + OutputType: Syslog, + SyslogConfig: &SyslogConfig{ + Url: remoteUrl, + Tag: tag, + }, + } +} + +func CaptureTransform(name string, bufferCap int, passthrough bool) *TransformConfig { + return &TransformConfig{ + TransformType: Capture, + CaptureConfig: &CaptureConfig{ + Name: name, + BufferCap: bufferCap, + Passthrough: passthrough, + }, + } +} + +func LabelTransform(prefix bool, labelKeyvals ...string) *TransformConfig { + length := len(labelKeyvals) / 2 + labels := make(map[string]string, length) + for i := 0; i < 2*length; i += 2 { + labels[labelKeyvals[i]] = labelKeyvals[i+1] + } + return &TransformConfig{ + TransformType: Label, + LabelConfig: &LabelConfig{ + Prefix: prefix, + Labels: labels, + }, + } +} + +func PruneTransform(keys ...string) *TransformConfig { + return &TransformConfig{ + TransformType: Prune, + PruneConfig: &PruneConfig{ + Keys: keys, + }, + } +} + +func FilterTransform(fmode filterMode, keyvalueRegexes ...string) *TransformConfig { + length := len(keyvalueRegexes) / 2 + predicates := make([]*KeyValuePredicateConfig, length) + for i := 0; i < length; i++ { + kv := i * 2 + predicates[i] = &KeyValuePredicateConfig{ + KeyRegex: keyvalueRegexes[kv], + ValueRegex: keyvalueRegexes[kv+1], + } + } + return &TransformConfig{ + TransformType: Filter, + FilterConfig: &FilterConfig{ + FilterMode: fmode, + Predicates: predicates, + }, + } +} + +// Logger formation +func (sinkConfig *SinkConfig) BuildLogger() (kitlog.Logger, map[string]*loggers.CaptureLogger, error) { + return BuildLoggerFromSinkConfig(sinkConfig, make(map[string]*loggers.CaptureLogger)) +} + +func BuildLoggerFromSinkConfig(sinkConfig *SinkConfig, + captures map[string]*loggers.CaptureLogger) (kitlog.Logger, map[string]*loggers.CaptureLogger, error) { + if sinkConfig == nil { + return kitlog.NewNopLogger(), captures, nil + } + numSinks := len(sinkConfig.Sinks) + outputLoggers := make([]kitlog.Logger, numSinks, numSinks+1) + // We need a depth-first post-order over the output loggers so we'll keep + // recurring into children sinks we reach a terminal sink (with no children) + for i, sc := range sinkConfig.Sinks { + l, captures, err := BuildLoggerFromSinkConfig(sc, captures) + if err != nil { + return nil, captures, err + } + outputLoggers[i] = l + } + + // Grab the outputs after we have terminated any children sinks above + if sinkConfig.Output != nil && sinkConfig.Output.OutputType != NoOutput { + l, err := BuildOutputLogger(sinkConfig.Output) + if err != nil { + return nil, captures, err + } + outputLoggers = append(outputLoggers, l) + } + + outputLogger := loggers.NewMultipleOutputLogger(outputLoggers...) + + if sinkConfig.Transform != nil && sinkConfig.Transform.TransformType != NoTransform { + return BuildTransformLogger(sinkConfig.Transform, captures, outputLogger) + } + return outputLogger, captures, nil +} + +func BuildOutputLogger(outputConfig *OutputConfig) (kitlog.Logger, error) { + switch outputConfig.OutputType { + case NoOutput: + return kitlog.NewNopLogger(), nil + //case Graylog: + case Syslog: + urlString := outputConfig.SyslogConfig.Url + if urlString != "" { + remoteUrl, err := url.Parse(urlString) + if err != nil { + return nil, fmt.Errorf("Error parsing remote syslog URL: %s, "+ + "error: %s", + urlString, err) + } + return loggers.NewRemoteSyslogLogger(remoteUrl, + outputConfig.SyslogConfig.Tag, outputConfig.Format) + } + return loggers.NewSyslogLogger(outputConfig.SyslogConfig.Tag, + outputConfig.Format) + case Stdout: + return loggers.NewStreamLogger(os.Stdout, outputConfig.Format), nil + case Stderr: + return loggers.NewStreamLogger(os.Stderr, outputConfig.Format), nil + case File: + return loggers.NewFileLogger(outputConfig.FileConfig.Path, outputConfig.Format) + default: + return nil, fmt.Errorf("Could not build logger for output: '%s'", + outputConfig.OutputType) + } +} + +func BuildTransformLogger(transformConfig *TransformConfig, + captures map[string]*loggers.CaptureLogger, + outputLogger kitlog.Logger) (kitlog.Logger, map[string]*loggers.CaptureLogger, error) { + switch transformConfig.TransformType { + case NoTransform: + return outputLogger, captures, nil + case Label: + keyvals := make([]interface{}, 0, len(transformConfig.Labels)*2) + for k, v := range transformConfig.LabelConfig.Labels { + keyvals = append(keyvals, k, v) + } + if transformConfig.LabelConfig.Prefix { + return kitlog.NewContext(outputLogger).WithPrefix(keyvals...), captures, nil + } else { + return kitlog.NewContext(outputLogger).With(keyvals...), captures, nil + } + case Prune: + keys := make([]interface{}, len(transformConfig.PruneConfig.Keys)) + for i, k := range transformConfig.PruneConfig.Keys { + keys[i] = k + } + return kitlog.LoggerFunc(func(keyvals ...interface{}) error { + return outputLogger.Log(structure.RemoveKeys(keyvals, keys...)...) + }), captures, nil + + case Capture: + name := transformConfig.CaptureConfig.Name + if _, ok := captures[name]; ok { + return nil, captures, fmt.Errorf("Could not register new logging capture since name '%s' already "+ + "registered", name) + } + // Create a capture logger according to configuration (it may tee the output) + // or capture it to be flushed later + captureLogger := loggers.NewCaptureLogger(outputLogger, + channels.BufferCap(transformConfig.CaptureConfig.BufferCap), + transformConfig.CaptureConfig.Passthrough) + // Register the capture + captures[name] = captureLogger + // Pass it upstream to be logged to + return captureLogger, captures, nil + case Filter: + predicate, err := BuildFilterPredicate(transformConfig.FilterConfig) + if err != nil { + return nil, captures, fmt.Errorf("Could not build filter predicate: '%s'", err) + } + return loggers.NewFilterLogger(outputLogger, predicate), captures, nil + default: + return nil, captures, fmt.Errorf("Could not build logger for transform: '%s'", transformConfig.TransformType) + } +} diff --git a/logging/config/sinks_test.go b/logging/config/sinks_test.go new file mode 100644 index 0000000000000000000000000000000000000000..fbe035bb410310ba7b3b13e993ff924973f4121a --- /dev/null +++ b/logging/config/sinks_test.go @@ -0,0 +1,117 @@ +package config + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestBuildLoggerFromSinkConfig(t *testing.T) { + sinkConfig := Sink(). + AddSinks( + Sink(). + AddSinks( + Sink(). + AddSinks( + Sink(). + SetTransform(CaptureTransform("cap", 100, true)). + SetOutput(StderrOutput()). + AddSinks( + Sink(). + SetTransform(LabelTransform(true, "Label", "A Label!")). + SetOutput(StdoutOutput()))))) + + logger, captures, err := sinkConfig.BuildLogger() + logger.Log("Foo", "Bar") + assert.NoError(t, err) + assert.Equal(t, logLines("Foo", "Bar"), + captures["cap"].BufferLogger().FlushLogLines()) +} + +func TestFilterSinks(t *testing.T) { + sinkConfig := Sink(). + SetOutput(StderrOutput()). + AddSinks( + Sink(). + SetTransform(FilterTransform(IncludeWhenAnyMatches, + "Foo", "Bar", + "Rough", "Trade", + )). + AddSinks( + Sink(). + SetTransform(CaptureTransform("Included", 100, true)). + AddSinks( + Sink(). + SetTransform(FilterTransform(ExcludeWhenAllMatch, + "Foo", "Baz", + "Index", "00$")). + AddSinks( + Sink(). + SetTransform(CaptureTransform("Excluded", 100, false)), + ), + ), + ), + ) + + logger, captures, err := sinkConfig.BuildLogger() + assert.NoError(t, err, "Should be able to build filter logger") + included := captures["Included"] + excluded := captures["Excluded"] + + // Included by both filters + ll := logLines("Foo", "Bar") + logger.Log(ll[0]...) + assert.Equal(t, logLines("Foo", "Bar"), + included.BufferLogger().FlushLogLines()) + assert.Equal(t, logLines("Foo", "Bar"), + excluded.BufferLogger().FlushLogLines()) + + // Included by first filter and excluded by second + ll = logLines("Foo", "Bar", "Foo", "Baz", "Index", "1000") + logger.Log(ll[0]...) + assert.Equal(t, ll, included.BufferLogger().FlushLogLines()) + assert.Equal(t, logLines(), excluded.BufferLogger().FlushLogLines()) + + // Included by first filter and not excluded by second despite matching one + // predicate + ll = logLines("Rough", "Trade", "Index", "1000") + logger.Log(ll[0]...) + assert.Equal(t, ll, included.BufferLogger().FlushLogLines()) + assert.Equal(t, ll, excluded.BufferLogger().FlushLogLines()) +} + +func TestPruneTransform(t *testing.T) { + sinkConfig := Sink(). + SetTransform(PruneTransform("Trace")). + AddSinks(Sink(). + SetTransform(CaptureTransform("cap", 100, false))) + + logger, captures, err := sinkConfig.BuildLogger() + assert.NoError(t, err) + logger.Log("msg", "Hello with a trace", + "Trace", []string{"logger:32, state:23"}) + logger.Log("msg", "Goodbye with a trace", + "Trace", []string{"logger:32, state:14"}) + assert.Equal(t, logLines("msg", "Hello with a trace", "", + "msg", "Goodbye with a trace"), + captures["cap"].FlushLogLines()) +} + +// Takes a variadic argument of log lines as a list of key value pairs delimited +// by the empty string +func logLines(keyvals ...string) [][]interface{} { + llines := make([][]interface{}, 0) + line := make([]interface{}, 0) + for _, kv := range keyvals { + if kv == "" { + llines = append(llines, line) + line = make([]interface{}, 0) + } else { + line = append(line, kv) + } + } + if len(line) > 0 { + llines = append(llines, line) + } + return llines +} diff --git a/logging/convention.go b/logging/convention.go index fdd09f7fadba0f022582905621a5d8672a46fbc5..d470451a9670a480bf47f9d36f6a4b900f5124c2 100644 --- a/logging/convention.go +++ b/logging/convention.go @@ -16,8 +16,8 @@ package logging import ( kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/logging/structure" + "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/util/slice" ) @@ -25,23 +25,13 @@ import ( // to centralise and establish logging conventions on top of in with the base // logging interface -// Record structured Info log line with a message and conventional keys -func InfoMsgVals(logger loggers.InfoTraceLogger, message string, vals ...interface{}) { - MsgVals(kitlog.LoggerFunc(logger.Info), message, vals...) -} - -// Record structured Trace log line with a message and conventional keys -func TraceMsgVals(logger loggers.InfoTraceLogger, message string, vals ...interface{}) { - MsgVals(kitlog.LoggerFunc(logger.Trace), message, vals...) -} - // Record structured Info log line with a message -func InfoMsg(logger loggers.InfoTraceLogger, message string, keyvals ...interface{}) { +func InfoMsg(logger types.InfoTraceLogger, message string, keyvals ...interface{}) { Msg(kitlog.LoggerFunc(logger.Info), message, keyvals...) } // Record structured Trace log line with a message -func TraceMsg(logger loggers.InfoTraceLogger, message string, keyvals ...interface{}) { +func TraceMsg(logger types.InfoTraceLogger, message string, keyvals ...interface{}) { Msg(kitlog.LoggerFunc(logger.Trace), message, keyvals...) } @@ -49,7 +39,7 @@ func TraceMsg(logger loggers.InfoTraceLogger, message string, keyvals ...interfa // 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 loggers.InfoTraceLogger, scopeName string) loggers.InfoTraceLogger { +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) } @@ -59,14 +49,3 @@ func Msg(logger kitlog.Logger, message string, keyvals ...interface{}) error { prepended := slice.CopyPrepend(keyvals, structure.MessageKey, message) return logger.Log(prepended...) } - -// Record a structured log line with a message and conventional keys -func MsgVals(logger kitlog.Logger, message string, vals ...interface{}) error { - keyvals := make([]interface{}, len(vals)*2) - for i := 0; i < len(vals); i++ { - kv := i * 2 - keyvals[kv] = structure.KeyFromValue(vals[i]) - keyvals[kv+1] = vals[i] - } - return Msg(logger, message, keyvals) -} diff --git a/logging/lifecycle/lifecycle.go b/logging/lifecycle/lifecycle.go index 4a5e1235d3a4a6720e62732da2d6d99b137d097f..ab1c4f540fd9c0bcb66cd3ba260d732e40c4b0e4 100644 --- a/logging/lifecycle/lifecycle.go +++ b/logging/lifecycle/lifecycle.go @@ -23,10 +23,12 @@ import ( "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/adapters/stdlib" tmLog15adapter "github.com/hyperledger/burrow/logging/adapters/tendermint_log15" + "github.com/hyperledger/burrow/logging/config" "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/logging/structure" kitlog "github.com/go-kit/kit/log" + "github.com/hyperledger/burrow/logging/types" "github.com/streadway/simpleuuid" tmLog15 "github.com/tendermint/log15" ) @@ -35,22 +37,39 @@ import ( // 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 { - return NewStdErrLogger() +func NewLoggerFromLoggingConfig(loggingConfig *config.LoggingConfig) (types.InfoTraceLogger, error) { + if loggingConfig == nil { + return NewStdErrLogger(), nil + } + infoOnlyLogger, infoAndTraceLogger, err := infoTraceLoggersFromLoggingConfig(loggingConfig) + if err != nil { + return nil, err + } + return NewLogger(infoOnlyLogger, infoAndTraceLogger), nil +} + +// 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 { + infoOnlyLogger, infoAndTraceLogger, err := infoTraceLoggersFromLoggingConfig(loggingConfig) + if err != nil { + return err + } + logger.SwapInfoOnlyOutput(infoOnlyLogger) + logger.SwapInfoAndTraceOutput(infoAndTraceLogger) + return nil } -func NewStdErrLogger() loggers.InfoTraceLogger { - logger := tmLog15adapter.Log15HandlerAsKitLogger( - tmLog15.StreamHandler(os.Stderr, tmLog15.TerminalFormat())) - return NewLogger(logger, logger) +func NewStdErrLogger() types.InfoTraceLogger { + logger := loggers.NewStreamLogger(os.Stderr, "terminal") + return NewLogger(nil, logger) } -// Provided a standard burrow logger that outputs to the supplied underlying info and trace -// loggers -func NewLogger(infoLogger, traceLogger kitlog.Logger) loggers.InfoTraceLogger { - infoTraceLogger := loggers.NewInfoTraceLogger( - loggers.MonaxFormatLogger(infoLogger), - loggers.MonaxFormatLogger(traceLogger)) +// Provided a standard logger that outputs to the supplied underlying info +// and trace loggers +func NewLogger(infoOnlyLogger, infoAndTraceLogger kitlog.Logger) types.InfoTraceLogger { + infoTraceLogger := loggers.NewInfoTraceLogger(infoOnlyLogger, infoAndTraceLogger) // Create a random ID based on start time uuid, _ := simpleuuid.NewTime(time.Now()) var runId string @@ -60,13 +79,26 @@ func NewLogger(infoLogger, traceLogger kitlog.Logger) loggers.InfoTraceLogger { return logging.WithMetadata(infoTraceLogger.With(structure.RunId, runId)) } -func CaptureTendermintLog15Output(infoTraceLogger loggers.InfoTraceLogger) { +func CaptureTendermintLog15Output(infoTraceLogger types.InfoTraceLogger) { tmLog15.Root().SetHandler( tmLog15adapter.InfoTraceLoggerAsLog15Handler(infoTraceLogger. With(structure.CapturedLoggingSourceKey, "tendermint_log15"))) } -func CaptureStdlibLogOutput(infoTraceLogger loggers.InfoTraceLogger) { +func CaptureStdlibLogOutput(infoTraceLogger types.InfoTraceLogger) { stdlib.CaptureRootLogger(infoTraceLogger. With(structure.CapturedLoggingSourceKey, "stdlib_log")) } + +// Helpers +func infoTraceLoggersFromLoggingConfig(loggingConfig *config.LoggingConfig) (kitlog.Logger, kitlog.Logger, error) { + infoOnlyLogger, _, err := loggingConfig.InfoSink.BuildLogger() + if err != nil { + return nil, nil, err + } + infoAndTraceLogger, _, err := loggingConfig.InfoAndTraceSink.BuildLogger() + if err != nil { + return nil, nil, err + } + return infoOnlyLogger, infoAndTraceLogger, nil +} diff --git a/logging/lifecycle/lifecycle_test.go b/logging/lifecycle/lifecycle_test.go new file mode 100644 index 0000000000000000000000000000000000000000..bacb97ebe5924c85dba533da224018e3c559efe5 --- /dev/null +++ b/logging/lifecycle/lifecycle_test.go @@ -0,0 +1,14 @@ +package lifecycle + +import ( + "runtime" + "testing" + "time" +) + +func TestNewStdErrLogger(t *testing.T) { + logger := NewStdErrLogger() + logger.Info("Quick", "Test") + time.Sleep(time.Second) + runtime.Gosched() +} diff --git a/logging/loggers/eris_format_logger.go b/logging/loggers/burrow_format_logger.go similarity index 87% rename from logging/loggers/eris_format_logger.go rename to logging/loggers/burrow_format_logger.go index e9d65d3c8b9e04d3427d75221e55a44d04cb7754..ec522b3d896495e052616007d7eaa578d4c60961 100644 --- a/logging/loggers/eris_format_logger.go +++ b/logging/loggers/burrow_format_logger.go @@ -34,6 +34,13 @@ type burrowFormatLogger struct { var _ kitlog.Logger = &burrowFormatLogger{} func (efl *burrowFormatLogger) Log(keyvals ...interface{}) error { + if efl.logger == nil { + return nil + } + if len(keyvals)%2 != 0 { + return fmt.Errorf("Log line contains an odd number of elements so "+ + "was dropped: %v", keyvals) + } return efl.logger.Log(structure.MapKeyValues(keyvals, burrowFormatKeyValueMapper)...) } @@ -48,6 +55,6 @@ func burrowFormatKeyValueMapper(key, value interface{}) (interface{}, interface{ return key, value } -func MonaxFormatLogger(logger kitlog.Logger) *burrowFormatLogger { +func BurrowFormatLogger(logger kitlog.Logger) *burrowFormatLogger { return &burrowFormatLogger{logger: logger} } diff --git a/logging/loggers/capture_logger.go b/logging/loggers/capture_logger.go new file mode 100644 index 0000000000000000000000000000000000000000..e195c3a454c24fdd9d8056cf937197a27642b7a5 --- /dev/null +++ b/logging/loggers/capture_logger.go @@ -0,0 +1,85 @@ +package loggers + +import ( + "sync" + + "github.com/eapache/channels" + kitlog "github.com/go-kit/kit/log" +) + +type CaptureLogger struct { + bufferLogger *ChannelLogger + outputLogger kitlog.Logger + passthrough bool + sync.RWMutex +} + +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. +// 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 { + return &CaptureLogger{ + bufferLogger: NewChannelLogger(bufferCap), + outputLogger: outputLogger, + passthrough: passthrough, + } +} + +func (cl *CaptureLogger) Log(keyvals ...interface{}) error { + err := cl.bufferLogger.Log(keyvals...) + if cl.Passthrough() { + err = cl.outputLogger.Log(keyvals...) + } + return err +} + +// 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.passthrough = passthrough + cl.RWMutex.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() + passthrough := cl.passthrough + cl.RWMutex.RUnlock() + return passthrough +} + +// Flushes every log line available in the buffer at the time of calling +// to the OutputLogger and returns. Does not block indefinitely. +// +// Note: will remove log lines from buffer so they will not be produced on any +// subsequent flush of buffer +func (cl *CaptureLogger) Flush() { + cl.bufferLogger.Flush(cl.outputLogger) +} + +// Flushes every log line available in the buffer at the time of calling +// to a slice and returns it. Does not block indefinitely. +// +// Note: will remove log lines from buffer so they will not be produced on any +// subsequent flush of buffer +func (cl *CaptureLogger) FlushLogLines() [][]interface{} { + return cl.bufferLogger.FlushLogLines() +} + +// The OutputLogger whose input this CaptureLogger is capturing +func (cl *CaptureLogger) OutputLogger() kitlog.Logger { + return cl.outputLogger +} + +// The BufferLogger where the input into these CaptureLogger is stored in a ring +// buffer of log lines. +func (cl *CaptureLogger) BufferLogger() *ChannelLogger { + return cl.bufferLogger +} diff --git a/logging/loggers/capture_logger_test.go b/logging/loggers/capture_logger_test.go new file mode 100644 index 0000000000000000000000000000000000000000..d6caea72cadaf5ee23665d0a7e32f4a0387adbe4 --- /dev/null +++ b/logging/loggers/capture_logger_test.go @@ -0,0 +1,49 @@ +package loggers + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestFlushCaptureLogger(t *testing.T) { + outputLogger := newTestLogger() + cl := NewCaptureLogger(outputLogger, 100, false) + buffered := 50 + for i := 0; i < buffered; i++ { + cl.Log("Foo", "Bar", "Index", i) + } + assert.True(t, outputLogger.empty()) + + // Flush the ones we bufferred + cl.Flush() + _, err := outputLogger.logLines(buffered) + assert.NoError(t, err) +} + +func TestTeeCaptureLogger(t *testing.T) { + outputLogger := newTestLogger() + cl := NewCaptureLogger(outputLogger, 100, true) + buffered := 50 + for i := 0; i < buffered; i++ { + cl.Log("Foo", "Bar", "Index", i) + } + // Check passthrough to output + ll, err := outputLogger.logLines(buffered) + assert.NoError(t, err) + assert.Equal(t, ll, cl.BufferLogger().FlushLogLines()) + + cl.SetPassthrough(false) + buffered = 110 + for i := 0; i < buffered; i++ { + cl.Log("Foo", "Bar", "Index", i) + } + assert.True(t, outputLogger.empty()) + + cl.Flush() + _, err = outputLogger.logLines(100) + assert.NoError(t, err) + _, err = outputLogger.logLines(1) + // Expect timeout + assert.Error(t, err) +} diff --git a/logging/loggers/channel_logger.go b/logging/loggers/channel_logger.go index 1bacfa44697847389ab8b689f0a672cb3a3fa53b..da26a81ba6415da11fb4753a4eb4254e89871dc0 100644 --- a/logging/loggers/channel_logger.go +++ b/logging/loggers/channel_logger.go @@ -15,73 +15,131 @@ package loggers import ( + "sync" + "github.com/eapache/channels" kitlog "github.com/go-kit/kit/log" ) const ( - LoggingRingBufferCap channels.BufferCap = 100 + DefaultLoggingRingBufferCap channels.BufferCap = 100 ) type ChannelLogger struct { ch channels.Channel + sync.RWMutex } var _ kitlog.Logger = (*ChannelLogger)(nil) -// Creates a Logger that uses a uses a non-blocking channel. -// -// We would like calls to Log to never block so we use a channel implementation -// that is non-blocking on writes and is able to be so by using a finite ring -// buffer. -func newChannelLogger() *ChannelLogger { +// Creates a Logger that uses a uses a non-blocking ring buffered channel. +// This logger provides a common abstraction for both a buffered, flushable +// logging cache. And a non-blocking conduit to transmit logs via +// DrainForever (or NonBlockingLogger). +func NewChannelLogger(loggingRingBufferCap channels.BufferCap) *ChannelLogger { return &ChannelLogger{ - ch: channels.NewRingChannel(LoggingRingBufferCap), + ch: channels.NewRingChannel(loggingRingBufferCap), } } func (cl *ChannelLogger) Log(keyvals ...interface{}) error { + // In case channel is being reset + cl.RWMutex.RLock() cl.ch.In() <- keyvals + cl.RWMutex.RUnlock() // We don't have a way to pass on any logging errors, but that's okay: Log is // a maximal interface and the error return type is only there for special // cases. return nil } +// Get the current occupancy level of the ring buffer +func (cl *ChannelLogger) BufferLength() int { + return cl.ch.Len() +} + +// Get the cap off the internal ring buffer +func (cl *ChannelLogger) BufferCap() channels.BufferCap { + return cl.ch.Cap() +} + // Read a log line by waiting until one is available and returning it func (cl *ChannelLogger) WaitReadLogLine() []interface{} { - log := <-cl.ch.Out() - // We are passing slices of interfaces down this channel (go-kit log's Log - // interface type), a panic is the right thing to do if this type assertion - // fails. - return log.([]interface{}) + logLine, ok := <-cl.ch.Out() + return readLogLine(logLine, ok) } // Tries to read a log line from the channel buffer or returns nil if none is // immediately available func (cl *ChannelLogger) ReadLogLine() []interface{} { select { - case log := <-cl.ch.Out(): - // See WaitReadLogLine - return log.([]interface{}) + case logLine, ok := <-cl.ch.Out(): + return readLogLine(logLine, ok) default: return nil } } +func readLogLine(logLine interface{}, ok bool) []interface{} { + if !ok { + // Channel closed + return nil + } + // We are passing slices of interfaces down this channel (go-kit log's Log + // interface type), a panic is the right thing to do if this type assertion + // fails. + return logLine.([]interface{}) +} + // Enters an infinite loop that will drain any log lines from the passed logger. // // Exits if the channel is closed. -func (cl *ChannelLogger) DrainChannelToLogger(logger kitlog.Logger) { - for cl.ch.Out() != nil { - logger.Log(cl.WaitReadLogLine()...) +func (cl *ChannelLogger) DrainForever(logger kitlog.Logger) { + // logLine could be nil if channel was closed while waiting for next line + for logLine := cl.WaitReadLogLine(); logLine != nil; logLine = cl.WaitReadLogLine() { + logger.Log(logLine...) + } +} + +// Drains everything that is available at the time of calling +func (cl *ChannelLogger) Flush(logger kitlog.Logger) { + // Grab the buffer at the here rather than within loop condition so that we + // do not drain the buffer forever + bufferLength := cl.BufferLength() + for i := 0; i < bufferLength; i++ { + logLine := cl.WaitReadLogLine() + if logLine != nil { + logger.Log(logLine...) + } } } -// Wraps an underlying Logger baseLogger to provide a Logger that is -// is non-blocking on calls to Log. -func NonBlockingLogger(logger kitlog.Logger) *ChannelLogger { - cl := newChannelLogger() - go cl.DrainChannelToLogger(logger) +// Drains the next contiguous segment of loglines up to the buffer cap waiting +// for at least one line +func (cl *ChannelLogger) FlushLogLines() [][]interface{} { + logLines := make([][]interface{}, 0, cl.ch.Len()) + cl.Flush(kitlog.LoggerFunc(func(keyvals ...interface{}) error { + logLines = append(logLines, keyvals) + return nil + })) + return logLines +} + +// Close the existing channel halting goroutines that are draining the channel +// and create a new channel to buffer into. Should not cause any log lines +// arriving concurrently to be lost, but any that have not been drained from +// old channel may be. +func (cl *ChannelLogger) Reset() { + cl.RWMutex.Lock() + cl.ch.Close() + cl.ch = channels.NewRingChannel(cl.ch.Cap()) + cl.RWMutex.Unlock() +} + +// Returns a Logger that wraps the outputLogger passed and does not block on +// calls to Log. +func NonBlockingLogger(outputLogger kitlog.Logger) *ChannelLogger { + cl := NewChannelLogger(DefaultLoggingRingBufferCap) + go cl.DrainForever(outputLogger) return cl } diff --git a/logging/loggers/channel_logger_test.go b/logging/loggers/channel_logger_test.go index 0573556e15f70b11ec1163e36ab5435106e612ab..0badbde119f5365180637a7355ffe7e47b7ceab9 100644 --- a/logging/loggers/channel_logger_test.go +++ b/logging/loggers/channel_logger_test.go @@ -17,21 +17,23 @@ package loggers import ( "testing" - "fmt" + "time" + "github.com/eapache/channels" "github.com/stretchr/testify/assert" ) func TestChannelLogger(t *testing.T) { - cl := newChannelLogger() + loggingRingBufferCap := channels.BufferCap(5) + cl := NewChannelLogger(loggingRingBufferCap) // Push a larger number of log messages than will fit into ring buffer - for i := 0; i < int(LoggingRingBufferCap)+10; i++ { + for i := 0; i < int(loggingRingBufferCap)+10; i++ { cl.Log("log line", i) } // Observe that oldest 10 messages are overwritten (so first message is 10) - for i := 0; i < int(LoggingRingBufferCap); i++ { + for i := 0; i < int(loggingRingBufferCap); i++ { ll := cl.WaitReadLogLine() assert.Equal(t, 10+i, ll[1]) } @@ -40,8 +42,35 @@ func TestChannelLogger(t *testing.T) { "should be no more log lines.") } -func TestBlether(t *testing.T) { - var bs []byte - ext := append(bs) - fmt.Println(ext) +func TestChannelLogger_Reset(t *testing.T) { + loggingRingBufferCap := channels.BufferCap(5) + cl := NewChannelLogger(loggingRingBufferCap) + for i := 0; i < int(loggingRingBufferCap); i++ { + cl.Log("log line", i) + } + cl.Reset() + for i := 0; i < int(loggingRingBufferCap); i++ { + cl.Log("log line", i) + } + for i := 0; i < int(loggingRingBufferCap); i++ { + ll := cl.WaitReadLogLine() + assert.Equal(t, i, ll[1]) + } + assert.Nil(t, cl.ReadLogLine(), "Since we have drained the buffer there "+ + "should be no more log lines.") +} + +func TestNonBlockingLogger(t *testing.T) { + tl := newTestLogger() + nbl := NonBlockingLogger(tl) + nbl.Log("Foo", "Bar") + nbl.Log("Baz", "Bur") + nbl.Log("Badger", "Romeo") + time.Sleep(time.Second) + + lls, err := tl.logLines(3) + assert.NoError(t, err) + assert.Equal(t, logLines("Foo", "Bar", "", + "Baz", "Bur", "", + "Badger", "Romeo"), lls) } diff --git a/logging/loggers/filter_logger.go b/logging/loggers/filter_logger.go new file mode 100644 index 0000000000000000000000000000000000000000..ba9e542f525c41ec0b54b1b8e292ee2e22134ab6 --- /dev/null +++ b/logging/loggers/filter_logger.go @@ -0,0 +1,28 @@ +package loggers + +import kitlog "github.com/go-kit/kit/log" + +// Filter logger allows us to filter lines logged to it before passing on to underlying +// output logger +type filterLogger struct { + logger kitlog.Logger + predicate func(keyvals []interface{}) bool +} + +var _ kitlog.Logger = (*filterLogger)(nil) + +func (fl filterLogger) Log(keyvals ...interface{}) error { + if !fl.predicate(keyvals) { + return fl.logger.Log(keyvals...) + } + return nil +} + +// Creates a logger that removes lines from output when the predicate evaluates true +func NewFilterLogger(outputLogger kitlog.Logger, + predicate func(keyvals []interface{}) bool) kitlog.Logger { + return &filterLogger{ + logger: outputLogger, + predicate: predicate, + } +} diff --git a/logging/loggers/filter_logger_test.go b/logging/loggers/filter_logger_test.go new file mode 100644 index 0000000000000000000000000000000000000000..f200a8276668fd5d88b7a85586ad6f5a40e2e712 --- /dev/null +++ b/logging/loggers/filter_logger_test.go @@ -0,0 +1,18 @@ +package loggers + +import ( + "testing" + + . "github.com/hyperledger/burrow/util/slice" + "github.com/stretchr/testify/assert" +) + +func TestFilterLogger(t *testing.T) { + testLogger := NewChannelLogger(100) + filterLogger := NewFilterLogger(testLogger, func(keyvals []interface{}) bool { + return len(keyvals) > 0 && keyvals[0] == "Spoon" + }) + filterLogger.Log("Fish", "Present") + filterLogger.Log("Spoon", "Present") + assert.Equal(t, [][]interface{}{Slice("Fish", "Present")}, testLogger.FlushLogLines()) +} diff --git a/logging/loggers/graylog_logger.go b/logging/loggers/graylog_logger.go new file mode 100644 index 0000000000000000000000000000000000000000..769cc92bb9e6cfabf5657b2876089e18f79f2dfd --- /dev/null +++ b/logging/loggers/graylog_logger.go @@ -0,0 +1 @@ +package loggers diff --git a/logging/loggers/info_trace_logger.go b/logging/loggers/info_trace_logger.go index 02016a3e44d85c6094284a1a943ed4ddf5cffe6b..2ad14e1d0fee6b4e56cdc1b2fb46ced58f66e070 100644 --- a/logging/loggers/info_trace_logger.go +++ b/logging/loggers/info_trace_logger.go @@ -17,125 +17,94 @@ package loggers import ( kitlog "github.com/go-kit/kit/log" "github.com/hyperledger/burrow/logging/structure" -) - -const ( - InfoChannelName = "Info" - TraceChannelName = "Trace" - - InfoLevelName = InfoChannelName - TraceLevelName = TraceChannelName + "github.com/hyperledger/burrow/logging/types" ) type infoTraceLogger struct { - infoLogger *kitlog.Context - traceLogger *kitlog.Context -} - -// InfoTraceLogger maintains two independent concurrently-safe channels of -// logging. The idea behind the independence is that you can ignore one channel -// with no performance penalty. For more fine grained filtering or aggregation -// the Info and Trace loggers can be decorated loggers that perform arbitrary -// filtering/routing/aggregation on log messages. -type InfoTraceLogger interface { - // Send a log message to the default channel - 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 + infoOnly *kitlog.Context + infoAndTrace *kitlog.Context + infoOnlyOutputLogger *kitlog.SwapLogger + infoAndTraceOutputLogger *kitlog.SwapLogger } // Interface assertions -var _ InfoTraceLogger = (*infoTraceLogger)(nil) -var _ kitlog.Logger = (InfoTraceLogger)(nil) +var _ types.InfoTraceLogger = (*infoTraceLogger)(nil) +var _ kitlog.Logger = (types.InfoTraceLogger)(nil) -func NewInfoTraceLogger(infoLogger, traceLogger kitlog.Logger) InfoTraceLogger { +// Create an InfoTraceLogger by passing the initial ouput loggers. The infoOnlyLogger will only be sent messages from +// the Info channel. The infoAndTraceLogger will be sent messages from both the Info and Trace channels. +func NewInfoTraceLogger(infoOnlyLogger, infoAndTraceLogger kitlog.Logger) types.InfoTraceLogger { // 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. - // We also guard against any concurrency bugs in underlying loggers by feeding - // them from a single channel - logger := kitlog.NewContext(NonBlockingLogger(VectorValuedLogger( - MultipleChannelLogger( - map[string]kitlog.Logger{ - InfoChannelName: infoLogger, - TraceChannelName: traceLogger, - })))) + var infoOnlyOutputLogger, infoAndTraceOutputLogger kitlog.SwapLogger + infoOnlyOutputLogger.Swap(infoOnlyLogger) + infoAndTraceOutputLogger.Swap(infoAndTraceLogger) return &infoTraceLogger{ - infoLogger: logger.With( - structure.ChannelKey, InfoChannelName, - structure.LevelKey, InfoLevelName, + infoOnlyOutputLogger: &infoOnlyOutputLogger, + infoAndTraceOutputLogger: &infoAndTraceOutputLogger, + infoOnly: wrapOutputLogger(&infoOnlyOutputLogger).With( + structure.ChannelKey, types.InfoChannelName, + structure.LevelKey, types.InfoLevelName, ), - traceLogger: logger.With( - structure.ChannelKey, TraceChannelName, - structure.LevelKey, TraceLevelName, + infoAndTrace: wrapOutputLogger(&infoAndTraceOutputLogger).With( + structure.ChannelKey, types.TraceChannelName, + structure.LevelKey, types.TraceLevelName, ), } } -func NewNoopInfoTraceLogger() InfoTraceLogger { - noopLogger := kitlog.NewNopLogger() - return NewInfoTraceLogger(noopLogger, noopLogger) +func NewNoopInfoTraceLogger() types.InfoTraceLogger { + return NewInfoTraceLogger(nil, nil) } -func (l *infoTraceLogger) With(keyvals ...interface{}) InfoTraceLogger { +func (l *infoTraceLogger) With(keyvals ...interface{}) types.InfoTraceLogger { return &infoTraceLogger{ - infoLogger: l.infoLogger.With(keyvals...), - traceLogger: l.traceLogger.With(keyvals...), + infoOnly: l.infoOnly.With(keyvals...), + infoAndTrace: l.infoAndTrace.With(keyvals...), } } -func (l *infoTraceLogger) WithPrefix(keyvals ...interface{}) InfoTraceLogger { +func (l *infoTraceLogger) WithPrefix(keyvals ...interface{}) types.InfoTraceLogger { return &infoTraceLogger{ - infoLogger: l.infoLogger.WithPrefix(keyvals...), - traceLogger: l.traceLogger.WithPrefix(keyvals...), + infoOnly: l.infoOnly.WithPrefix(keyvals...), + infoAndTrace: l.infoAndTrace.WithPrefix(keyvals...), } } func (l *infoTraceLogger) Info(keyvals ...interface{}) error { - // We send Info and Trace log lines down the same pipe to keep them ordered - return l.infoLogger.Log(keyvals...) + // We log Info to the info only + l.infoOnly.Log(keyvals...) + // And pass to infoAndTrace + l.infoAndTrace.Log(keyvals...) + return nil } func (l *infoTraceLogger) Trace(keyvals ...interface{}) error { - return l.traceLogger.Log(keyvals...) + l.infoAndTrace.Log(keyvals...) + return nil +} + +func (l *infoTraceLogger) SwapInfoOnlyOutput(infoLogger kitlog.Logger) { + l.infoOnlyOutputLogger.Swap(infoLogger) +} + +func (l *infoTraceLogger) SwapInfoAndTraceOutput(infoTraceLogger kitlog.Logger) { + l.infoAndTraceOutputLogger.Swap(infoTraceLogger) } // 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 thing of logs from +// 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 { l.Trace(keyvals...) return nil } + +// 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.Context { + return kitlog.NewContext(NonBlockingLogger(BurrowFormatLogger( + VectorValuedLogger(outputLogger)))) +} diff --git a/logging/loggers/info_trace_logger_test.go b/logging/loggers/info_trace_logger_test.go index 1717455401d50c787be69f7a9ee99991c3836366..203ef65e3efcbe1216693361edb66daaecf1894e 100644 --- a/logging/loggers/info_trace_logger_test.go +++ b/logging/loggers/info_trace_logger_test.go @@ -26,3 +26,8 @@ func TestLogger(t *testing.T) { logger := NewInfoTraceLogger(stderrLogger, stderrLogger) logger.Trace("hello", "barry") } + +func TestNewNoopInfoTraceLogger(t *testing.T) { + logger := NewNoopInfoTraceLogger() + logger.Trace("goodbye", "trevor") +} diff --git a/logging/loggers/logging_test.go b/logging/loggers/logging_test.go deleted file mode 100644 index 103d8ddf7c295cd5749e66ea5697c4eaa55791cf..0000000000000000000000000000000000000000 --- a/logging/loggers/logging_test.go +++ /dev/null @@ -1,35 +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 "errors" - -type testLogger struct { - logLines [][]interface{} - err error -} - -func newErrorLogger(errMessage string) *testLogger { - return &testLogger{err: errors.New(errMessage)} -} - -func newTestLogger() *testLogger { - return &testLogger{} -} - -func (tl *testLogger) Log(keyvals ...interface{}) error { - tl.logLines = append(tl.logLines, keyvals) - return tl.err -} diff --git a/logging/loggers/multiple_channel_logger.go b/logging/loggers/multiple_channel_logger.go deleted file mode 100644 index 7e43d93dbf1c79deb9d9a6965a1b1d94eb9c0c25..0000000000000000000000000000000000000000 --- a/logging/loggers/multiple_channel_logger.go +++ /dev/null @@ -1,51 +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 ( - "fmt" - - kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/logging/structure" -) - -// This represents a 'SELECT ONE' type logger. When logged to it will search -// for the ChannelKey field, look that up in its map and send the log line there -// Otherwise logging is a noop (but an error will be returned - which is optional) -type MultipleChannelLogger map[string]kitlog.Logger - -var _ kitlog.Logger = MultipleChannelLogger(nil) - -// Like go-kit log's Log method only logs a message to the specified channelName -// which must be a member of this MultipleChannelLogger -func (mcl MultipleChannelLogger) Log(keyvals ...interface{}) error { - channel := structure.Value(keyvals, structure.ChannelKey) - if channel == nil { - return fmt.Errorf("MultipleChannelLogger could not select channel because"+ - " '%s' was not set in log message", structure.ChannelKey) - } - channelName, ok := channel.(string) - if !ok { - return fmt.Errorf("MultipleChannelLogger could not select channel because"+ - " channel was set to non-string value %v", channel) - } - logger := mcl[channelName] - if logger == nil { - return fmt.Errorf("Could not log to channel '%s', since it is not "+ - "registered with this MultipleChannelLogger (the underlying logger may "+ - "have been nil when passed to NewMultipleChannelLogger)", channelName) - } - return logger.Log(keyvals...) -} diff --git a/logging/loggers/multiple_channel_logger_test.go b/logging/loggers/multiple_channel_logger_test.go deleted file mode 100644 index 237729d8ee87e0af4d79607a94d82bd49e1b664d..0000000000000000000000000000000000000000 --- a/logging/loggers/multiple_channel_logger_test.go +++ /dev/null @@ -1,42 +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 ( - "runtime" - "testing" - "time" - - kitlog "github.com/go-kit/kit/log" - "github.com/hyperledger/burrow/logging/structure" - "github.com/stretchr/testify/assert" -) - -func TestMultipleChannelLogger(t *testing.T) { - boringLogger, interestingLogger := newTestLogger(), newTestLogger() - mcl := kitlog.NewContext(MultipleChannelLogger(map[string]kitlog.Logger{ - "Boring": boringLogger, - "Interesting": interestingLogger, - })) - err := mcl.With("time", kitlog.Valuer(func() interface{} { return "aa" })). - Log(structure.ChannelKey, "Boring", "foo", "bar") - assert.NoError(t, err, "Should log without an error") - // Wait for channel to drain - time.Sleep(time.Second) - runtime.Gosched() - assert.Equal(t, []interface{}{"time", "aa", structure.ChannelKey, "Boring", - "foo", "bar"}, - boringLogger.logLines[0]) -} diff --git a/logging/loggers/multiple_output_logger.go b/logging/loggers/multiple_output_logger.go index 89ae50a978964758ead7891c5e79ece832cd87ce..143160247e681d1be61da1433825e8be9d5107d1 100644 --- a/logging/loggers/multiple_output_logger.go +++ b/logging/loggers/multiple_output_logger.go @@ -39,7 +39,16 @@ func (mol MultipleOutputLogger) Log(keyvals ...interface{}) error { // Creates a logger that forks log messages to each of its outputLoggers func NewMultipleOutputLogger(outputLoggers ...kitlog.Logger) kitlog.Logger { - return MultipleOutputLogger(outputLoggers) + moLogger := make(MultipleOutputLogger, 0, len(outputLoggers)) + // Flatten any MultipleOutputLoggers + for _, ol := range outputLoggers { + if ls, ok := ol.(MultipleOutputLogger); ok { + moLogger = append(moLogger, ls...) + } else { + moLogger = append(moLogger, ol) + } + } + return moLogger } type multipleErrors []error diff --git a/logging/loggers/multiple_output_logger_test.go b/logging/loggers/multiple_output_logger_test.go index 4f606376af8c44d8441bbb33d6d49d322138a833..d310328bd0546ebb48cb10d4f14bd8a3b0cb64f0 100644 --- a/logging/loggers/multiple_output_logger_test.go +++ b/logging/loggers/multiple_output_logger_test.go @@ -24,9 +24,13 @@ func TestNewMultipleOutputLogger(t *testing.T) { a, b := newErrorLogger("error a"), newErrorLogger("error b") mol := NewMultipleOutputLogger(a, b) logLine := []interface{}{"msg", "hello"} - err := mol.Log(logLine...) + errLog := mol.Log(logLine...) expected := [][]interface{}{logLine} - assert.Equal(t, expected, a.logLines) - assert.Equal(t, expected, b.logLines) - assert.IsType(t, multipleErrors{}, err) + logLineA, err := a.logLines(1) + assert.NoError(t, err) + logLineB, err := b.logLines(1) + assert.NoError(t, err) + assert.Equal(t, expected, logLineA) + assert.Equal(t, expected, logLineB) + assert.IsType(t, multipleErrors{}, errLog) } diff --git a/logging/loggers/shared_test.go b/logging/loggers/shared_test.go new file mode 100644 index 0000000000000000000000000000000000000000..86783f49c858455216e1de49818de3dce95b56e6 --- /dev/null +++ b/logging/loggers/shared_test.go @@ -0,0 +1,81 @@ +package loggers + +import ( + "errors" + "fmt" + "time" + + kitlog "github.com/go-kit/kit/log" +) + +const logLineTimeout time.Duration = time.Second + +type testLogger struct { + channelLogger *ChannelLogger + logLineCh chan ([]interface{}) + err error +} + +func (tl *testLogger) empty() bool { + return tl.channelLogger.BufferLength() == 0 +} + +func (tl *testLogger) logLines(numberOfLines int) ([][]interface{}, error) { + logLines := make([][]interface{}, numberOfLines) + for i := 0; i < numberOfLines; i++ { + select { + case logLine := <-tl.logLineCh: + logLines[i] = logLine + case <-time.After(logLineTimeout): + return logLines, fmt.Errorf("Timed out waiting for log line "+ + "(waited %s)", logLineTimeout) + } + } + return logLines, nil +} + +func (tl *testLogger) Log(keyvals ...interface{}) error { + tl.channelLogger.Log(keyvals...) + return tl.err +} + +func newErrorLogger(errMessage string) *testLogger { + return makeTestLogger(errors.New(errMessage)) +} + +func newTestLogger() *testLogger { + return makeTestLogger(nil) +} + +func makeTestLogger(err error) *testLogger { + cl := NewChannelLogger(100) + logLineCh := make(chan ([]interface{})) + go cl.DrainForever(kitlog.LoggerFunc(func(keyvals ...interface{}) error { + logLineCh <- keyvals + return nil + })) + return &testLogger{ + channelLogger: cl, + logLineCh: logLineCh, + err: err, + } +} + +// Takes a variadic argument of log lines as a list of key value pairs delimited +// by the empty string +func logLines(keyvals ...string) [][]interface{} { + llines := make([][]interface{}, 0) + line := make([]interface{}, 0) + for _, kv := range keyvals { + if kv == "" { + llines = append(llines, line) + line = make([]interface{}, 0) + } else { + line = append(line, kv) + } + } + if len(line) > 0 { + llines = append(llines, line) + } + return llines +} diff --git a/logging/loggers/tendermint_log15_loggers.go b/logging/loggers/tendermint_log15_loggers.go new file mode 100644 index 0000000000000000000000000000000000000000..982b232a3c45842b3da28d96654a4aba45dede54 --- /dev/null +++ b/logging/loggers/tendermint_log15_loggers.go @@ -0,0 +1,54 @@ +package loggers + +import ( + "io" + + "log/syslog" + "net/url" + + kitlog "github.com/go-kit/kit/log" + log15a "github.com/hyperledger/burrow/logging/adapters/tendermint_log15" + "github.com/tendermint/log15" +) + +const syslogPriority = syslog.LOG_LOCAL0 + +func NewStreamLogger(writer io.Writer, formatName string) kitlog.Logger { + return log15a.Log15HandlerAsKitLogger(log15.StreamHandler(writer, + format(formatName))) +} + +func NewFileLogger(path string, formatName string) (kitlog.Logger, error) { + handler, err := log15.FileHandler(path, format(formatName)) + return log15a.Log15HandlerAsKitLogger(handler), err +} + +func NewRemoteSyslogLogger(url *url.URL, tag, formatName string) (kitlog.Logger, error) { + handler, err := log15.SyslogNetHandler(url.Scheme, url.Host, syslogPriority, + tag, format(formatName)) + if err != nil { + return nil, err + } + return log15a.Log15HandlerAsKitLogger(handler), nil +} + +func NewSyslogLogger(tag, formatName string) (kitlog.Logger, error) { + handler, err := log15.SyslogHandler(syslogPriority, tag, format(formatName)) + if err != nil { + return nil, err + } + return log15a.Log15HandlerAsKitLogger(handler), nil +} + +func format(name string) log15.Format { + switch name { + case "json": + return log15.JsonFormat() + case "logfmt": + return log15.LogfmtFormat() + case "terminal": + return log15.TerminalFormat() + default: + return log15.LogfmtFormat() + } +} diff --git a/logging/loggers/vector_valued_logger_test.go b/logging/loggers/vector_valued_logger_test.go index a9e66ffc1344a8453b95714a592ffb849f4bb306..62d85f613d04008ee5036202149855163f65835b 100644 --- a/logging/loggers/vector_valued_logger_test.go +++ b/logging/loggers/vector_valued_logger_test.go @@ -25,7 +25,8 @@ func TestVectorValuedLogger(t *testing.T) { logger := newTestLogger() vvl := VectorValuedLogger(logger) vvl.Log("foo", "bar", "seen", 1, "seen", 3, "seen", 2) - + lls, err := logger.logLines(1) + assert.NoError(t, err) assert.Equal(t, Slice("foo", "bar", "seen", Slice(1, 3, 2)), - logger.logLines[0]) + lls[0]) } diff --git a/logging/metadata.go b/logging/metadata.go index 846adf52bd56b3884afb3a18c9c9cd2bd429433f..8d8ca1d32b25ecf59d02c2b57a972b9227db2c49 100644 --- a/logging/metadata.go +++ b/logging/metadata.go @@ -19,8 +19,8 @@ import ( kitlog "github.com/go-kit/kit/log" "github.com/go-stack/stack" - "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/logging/structure" + "github.com/hyperledger/burrow/logging/types" ) const ( @@ -36,12 +36,12 @@ var defaultTimestampUTCValuer kitlog.Valuer = func() interface{} { return time.Now() } -func WithMetadata(infoTraceLogger loggers.InfoTraceLogger) loggers.InfoTraceLogger { +func WithMetadata(infoTraceLogger types.InfoTraceLogger) types.InfoTraceLogger { return infoTraceLogger.With(structure.TimeKey, defaultTimestampUTCValuer, structure.CallerKey, kitlog.Caller(infoTraceLoggerCallDepth), - "trace", TraceValuer()) + structure.TraceKey, TraceValuer()) } func TraceValuer() kitlog.Valuer { - return func() interface{} { return stack.Trace() } + return func() interface{} { return stack.Trace().TrimBelow(stack.Caller(infoTraceLoggerCallDepth - 1)) } } diff --git a/logging/structure/structure.go b/logging/structure/structure.go index 39ea04ae7bf8541245e2d56885fcdd8b23fd7cfd..271d8564a5e266ac0eddfe6abed20c9f42a64207 100644 --- a/logging/structure/structure.go +++ b/logging/structure/structure.go @@ -14,21 +14,19 @@ package structure -import ( - "reflect" - - . "github.com/hyperledger/burrow/util/slice" -) +import . "github.com/hyperledger/burrow/util/slice" const ( // Log time (time.Time) TimeKey = "time" // Call site for log invocation (go-stack.Call) CallerKey = "caller" + // Trace for log call + TraceKey = "trace" // Level name (string) LevelKey = "level" // Channel name in a vector channel logging context - ChannelKey = "channel" + ChannelKey = "log_channel" // Log message (string) MessageKey = "message" // Captured logging source (like tendermint_log15, stdlib_log) @@ -48,6 +46,7 @@ const ( // the unmatched remainder keyvals as context as a slice of key-values. func ValuesAndContext(keyvals []interface{}, keys ...interface{}) (map[interface{}]interface{}, []interface{}) { + vals := make(map[interface{}]interface{}, len(keys)) context := make([]interface{}, len(keyvals)) copy(context, keyvals) @@ -74,6 +73,21 @@ func ValuesAndContext(keyvals []interface{}, return vals, context } +// Drops all key value pairs where the key is in keys +func RemoveKeys(keyvals []interface{}, keys ...interface{}) []interface{} { + keyvalsWithoutKeys := make([]interface{}, 0, len(keyvals)) +NEXT_KEYVAL: + for i := 0; i < 2*(len(keyvals)/2); i += 2 { + for _, key := range keys { + if keyvals[i] == key { + continue NEXT_KEYVAL + } + } + keyvalsWithoutKeys = append(keyvalsWithoutKeys, keyvals[i], keyvals[i+1]) + } + return keyvalsWithoutKeys +} + // Stateful index that tracks the location of a possible vector value type vectorValueindex struct { // Location of the value belonging to a key in output slice @@ -136,18 +150,6 @@ func Value(keyvals []interface{}, key interface{}) interface{} { return nil } -// Obtain a canonical key from a value. Useful for structured logging where the -// type of value alone may be sufficient to determine its key. Providing this -// function centralises any convention over type names -func KeyFromValue(val interface{}) string { - switch val.(type) { - case string: - return "text" - default: - 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)) diff --git a/logging/structure/structure_test.go b/logging/structure/structure_test.go index 29252df91f748b8b4a27c6e287bf5beb2fe56d6f..d7e147356460f27cdec71e8c4f30f28df44687f6 100644 --- a/logging/structure/structure_test.go +++ b/logging/structure/structure_test.go @@ -40,6 +40,7 @@ func TestVectorise(t *testing.T) { ) kvsVector := Vectorise(kvs, "occupation", "scope") + // Vectorise scope assert.Equal(t, Slice( "scope", Slice("lawnmower", "hose pipe", "rake"), "hub", "budub", @@ -48,3 +49,24 @@ func TestVectorise(t *testing.T) { ), kvsVector) } + +func TestRemoveKeys(t *testing.T) { + // Remove multiple of same key + assert.Equal(t, Slice("Fish", 9), + RemoveKeys(Slice("Foo", "Bar", "Fish", 9, "Foo", "Baz", "odd-key"), + "Foo")) + + // Remove multiple different keys + assert.Equal(t, Slice("Fish", 9), + RemoveKeys(Slice("Foo", "Bar", "Fish", 9, "Foo", "Baz", "Bar", 89), + "Foo", "Bar")) + + // Remove nothing but supply keys + assert.Equal(t, Slice("Foo", "Bar", "Fish", 9), + RemoveKeys(Slice("Foo", "Bar", "Fish", 9), + "A", "B", "C")) + + // Remove nothing since no keys supplied + assert.Equal(t, Slice("Foo", "Bar", "Fish", 9), + RemoveKeys(Slice("Foo", "Bar", "Fish", 9))) +} diff --git a/logging/types/info_trace_logger.go b/logging/types/info_trace_logger.go new file mode 100644 index 0000000000000000000000000000000000000000..68e76eb548cbc6e7e9d7524d5320f59190a5093f --- /dev/null +++ b/logging/types/info_trace_logger.go @@ -0,0 +1,66 @@ +package types + +import kitlog "github.com/go-kit/kit/log" + +const ( + InfoChannelName = "Info" + TraceChannelName = "Trace" + + InfoLevelName = InfoChannelName + TraceLevelName = TraceChannelName +) + +// InfoTraceLogger maintains two independent concurrently-safe channels of +// logging. The idea behind the independence is that you can ignore one channel +// with no performance penalty. For more fine grained filtering or aggregation +// the Info and Trace loggers can be decorated loggers that perform arbitrary +// filtering/routing/aggregation on log messages. +type InfoTraceLogger interface { + // Send a log message to the default channel + 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 messages will be sent to + // the infoOnly and the infoAndTrace output loggers. + 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 messages will only be sent to the infoAndTrace output logger. + 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 infoOnlyLogger with another one to re-route messages + // on the Info channel + SwapInfoOnlyOutput(infoOnlyLogger kitlog.Logger) + + // Hot swap the underlying infoAndTraceLogger with another one to re-route messages + // on the Info and Trace channels + SwapInfoAndTraceOutput(infoTraceLogger kitlog.Logger) +} + +// Interface assertions +var _ kitlog.Logger = (InfoTraceLogger)(nil) diff --git a/manager/burrow-mint/burrow-mint.go b/manager/burrow-mint/burrow-mint.go index 92219def5d8cfe35193d0820d5dcca46794b79f1..b54f9f3de5a174c2ff7c86daafbae5e9f585c94b 100644 --- a/manager/burrow-mint/burrow-mint.go +++ b/manager/burrow-mint/burrow-mint.go @@ -25,7 +25,7 @@ import ( wire "github.com/tendermint/go-wire" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" sm "github.com/hyperledger/burrow/manager/burrow-mint/state" manager_types "github.com/hyperledger/burrow/manager/types" @@ -48,7 +48,7 @@ type BurrowMint struct { evsw tendermint_events.EventSwitch nTxs int // count txs in a block - logger loggers.InfoTraceLogger + logger logging_types.InfoTraceLogger } // NOTE [ben] Compiler check to ensure BurrowMint successfully implements @@ -72,7 +72,8 @@ func (app *BurrowMint) GetCheckCache() *sm.BlockCache { return app.checkCache } -func NewBurrowMint(s *sm.State, evsw tendermint_events.EventSwitch, logger loggers.InfoTraceLogger) *BurrowMint { +func NewBurrowMint(s *sm.State, evsw tendermint_events.EventSwitch, + logger logging_types.InfoTraceLogger) *BurrowMint { return &BurrowMint{ state: s, cache: sm.NewBlockCache(s), @@ -107,7 +108,7 @@ func (app *BurrowMint) DeliverTx(txBytes []byte) abci.Result { return abci.NewError(abci.CodeType_EncodingError, fmt.Sprintf("Encoding error: %v", err)) } - err = sm.ExecTx(app.cache, *tx, true, app.evc) + err = sm.ExecTx(app.cache, *tx, true, app.evc, app.logger) if err != nil { return abci.NewError(abci.CodeType_InternalError, fmt.Sprintf("Internal error: %v", err)) } @@ -129,7 +130,7 @@ func (app *BurrowMint) CheckTx(txBytes []byte) abci.Result { } // TODO: map ExecTx errors to sensible abci error codes - err = sm.ExecTx(app.checkCache, *tx, false, nil) + err = sm.ExecTx(app.checkCache, *tx, false, nil, app.logger) if err != nil { return abci.NewError(abci.CodeType_InternalError, fmt.Sprintf("Internal error: %v", err)) } diff --git a/manager/burrow-mint/evm/log.go b/manager/burrow-mint/evm/log.go deleted file mode 100644 index 8b5565197bf62c487aed2852e7c65998cc5a0019..0000000000000000000000000000000000000000 --- a/manager/burrow-mint/evm/log.go +++ /dev/null @@ -1,21 +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 vm - -import ( - "github.com/tendermint/go-logger" -) - -var log = logger.New("module", "vm") diff --git a/manager/burrow-mint/evm/vm.go b/manager/burrow-mint/evm/vm.go index d2c6e88d2be81fdfcee76458e093c5f5b010657d..b5696651ee32187ca19d632b6ce9e8460802c9ea 100644 --- a/manager/burrow-mint/evm/vm.go +++ b/manager/burrow-mint/evm/vm.go @@ -106,12 +106,12 @@ func (vm *VM) SetFireable(evc events.Fireable) { // (unlike in state/execution, where we guarantee HasPermission is called // on known permissions and panics else) // If the perm is not defined in the acc nor set by default in GlobalPermissions, -// prints a log warning and returns false. +// this function returns false. func HasPermission(appState AppState, acc *Account, perm ptypes.PermFlag) bool { v, err := acc.Permissions.Base.Get(perm) if _, ok := err.(ptypes.ErrValueNotSet); ok { if appState == nil { - log.Warn(fmt.Sprintf("\n\n***** Unknown permission %b! ********\n\n", perm)) + // In this case the permission is unknown return false } return HasPermission(nil, appState.GetAccount(ptypes.GlobalPermissionsAddress256), perm) diff --git a/manager/burrow-mint/pipe.go b/manager/burrow-mint/pipe.go index ef3beb33ed07e7e0627828c689f328e11207af52..3830bd0e88b3f8ff7b6684cefb50c8408734fb21 100644 --- a/manager/burrow-mint/pipe.go +++ b/manager/burrow-mint/pipe.go @@ -35,7 +35,7 @@ import ( edb_event "github.com/hyperledger/burrow/event" genesis "github.com/hyperledger/burrow/genesis" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" vm "github.com/hyperledger/burrow/manager/burrow-mint/evm" "github.com/hyperledger/burrow/manager/burrow-mint/state" manager_types "github.com/hyperledger/burrow/manager/types" @@ -57,7 +57,7 @@ type burrowMintPipe struct { // Genesis cache genesisDoc *genesis.GenesisDoc genesisState *state.State - logger loggers.InfoTraceLogger + logger logging_types.InfoTraceLogger } // Interface type assertions @@ -67,7 +67,7 @@ var _ definitions.TendermintPipe = (*burrowMintPipe)(nil) func NewBurrowMintPipe(moduleConfig *config.ModuleConfig, eventSwitch go_events.EventSwitch, - logger loggers.InfoTraceLogger) (*burrowMintPipe, error) { + logger logging_types.InfoTraceLogger) (*burrowMintPipe, error) { startedState, genesisDoc, err := startState(moduleConfig.DataDir, moduleConfig.Config.GetString("db_backend"), moduleConfig.GenesisFile, @@ -177,7 +177,7 @@ func startState(dataDir, backend, genesisFile, chainId string) (*state.State, //------------------------------------------------------------------------------ // Implement definitions.Pipe for burrowMintPipe -func (pipe *burrowMintPipe) Logger() loggers.InfoTraceLogger { +func (pipe *burrowMintPipe) Logger() logging_types.InfoTraceLogger { return pipe.logger } diff --git a/manager/burrow-mint/state/execution.go b/manager/burrow-mint/state/execution.go index 0302a4da477df42714fc87713a2b4227f788ea4f..9fc20e55dcfdfea1d91a4c43ba4ec26e21fb7a28 100644 --- a/manager/burrow-mint/state/execution.go +++ b/manager/burrow-mint/state/execution.go @@ -22,11 +22,13 @@ import ( acm "github.com/hyperledger/burrow/account" "github.com/hyperledger/burrow/common/sanity" core_types "github.com/hyperledger/burrow/core/types" + logging_types "github.com/hyperledger/burrow/logging/types" "github.com/hyperledger/burrow/manager/burrow-mint/evm" ptypes "github.com/hyperledger/burrow/permission/types" // for GlobalPermissionAddress ... "github.com/hyperledger/burrow/txs" . "github.com/hyperledger/burrow/word256" + "github.com/hyperledger/burrow/logging" "github.com/tendermint/go-events" ) @@ -183,7 +185,8 @@ func getInputs(state AccountGetter, ins []*txs.TxInput) (map[string]*acm.Account return accounts, nil } -func getOrMakeOutputs(state AccountGetter, accounts map[string]*acm.Account, outs []*txs.TxOutput) (map[string]*acm.Account, error) { +func getOrMakeOutputs(state AccountGetter, accounts map[string]*acm.Account, + outs []*txs.TxOutput, logger logging_types.InfoTraceLogger) (map[string]*acm.Account, error) { if accounts == nil { accounts = make(map[string]*acm.Account) } @@ -199,7 +202,7 @@ func getOrMakeOutputs(state AccountGetter, accounts map[string]*acm.Account, out // output account may be nil (new) if acc == nil { if !checkedCreatePerms { - if !hasCreateAccountPermission(state, accounts) { + if !hasCreateAccountPermission(state, accounts, logger) { return nil, fmt.Errorf("At least one input does not have permission to create accounts") } checkedCreatePerms = true @@ -316,8 +319,10 @@ func adjustByOutputs(accounts map[string]*acm.Account, outs []*txs.TxOutput) { // If the tx is invalid, an error will be returned. // Unlike ExecBlock(), state will not be altered. -func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable) (err error) { +func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable, + logger logging_types.InfoTraceLogger) (err error) { + logger = logging.WithScope(logger, "ExecTx") // TODO: do something with fees fees := int64(0) _s := blockCache.State() // hack to access validators and block height @@ -331,13 +336,13 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable } // ensure all inputs have send permissions - if !hasSendPermission(blockCache, accounts) { + if !hasSendPermission(blockCache, accounts, logger) { return fmt.Errorf("At least one input lacks permission for SendTx") } // add outputs to accounts map // if any outputs don't exist, all inputs must have CreateAccount perm - accounts, err = getOrMakeOutputs(blockCache, accounts, tx.Outputs) + accounts, err = getOrMakeOutputs(blockCache, accounts, tx.Outputs, logger) if err != nil { return err } @@ -382,41 +387,46 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable // Validate input inAcc = blockCache.GetAccount(tx.Input.Address) if inAcc == nil { - log.Info(fmt.Sprintf("Can't find in account %X", tx.Input.Address)) + logging.InfoMsg(logger, "Cannot find input account", + "tx_input", tx.Input) return txs.ErrTxInvalidAddress } createContract := len(tx.Address) == 0 if createContract { - if !hasCreateContractPermission(blockCache, inAcc) { + if !hasCreateContractPermission(blockCache, inAcc, logger) { return fmt.Errorf("Account %X does not have CreateContract permission", tx.Input.Address) } } else { - if !hasCallPermission(blockCache, inAcc) { + if !hasCallPermission(blockCache, inAcc, logger) { return fmt.Errorf("Account %X does not have Call permission", tx.Input.Address) } } // pubKey should be present in either "inAcc" or "tx.Input" if err := checkInputPubKey(inAcc, tx.Input); err != nil { - log.Info(fmt.Sprintf("Can't find pubkey for %X", tx.Input.Address)) + logging.InfoMsg(logger, "Cannot find public key for input account", + "tx_input", tx.Input) return err } signBytes := acm.SignBytes(_s.ChainID, tx) err := validateInput(inAcc, signBytes, tx.Input) if err != nil { - log.Info(fmt.Sprintf("validateInput failed on %X: %v", tx.Input.Address, err)) + logging.InfoMsg(logger, "validateInput failed", + "tx_input", tx.Input, "error", err) return err } if tx.Input.Amount < tx.Fee { - log.Info(fmt.Sprintf("Sender did not send enough to cover the fee %X", tx.Input.Address)) + logging.InfoMsg(logger, "Sender did not send enough to cover the fee", + "tx_input", tx.Input) return txs.ErrTxInsufficientFunds } if !createContract { // Validate output if len(tx.Address) != 20 { - log.Info(fmt.Sprintf("Destination address is not 20 bytes %X", tx.Address)) + logging.InfoMsg(logger, "Destination address is not 20 bytes", + "address", tx.Address) return txs.ErrTxInvalidAddress } // check if its a native contract @@ -430,7 +440,7 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable outAcc = blockCache.GetAccount(tx.Address) } - log.Info(fmt.Sprintf("Out account: %v", outAcc)) + logger.Trace("output_account", outAcc) // Good! value := tx.Input.Amount - tx.Fee @@ -468,11 +478,13 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable // you have to wait a block to avoid a re-ordering attack // that will take your fees if outAcc == nil { - log.Info(fmt.Sprintf("%X tries to call %X but it does not exist.", - inAcc.Address, tx.Address)) + logging.InfoMsg(logger, "Call to address that does not exist", + "caller_address", inAcc.Address, + "callee_address", tx.Address) } else { - log.Info(fmt.Sprintf("%X tries to call %X but code is blank.", - inAcc.Address, tx.Address)) + logging.InfoMsg(logger, "Call to address that holds no code", + "caller_address", inAcc.Address, + "callee_address", tx.Address) } err = txs.ErrTxInvalidAddress goto CALL_COMPLETE @@ -482,14 +494,18 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable if createContract { // We already checked for permission callee = txCache.CreateAccount(caller) - log.Info(fmt.Sprintf("Created new contract %X", callee.Address)) + logging.TraceMsg(logger, "Created new contract", + "contract_address", callee.Address, + "contract_code", callee.Code) code = tx.Data } else { callee = toVMAccount(outAcc) - log.Info(fmt.Sprintf("Calling contract %X with code %X", callee.Address, callee.Code)) + logging.TraceMsg(logger, "Calling existing contract", + "contract_address", callee.Address, + "contract_code", callee.Code) code = callee.Code } - log.Info(fmt.Sprintf("Code for this contract: %X", code)) + logger.Trace("callee_") // Run VM call and sync txCache to blockCache. { // Capture scope for goto. @@ -502,11 +518,12 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable 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. - log.Info(fmt.Sprintf("Error on execution: %v", err)) + logging.InfoMsg(logger, "Error on execution", + "error", err) goto CALL_COMPLETE } - log.Info("Successful execution") + logging.TraceMsg(logger, "Successful execution") if createContract { callee.Code = ret } @@ -515,8 +532,12 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable CALL_COMPLETE: // err may or may not be nil. - // Create a receipt from the ret and whether errored. - log.Notice("VM call complete", "caller", caller, "callee", callee, "return", ret, "err", err) + // Create a receipt from the ret and whether it erred. + logging.TraceMsg(logger, "VM call complete", + "caller", caller, + "callee", callee, + "return", ret, + "error", err) // Fire Events for sender and receiver // a separate event will be fired from vm for each additional call @@ -548,27 +569,30 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable // Validate input inAcc = blockCache.GetAccount(tx.Input.Address) if inAcc == nil { - log.Info(fmt.Sprintf("Can't find in account %X", tx.Input.Address)) + logging.InfoMsg(logger, "Cannot find input account", + "tx_input", tx.Input) return txs.ErrTxInvalidAddress } // check permission - if !hasNamePermission(blockCache, inAcc) { + if !hasNamePermission(blockCache, inAcc, logger) { return fmt.Errorf("Account %X does not have Name permission", tx.Input.Address) } // pubKey should be present in either "inAcc" or "tx.Input" if err := checkInputPubKey(inAcc, tx.Input); err != nil { - log.Info(fmt.Sprintf("Can't find pubkey for %X", tx.Input.Address)) + logging.InfoMsg(logger, "Cannot find public key for input account", + "tx_input", tx.Input) return err } signBytes := acm.SignBytes(_s.ChainID, tx) err := validateInput(inAcc, signBytes, tx.Input) if err != nil { - log.Info(fmt.Sprintf("validateInput failed on %X: %v", tx.Input.Address, err)) + logging.InfoMsg(logger, "validateInput failed", + "tx_input", tx.Input, "error", err) return err } - // fee is in addition to the amount which is used to determine the TTL if tx.Input.Amount < tx.Fee { - log.Info(fmt.Sprintf("Sender did not send enough to cover the fee %X", tx.Input.Address)) + logging.InfoMsg(logger, "Sender did not send enough to cover the fee", + "tx_input", tx.Input) return txs.ErrTxInsufficientFunds } @@ -584,7 +608,11 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable expiresIn := int(value / costPerBlock) lastBlockHeight := _s.LastBlockHeight - log.Info("New NameTx", "value", value, "costPerBlock", costPerBlock, "expiresIn", expiresIn, "lastBlock", lastBlockHeight) + logging.TraceMsg(logger, "New NameTx", + "value", value, + "cost_per_block", costPerBlock, + "expires_in", expiresIn, + "last_block_height", lastBlockHeight) // check if the name exists entry := blockCache.GetNameRegEntry(tx.Name) @@ -596,7 +624,9 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable if entry.Expires > lastBlockHeight { // ensure we are owner if bytes.Compare(entry.Owner, tx.Input.Address) != 0 { - log.Info(fmt.Sprintf("Sender %X is trying to update a name (%s) for which he is not owner", tx.Input.Address, tx.Name)) + logging.InfoMsg(logger, "Sender is trying to update a name for which they are not an owner", + "sender_address", tx.Input.Address, + "name", tx.Name) return txs.ErrTxPermissionDenied } } else { @@ -607,7 +637,8 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable 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) - log.Info("Removing namereg entry", "name", entry.Name) + logging.TraceMsg(logger, "Removing NameReg entry (no value and empty data in tx requests this)", + "name", entry.Name) blockCache.RemoveNameRegEntry(entry.Name) } else { // update the entry by bumping the expiry @@ -618,7 +649,10 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable } entry.Expires = lastBlockHeight + expiresIn entry.Owner = tx.Input.Address - log.Info("An old namereg entry has expired and been reclaimed", "name", entry.Name, "expiresIn", expiresIn, "owner", entry.Owner) + logging.TraceMsg(logger, "An old NameReg entry has expired and been reclaimed", + "name", entry.Name, + "expires_in", expiresIn, + "owner", entry.Owner) } else { // since the size of the data may have changed // we use the total amount of "credit" @@ -629,7 +663,12 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable return errors.New(fmt.Sprintf("Names must be registered for at least %d blocks", txs.MinNameRegistrationPeriod)) } entry.Expires = lastBlockHeight + expiresIn - log.Info("Updated namereg entry", "name", entry.Name, "expiresIn", expiresIn, "oldCredit", oldCredit, "value", value, "credit", credit) + logging.TraceMsg(logger, "Updated NameReg entry", + "name", entry.Name, + "expires_in", expiresIn, + "old_credit", oldCredit, + "value", value, + "credit", credit) } entry.Data = tx.Data blockCache.UpdateNameRegEntry(entry) @@ -645,7 +684,9 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable Data: tx.Data, Expires: lastBlockHeight + expiresIn, } - log.Info("Creating namereg entry", "name", entry.Name, "expiresIn", expiresIn) + logging.TraceMsg(logger, "Creating NameReg entry", + "name", entry.Name, + "expires_in", expiresIn) blockCache.UpdateNameRegEntry(entry) } @@ -848,31 +889,37 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable // Validate input inAcc = blockCache.GetAccount(tx.Input.Address) if inAcc == nil { - log.Debug(fmt.Sprintf("Can't find in account %X", tx.Input.Address)) + logging.InfoMsg(logger, "Cannot find input account", + "tx_input", tx.Input) return txs.ErrTxInvalidAddress } permFlag := tx.PermArgs.PermFlag() // check permission - if !HasPermission(blockCache, inAcc, permFlag) { + if !HasPermission(blockCache, inAcc, permFlag, logger) { return fmt.Errorf("Account %X does not have moderator permission %s (%b)", tx.Input.Address, ptypes.PermFlagToString(permFlag), permFlag) } // pubKey should be present in either "inAcc" or "tx.Input" if err := checkInputPubKey(inAcc, tx.Input); err != nil { - log.Debug(fmt.Sprintf("Can't find pubkey for %X", tx.Input.Address)) + logging.InfoMsg(logger, "Cannot find public key for input account", + "tx_input", tx.Input) return err } signBytes := acm.SignBytes(_s.ChainID, tx) err := validateInput(inAcc, signBytes, tx.Input) if err != nil { - log.Debug(fmt.Sprintf("validateInput failed on %X: %v", tx.Input.Address, err)) + logging.InfoMsg(logger, "validateInput failed", + "tx_input", tx.Input, + "error", err) return err } value := tx.Input.Amount - log.Debug("New PermissionsTx", "function", ptypes.PermFlagToString(permFlag), "args", tx.PermArgs) + logging.TraceMsg(logger, "New PermissionsTx", + "perm_flag", ptypes.PermFlagToString(permFlag), + "perm_args", tx.PermArgs) var permAcc *acm.Account switch args := tx.PermArgs.(type) { @@ -944,7 +991,8 @@ func ExecTx(blockCache *BlockCache, tx txs.Tx, runCall bool, evc events.Fireable //--------------------------------------------------------------- // Get permission on an account or fall back to global value -func HasPermission(state AccountGetter, acc *acm.Account, perm ptypes.PermFlag) bool { +func HasPermission(state AccountGetter, acc *acm.Account, perm ptypes.PermFlag, + logger logging_types.InfoTraceLogger) bool { if perm > ptypes.AllPermFlags { sanity.PanicSanity("Checking an unknown permission in state should never happen") } @@ -961,55 +1009,67 @@ func HasPermission(state AccountGetter, acc *acm.Account, perm ptypes.PermFlag) if state == nil { sanity.PanicSanity("All known global permissions should be set!") } - log.Info("Permission for account is not set. Querying GlobalPermissionsAddress", "perm", permString) - return HasPermission(nil, state.GetAccount(ptypes.GlobalPermissionsAddress), perm) + logging.TraceMsg(logger, "Permission for account is not set. Querying GlobalPermissionsAddres.", + "perm_flag", permString) + return HasPermission(nil, state.GetAccount(ptypes.GlobalPermissionsAddress), perm, logger) } else if v { - log.Info("Account has permission", "address", fmt.Sprintf("%X", acc.Address), "perm", permString) + logging.TraceMsg(logger, "Account has permission", + "account_address", acc.Address, + "perm_flag", permString) } else { - log.Info("Account does not have permission", "address", fmt.Sprintf("%X", acc.Address), "perm", permString) + logging.TraceMsg(logger, "Account does not have permission", + "account_address", acc.Address, + "perm_flag", permString) } return v } // TODO: for debug log the failed accounts -func hasSendPermission(state AccountGetter, accs map[string]*acm.Account) bool { +func hasSendPermission(state AccountGetter, accs map[string]*acm.Account, + logger logging_types.InfoTraceLogger) bool { for _, acc := range accs { - if !HasPermission(state, acc, ptypes.Send) { + if !HasPermission(state, acc, ptypes.Send, logger) { return false } } return true } -func hasNamePermission(state AccountGetter, acc *acm.Account) bool { - return HasPermission(state, acc, ptypes.Name) +func hasNamePermission(state AccountGetter, acc *acm.Account, + logger logging_types.InfoTraceLogger) bool { + return HasPermission(state, acc, ptypes.Name, logger) } -func hasCallPermission(state AccountGetter, acc *acm.Account) bool { - return HasPermission(state, acc, ptypes.Call) +func hasCallPermission(state AccountGetter, acc *acm.Account, + logger logging_types.InfoTraceLogger) bool { + return HasPermission(state, acc, ptypes.Call, logger) } -func hasCreateContractPermission(state AccountGetter, acc *acm.Account) bool { - return HasPermission(state, acc, ptypes.CreateContract) +func hasCreateContractPermission(state AccountGetter, acc *acm.Account, + logger logging_types.InfoTraceLogger) bool { + return HasPermission(state, acc, ptypes.CreateContract, logger) } -func hasCreateAccountPermission(state AccountGetter, accs map[string]*acm.Account) bool { +func hasCreateAccountPermission(state AccountGetter, accs map[string]*acm.Account, + logger logging_types.InfoTraceLogger) bool { for _, acc := range accs { - if !HasPermission(state, acc, ptypes.CreateAccount) { + if !HasPermission(state, acc, ptypes.CreateAccount, logger) { return false } } return true } -func hasBondPermission(state AccountGetter, acc *acm.Account) bool { - return HasPermission(state, acc, ptypes.Bond) +func hasBondPermission(state AccountGetter, acc *acm.Account, + logger logging_types.InfoTraceLogger) bool { + return HasPermission(state, acc, ptypes.Bond, logger) } -func hasBondOrSendPermission(state AccountGetter, accs map[string]*acm.Account) bool { +func hasBondOrSendPermission(state AccountGetter, accs map[string]*acm.Account, + logger logging_types.InfoTraceLogger) bool { for _, acc := range accs { - if !HasPermission(state, acc, ptypes.Bond) { - if !HasPermission(state, acc, ptypes.Send) { + if !HasPermission(state, acc, ptypes.Bond, logger) { + if !HasPermission(state, acc, ptypes.Send, logger) { return false } } diff --git a/manager/burrow-mint/state/log.go b/manager/burrow-mint/state/log.go deleted file mode 100644 index d8e71b796dd6dc0599c7bebea5257b0a2283c1d7..0000000000000000000000000000000000000000 --- a/manager/burrow-mint/state/log.go +++ /dev/null @@ -1,21 +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 state - -import ( - "github.com/tendermint/go-logger" -) - -var log = logger.New("module", "state") diff --git a/manager/burrow-mint/state/permissions_test.go b/manager/burrow-mint/state/permissions_test.go index 51d52e4e4b258e0803c9e21ffda71f742f2b783f..dd812410f4939715c102e78d4239dd28f72ae978 100644 --- a/manager/burrow-mint/state/permissions_test.go +++ b/manager/burrow-mint/state/permissions_test.go @@ -29,6 +29,7 @@ import ( "github.com/hyperledger/burrow/txs" . "github.com/hyperledger/burrow/word256" + "github.com/hyperledger/burrow/logging/lifecycle" "github.com/tendermint/go-crypto" dbm "github.com/tendermint/go-db" "github.com/tendermint/go-events" @@ -109,6 +110,7 @@ x - roles: has, add, rm // keys var user = makeUsers(10) var chainID = "testchain" +var logger = lifecycle.NewStdErrLogger() func makeUsers(n int) []*acm.PrivAccount { accounts := []*acm.PrivAccount{} @@ -175,7 +177,7 @@ func TestSendFails(t *testing.T) { } tx.AddOutput(user[1].Address, 5) tx.SignInput(chainID, 0, user[0]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -188,7 +190,7 @@ func TestSendFails(t *testing.T) { } tx.AddOutput(user[4].Address, 5) tx.SignInput(chainID, 0, user[2]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -201,7 +203,7 @@ func TestSendFails(t *testing.T) { } tx.AddOutput(user[4].Address, 5) tx.SignInput(chainID, 0, user[3]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -217,7 +219,7 @@ func TestSendFails(t *testing.T) { } tx.AddOutput(user[6].Address, 5) tx.SignInput(chainID, 0, user[3]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -241,7 +243,7 @@ func TestName(t *testing.T) { t.Fatal(err) } tx.Sign(chainID, user[0]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -253,7 +255,7 @@ func TestName(t *testing.T) { t.Fatal(err) } tx.Sign(chainID, user[1]) - if err := ExecTx(blockCache, tx, true, nil); err != nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err != nil { t.Fatal(err) } } @@ -273,7 +275,7 @@ func TestCallFails(t *testing.T) { // simple call tx should fail tx, _ := txs.NewCallTx(blockCache, user[0].PubKey, user[4].Address, nil, 100, 100, 100) tx.Sign(chainID, user[0]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -282,7 +284,7 @@ func TestCallFails(t *testing.T) { // simple call tx with send permission should fail tx, _ = txs.NewCallTx(blockCache, user[1].PubKey, user[4].Address, nil, 100, 100, 100) tx.Sign(chainID, user[1]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -291,7 +293,7 @@ func TestCallFails(t *testing.T) { // simple call tx with create permission should fail tx, _ = txs.NewCallTx(blockCache, user[3].PubKey, user[4].Address, nil, 100, 100, 100) tx.Sign(chainID, user[3]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -303,7 +305,7 @@ func TestCallFails(t *testing.T) { // simple call create tx should fail tx, _ = txs.NewCallTx(blockCache, user[0].PubKey, nil, nil, 100, 100, 100) tx.Sign(chainID, user[0]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -312,7 +314,7 @@ func TestCallFails(t *testing.T) { // simple call create tx with send perm should fail tx, _ = txs.NewCallTx(blockCache, user[1].PubKey, nil, nil, 100, 100, 100) tx.Sign(chainID, user[1]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -321,7 +323,7 @@ func TestCallFails(t *testing.T) { // simple call create tx with call perm should fail tx, _ = txs.NewCallTx(blockCache, user[2].PubKey, nil, nil, 100, 100, 100) tx.Sign(chainID, user[2]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -342,7 +344,7 @@ func TestSendPermission(t *testing.T) { } tx.AddOutput(user[1].Address, 5) tx.SignInput(chainID, 0, user[0]) - if err := ExecTx(blockCache, tx, true, nil); err != nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err != nil { t.Fatal("Transaction failed", err) } @@ -357,7 +359,7 @@ func TestSendPermission(t *testing.T) { tx.AddOutput(user[2].Address, 10) tx.SignInput(chainID, 0, user[0]) tx.SignInput(chainID, 1, user[1]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -390,7 +392,7 @@ func TestCallPermission(t *testing.T) { // A single input, having the permission, should succeed tx, _ := txs.NewCallTx(blockCache, user[0].PubKey, simpleContractAddr, nil, 100, 100, 100) tx.Sign(chainID, user[0]) - if err := ExecTx(blockCache, tx, true, nil); err != nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err != nil { t.Fatal("Transaction failed", err) } @@ -504,7 +506,7 @@ func TestCreatePermission(t *testing.T) { // A single input, having the permission, should succeed tx, _ := txs.NewCallTx(blockCache, user[0].PubKey, nil, createCode, 100, 100, 100) tx.Sign(chainID, user[0]) - if err := ExecTx(blockCache, tx, true, nil); err != nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err != nil { t.Fatal("Transaction failed", err) } // ensure the contract is there @@ -529,7 +531,7 @@ func TestCreatePermission(t *testing.T) { // A single input, having the permission, should succeed tx, _ = txs.NewCallTx(blockCache, user[0].PubKey, nil, createFactoryCode, 100, 100, 100) tx.Sign(chainID, user[0]) - if err := ExecTx(blockCache, tx, true, nil); err != nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err != nil { t.Fatal("Transaction failed", err) } // ensure the contract is there @@ -747,7 +749,7 @@ func TestCreateAccountPermission(t *testing.T) { } tx.AddOutput(user[6].Address, 5) tx.SignInput(chainID, 0, user[0]) - if err := ExecTx(blockCache, tx, true, nil); err != nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err != nil { t.Fatal("Transaction failed", err) } @@ -762,7 +764,7 @@ func TestCreateAccountPermission(t *testing.T) { tx.AddOutput(user[7].Address, 10) tx.SignInput(chainID, 0, user[0]) tx.SignInput(chainID, 1, user[1]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -780,7 +782,7 @@ func TestCreateAccountPermission(t *testing.T) { tx.AddOutput(user[4].Address, 6) tx.SignInput(chainID, 0, user[0]) tx.SignInput(chainID, 1, user[1]) - if err := ExecTx(blockCache, tx, true, nil); err == nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err == nil { t.Fatal("Expected error") } else { fmt.Println(err) @@ -800,7 +802,7 @@ func TestCreateAccountPermission(t *testing.T) { tx.AddOutput(user[7].Address, 10) tx.SignInput(chainID, 0, user[0]) tx.SignInput(chainID, 1, user[1]) - if err := ExecTx(blockCache, tx, true, nil); err != nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err != nil { t.Fatal("Unexpected error", err) } @@ -816,7 +818,7 @@ func TestCreateAccountPermission(t *testing.T) { tx.AddOutput(user[4].Address, 3) tx.SignInput(chainID, 0, user[0]) tx.SignInput(chainID, 1, user[1]) - if err := ExecTx(blockCache, tx, true, nil); err != nil { + if err := ExecTx(blockCache, tx, true, nil, logger); err != nil { t.Fatal("Unexpected error", err) } @@ -1091,7 +1093,7 @@ func execTxWaitEvent(t *testing.T, blockCache *BlockCache, tx txs.Tx, eventid st }) evc := events.NewEventCache(evsw) go func() { - if err := ExecTx(blockCache, tx, true, evc); err != nil { + if err := ExecTx(blockCache, tx, true, evc, logger); err != nil { ch <- err.Error() } evc.Flush() @@ -1174,7 +1176,7 @@ func testSNativeTx(t *testing.T, expectPass bool, blockCache *BlockCache, perm p } tx, _ := txs.NewPermissionsTx(blockCache, user[0].PubKey, snativeArgs) tx.Sign(chainID, user[0]) - err := ExecTx(blockCache, tx, true, nil) + err := ExecTx(blockCache, tx, true, nil, logger) if expectPass { if err != nil { t.Fatal("Unexpected exception", err) diff --git a/manager/burrow-mint/state/state_test.go b/manager/burrow-mint/state/state_test.go index 7c13e2f7e97a843e218b40799f4339100a35eb5d..c56966b6bdfff4d964ec9885f2a6aa6a871481b7 100644 --- a/manager/burrow-mint/state/state_test.go +++ b/manager/burrow-mint/state/state_test.go @@ -34,7 +34,7 @@ func init() { func execTxWithState(state *State, tx txs.Tx, runCall bool) error { cache := NewBlockCache(state) - if err := ExecTx(cache, tx, runCall, nil); err != nil { + if err := ExecTx(cache, tx, runCall, nil, logger); err != nil { return err } else { cache.Sync() @@ -769,7 +769,7 @@ func TestSuicide(t *testing.T) { // we use cache instead of execTxWithState so we can run the tx twice cache := NewBlockCache(state) - if err := ExecTx(cache, tx, true, nil); err != nil { + if err := ExecTx(cache, tx, true, nil, logger); err != nil { t.Errorf("Got error in executing call transaction, %v", err) } @@ -777,7 +777,7 @@ func TestSuicide(t *testing.T) { // shouldn't happen twice and the caller should lose fee tx.Input.Sequence += 1 tx.Input.Signature = privAccounts[0].Sign(state.ChainID, tx) - if err := ExecTx(cache, tx, true, nil); err != nil { + if err := ExecTx(cache, tx, true, nil, logger); err != nil { t.Errorf("Got error in executing call transaction, %v", err) } diff --git a/manager/manager.go b/manager/manager.go index 4ec72bd6d79494cd4c44bfddc04dcd30a2f28d16..eac62048434dc39ff5c16946dd61130585d4587f 100644 --- a/manager/manager.go +++ b/manager/manager.go @@ -22,10 +22,9 @@ import ( config "github.com/hyperledger/burrow/config" definitions "github.com/hyperledger/burrow/definitions" burrowmint "github.com/hyperledger/burrow/manager/burrow-mint" - // types "github.com/hyperledger/burrow/manager/types" "github.com/hyperledger/burrow/logging" - "github.com/hyperledger/burrow/logging/loggers" + logging_types "github.com/hyperledger/burrow/logging/types" ) // NewApplicationPipe returns an initialised Pipe interface @@ -34,7 +33,7 @@ import ( // of an application. It is feasible this will be insufficient to support // different types of applications later down the line. func NewApplicationPipe(moduleConfig *config.ModuleConfig, - evsw events.EventSwitch, logger loggers.InfoTraceLogger, + evsw events.EventSwitch, logger logging_types.InfoTraceLogger, consensusMinorVersion string) (definitions.Pipe, error) { switch moduleConfig.Name { diff --git a/rpc/tendermint/test/config.go b/rpc/tendermint/test/config.go index 8bc31bf8cb340b97ab35e0f3708720ab5aeeb40c..6bed860535a00dc86e982a7c1ec32091e32038fa 100644 --- a/rpc/tendermint/test/config.go +++ b/rpc/tendermint/test/config.go @@ -119,11 +119,6 @@ genesis_file = "genesis.json" rpc_local_address = "0.0.0.0:36657" endpoint = "/websocket" - [servers.logging] - console_log_level = "info" - file_log_level = "warn" - log_file = "" - ################################################################################ ################################################################################ ## diff --git a/rpc/tendermint/test/rpc_client_test.go b/rpc/tendermint/test/rpc_client_test.go index fc554ae9ae972f815db0af00c5820e0c2d337bd4..f7f89827ca4625abaf60ae65eeee8707971aadcf 100644 --- a/rpc/tendermint/test/rpc_client_test.go +++ b/rpc/tendermint/test/rpc_client_test.go @@ -20,10 +20,11 @@ package test import ( "bytes" "fmt" - "golang.org/x/crypto/ripemd160" "testing" "time" + "golang.org/x/crypto/ripemd160" + consensus_types "github.com/hyperledger/burrow/consensus/types" edbcli "github.com/hyperledger/burrow/rpc/tendermint/client" "github.com/hyperledger/burrow/txs" diff --git a/rpc/v0/json_service.go b/rpc/v0/json_service.go index c04120714ba551456ae4d2df0cbcdea59733202e..6cb9f8ca76a724dd37f99dce677bd718a4bdb9ca 100644 --- a/rpc/v0/json_service.go +++ b/rpc/v0/json_service.go @@ -20,7 +20,7 @@ import ( definitions "github.com/hyperledger/burrow/definitions" event "github.com/hyperledger/burrow/event" - rpc "github.com/hyperledger/burrow/rpc" + "github.com/hyperledger/burrow/rpc" server "github.com/hyperledger/burrow/server" "github.com/gin-gonic/gin" diff --git a/rpc/v0/rest_server_pipe_test.go b/rpc/v0/rest_server_pipe_test.go index 52b1863461b4ca7e9ff4b2ffd8cdc6bb2a9c2b53..d949c79ebcde608b2bc91b314b5689d0074f5bef 100644 --- a/rpc/v0/rest_server_pipe_test.go +++ b/rpc/v0/rest_server_pipe_test.go @@ -24,6 +24,7 @@ import ( blockchain_types "github.com/hyperledger/burrow/blockchain/types" consensus_types "github.com/hyperledger/burrow/consensus/types" + logging_types "github.com/hyperledger/burrow/logging/types" manager_types "github.com/hyperledger/burrow/manager/types" "github.com/hyperledger/burrow/txs" @@ -43,7 +44,7 @@ type MockPipe struct { events event.EventEmitter namereg definitions.NameReg transactor definitions.Transactor - logger loggers.InfoTraceLogger + logger logging_types.InfoTraceLogger } // Create a new mock tendermint pipe. @@ -85,7 +86,7 @@ func (pipe *MockPipe) Transactor() definitions.Transactor { return pipe.transactor } -func (pipe *MockPipe) Logger() loggers.InfoTraceLogger { +func (pipe *MockPipe) Logger() logging_types.InfoTraceLogger { return pipe.logger } diff --git a/rpc/v0/rest_server_test.go b/rpc/v0/rest_server_test.go index b488bd25d07c88478a90c66ee58f5b978becaafd..b336d3f8e6fc873884a58bdbca76b76b0480b85c 100644 --- a/rpc/v0/rest_server_test.go +++ b/rpc/v0/rest_server_test.go @@ -33,10 +33,14 @@ import ( "github.com/gin-gonic/gin" "github.com/hyperledger/burrow/rpc/v0/shared" + "github.com/hyperledger/burrow/logging/lifecycle" + logging_types "github.com/hyperledger/burrow/logging/types" "github.com/stretchr/testify/suite" "github.com/tendermint/log15" ) +var logger logging_types.InfoTraceLogger = lifecycle.NewStdErrLogger() + func init() { runtime.GOMAXPROCS(runtime.NumCPU()) log15.Root().SetHandler(log15.LvlFilterHandler( @@ -67,7 +71,7 @@ func (mockSuite *MockSuite) SetupSuite() { sConf := server.DefaultServerConfig() sConf.Bind.Port = 31402 // Create a server process. - proc, _ := server.NewServeProcess(sConf, restServer) + proc, _ := server.NewServeProcess(sConf, logger, restServer) err := proc.Start() if err != nil { panic(err) diff --git a/server/config.go b/server/config.go index 4dcce19dd18199cfbbd19ae0f54bed9554b8db53..7a7a60425c43f9a1305a2b26a243aaefc8cfa4ec 100644 --- a/server/config.go +++ b/server/config.go @@ -30,7 +30,6 @@ type ( HTTP HTTP `toml:"HTTP"` WebSocket WebSocket `toml:"web_socket"` Tendermint Tendermint - Logging Logging `toml:"logging"` } Bind struct { @@ -70,12 +69,6 @@ type ( RpcLocalAddress string Endpoint string } - - Logging struct { - ConsoleLogLevel string `toml:"console_log_level"` - FileLogLevel string `toml:"file_log_level"` - LogFile string `toml:"log_file"` - } ) func ReadServerConfig(viper *viper.Viper) (*ServerConfig, error) { @@ -160,11 +153,6 @@ func ReadServerConfig(viper *viper.Viper) (*ServerConfig, error) { RpcLocalAddress: viper.GetString("tendermint.rpc_local_address"), Endpoint: viper.GetString("tendermint.endpoint"), }, - Logging: Logging{ - ConsoleLogLevel: viper.GetString("logging.console_log_level"), - FileLogLevel: viper.GetString("logging.file_log_level"), - LogFile: viper.GetString("logging.log_file"), - }, }, nil } @@ -194,10 +182,5 @@ func DefaultServerConfig() *ServerConfig { RpcLocalAddress: "0.0.0.0:46657", Endpoint: "/websocket", }, - Logging: Logging{ - ConsoleLogLevel: "info", - FileLogLevel: "warn", - LogFile: "", - }, } } diff --git a/server/log.go b/server/log.go deleted file mode 100644 index 274170d52f91770dddbf830038cc72a6003b5f89..0000000000000000000000000000000000000000 --- a/server/log.go +++ /dev/null @@ -1,21 +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 server - -import ( - "github.com/tendermint/log15" -) - -var log = log15.New("module", "server") diff --git a/server/logging.go b/server/logging.go deleted file mode 100644 index 4a38e0f82d039b18400ec07d1767812e1210c574..0000000000000000000000000000000000000000 --- a/server/logging.go +++ /dev/null @@ -1,73 +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 server - -import ( - "fmt" - "os" - - "github.com/tendermint/log15" -) - -var rootHandler log15.Handler - -// This is basically the same code as in tendermint. Initialize root -// and maybe later also track the loggers here. -func InitLogger(config *ServerConfig) { - - consoleLogLevel := config.Logging.ConsoleLogLevel - - // stdout handler - handlers := []log15.Handler{} - stdoutHandler := log15.LvlFilterHandler( - getLevel(consoleLogLevel), - log15.StreamHandler(os.Stdout, log15.TerminalFormat()), - ) - handlers = append(handlers, stdoutHandler) - - if config.Logging.LogFile != "" { - fileLogLevel := config.Logging.FileLogLevel - fh, err := log15.FileHandler(config.Logging.LogFile, log15.LogfmtFormat()) - if err != nil { - fmt.Println("Error creating log file: " + err.Error()) - os.Exit(1) - } - fileHandler := log15.LvlFilterHandler(getLevel(fileLogLevel), fh) - handlers = append(handlers, fileHandler) - } - - rootHandler = log15.MultiHandler(handlers...) - - // By setting handlers on the root, we handle events from all loggers. - log15.Root().SetHandler(rootHandler) -} - -// See binary/log for an example of usage. -func RootHandler() log15.Handler { - return rootHandler -} - -func New(ctx ...interface{}) log15.Logger { - return log15.Root().New(ctx...) -} - -func getLevel(lvlString string) log15.Lvl { - lvl, err := log15.LvlFromString(lvlString) - if err != nil { - fmt.Printf("Invalid log level %v: %v", lvlString, err) - os.Exit(1) - } - return lvl -} diff --git a/server/server.go b/server/server.go index 28d107eec1740b5cd0ed10fa6bd6d725b0178e73..2a3d7bc7cff5cd21147323b10f1e337021871285 100644 --- a/server/server.go +++ b/server/server.go @@ -22,6 +22,8 @@ import ( "time" "github.com/gin-gonic/gin" + "github.com/hyperledger/burrow/logging" + logging_types "github.com/hyperledger/burrow/logging/types" cors "github.com/tommy351/gin-cors" "gopkg.in/tylerb/graceful.v1" ) @@ -57,19 +59,18 @@ type ServeProcess struct { startListenChans []chan struct{} stopListenChans []chan struct{} srv *graceful.Server + logger logging_types.InfoTraceLogger } // Initializes all the servers and starts listening for connections. -func (this *ServeProcess) Start() error { +func (serveProcess *ServeProcess) Start() error { router := gin.New() - config := this.config - - InitLogger(config) + config := serveProcess.config ch := NewCORSMiddleware(config.CORS) - router.Use(gin.Recovery(), logHandler, contentTypeMW, ch) + router.Use(gin.Recovery(), logHandler(serveProcess.logger), contentTypeMW, ch) address := config.Bind.Address port := config.Bind.Port @@ -86,7 +87,7 @@ func (this *ServeProcess) Start() error { } // Start the servers/handlers. - for _, s := range this.servers { + for _, s := range serveProcess.servers { s.Start(config, router) } @@ -119,15 +120,18 @@ func (this *ServeProcess) Start() error { } else { lst = l } - this.srv = srv - log.Info("Server started.") - for _, c := range this.startListenChans { + serveProcess.srv = srv + logging.InfoMsg(serveProcess.logger, "Server started.", + "chain_id", serveProcess.config.ChainId, + "address", serveProcess.config.Bind.Address, + "port", serveProcess.config.Bind.Port) + for _, c := range serveProcess.startListenChans { c <- struct{}{} } // Start the serve routine. go func() { - this.srv.Serve(lst) - for _, s := range this.servers { + serveProcess.srv.Serve(lst) + for _, s := range serveProcess.servers { s.ShutDown() } }() @@ -135,16 +139,16 @@ func (this *ServeProcess) Start() error { // on the graceful Server. This happens when someone // calls 'Stop' on the process. go func() { - <-this.stopChan - log.Info("Close signal sent to server.") - this.srv.Stop(killTime) + <-serveProcess.stopChan + logging.InfoMsg(serveProcess.logger, "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() { - <-this.srv.StopChan() - log.Info("Server stop event fired. Good bye.") - for _, c := range this.stopListenChans { + <-serveProcess.srv.StopChan() + logging.InfoMsg(serveProcess.logger, "Server stop event fired. Good bye.") + for _, c := range serveProcess.stopListenChans { c <- struct{}{} } }() @@ -154,8 +158,8 @@ func (this *ServeProcess) Start() error { // Stop will release the port, process any remaining requests // up until the timeout duration is passed, at which point it // will abort them and shut down. -func (this *ServeProcess) Stop(timeout time.Duration) error { - for _, s := range this.servers { +func (serveProcess *ServeProcess) Stop(timeout time.Duration) error { + for _, s := range serveProcess.servers { s.ShutDown() } toChan := make(chan struct{}) @@ -166,8 +170,8 @@ func (this *ServeProcess) Stop(timeout time.Duration) error { }() } - lChan := this.StopEventChannel() - this.stopChan <- struct{}{} + lChan := serveProcess.StopEventChannel() + serveProcess.stopChan <- struct{}{} select { case <-lChan: return nil @@ -180,9 +184,9 @@ func (this *ServeProcess) Stop(timeout time.Duration) error { // is fired after the Start() function is called, and after // the server has started listening for incoming connections. // An error here . -func (this *ServeProcess) StartEventChannel() <-chan struct{} { +func (serveProcess *ServeProcess) StartEventChannel() <-chan struct{} { lChan := make(chan struct{}, 1) - this.startListenChans = append(this.startListenChans, lChan) + serveProcess.startListenChans = append(serveProcess.startListenChans, lChan) return lChan } @@ -191,15 +195,15 @@ func (this *ServeProcess) StartEventChannel() <-chan struct{} { // timeout has passed. When the timeout has passed it will wait // for confirmation from the http.Server, which normally takes // a very short time (milliseconds). -func (this *ServeProcess) StopEventChannel() <-chan struct{} { +func (serveProcess *ServeProcess) StopEventChannel() <-chan struct{} { lChan := make(chan struct{}, 1) - this.stopListenChans = append(this.stopListenChans, lChan) + serveProcess.stopListenChans = append(serveProcess.stopListenChans, lChan) return lChan } // Creates a new serve process. -func NewServeProcess(config *ServerConfig, servers ...Server) (*ServeProcess, - error) { +func NewServeProcess(config *ServerConfig, logger logging_types.InfoTraceLogger, + servers ...Server) (*ServeProcess, error) { var scfg ServerConfig if config == nil { return nil, fmt.Errorf("Nil passed as server configuration") @@ -210,25 +214,40 @@ func NewServeProcess(config *ServerConfig, servers ...Server) (*ServeProcess, stoppedChan := make(chan struct{}, 1) startListeners := make([]chan struct{}, 0) stopListeners := make([]chan struct{}, 0) - sp := &ServeProcess{&scfg, servers, stopChan, stoppedChan, startListeners, stopListeners, nil} + sp := &ServeProcess{ + config: &scfg, + servers: servers, + stopChan: stopChan, + stoppedChan: stoppedChan, + startListenChans: startListeners, + stopListenChans: stopListeners, + srv: nil, + logger: logging.WithScope(logger, "ServeProcess"), + } return sp, nil } // Used to enable log15 logging instead of the default Gin logging. -func logHandler(c *gin.Context) { - - path := c.Request.URL.Path +func logHandler(logger logging_types.InfoTraceLogger) gin.HandlerFunc { + logger = logging.WithScope(logger, "ginLogHandler") + return func(c *gin.Context) { - // Process request - c.Next() + path := c.Request.URL.Path - clientIP := c.ClientIP() - method := c.Request.Method - statusCode := c.Writer.Status() - comment := c.Errors.String() + // Process request + c.Next() - log.Info("[GIN] HTTP: "+clientIP, "Code", statusCode, "Method", method, "path", path, "error", comment) + clientIP := c.ClientIP() + method := c.Request.Method + statusCode := c.Writer.Status() + comment := c.Errors.String() + logger.Info("client_ip", clientIP, + "status_code", statusCode, + "method", method, + "path", path, + "error", comment) + } } func NewCORSMiddleware(options CORS) gin.HandlerFunc { diff --git a/server/websocket.go b/server/websocket.go index aff2f94c307aa13c3383292ad9dd44f4b054b8e2..265ac3a47451cb096f854cfcc33373ff70bb3155 100644 --- a/server/websocket.go +++ b/server/websocket.go @@ -22,6 +22,8 @@ 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 @@ -56,6 +58,7 @@ type WebSocketServer struct { sessionManager *SessionManager config *ServerConfig allOrigins bool + logger logging_types.InfoTraceLogger } // Create a new server. @@ -63,69 +66,72 @@ type WebSocketServer struct { // NOTE: This is not the total number of connections allowed - only those that are // upgraded to websockets. Requesting a websocket connection will fail with a 503 if // the server is at capacity. -func NewWebSocketServer(maxSessions uint16, service WebSocketService) *WebSocketServer { +func NewWebSocketServer(maxSessions uint16, service WebSocketService, + logger logging_types.InfoTraceLogger) *WebSocketServer { return &WebSocketServer{ maxSessions: maxSessions, - sessionManager: NewSessionManager(maxSessions, service), + sessionManager: NewSessionManager(maxSessions, service, logger), + logger: logging.WithScope(logger, "WebSocketServer"), } } // Start the server. Adds the handler to the router and sets everything up. -func (this *WebSocketServer) Start(config *ServerConfig, router *gin.Engine) { +func (wsServer *WebSocketServer) Start(config *ServerConfig, router *gin.Engine) { - this.config = config + wsServer.config = config - this.upgrader = websocket.Upgrader{ + wsServer.upgrader = websocket.Upgrader{ ReadBufferSize: int(config.WebSocket.ReadBufferSize), // TODO Will this be enough for massive "get blockchain" requests? WriteBufferSize: int(config.WebSocket.WriteBufferSize), } - this.upgrader.CheckOrigin = func(r *http.Request) bool { return true } - router.GET(config.WebSocket.WebSocketEndpoint, this.handleFunc) - this.running = true + wsServer.upgrader.CheckOrigin = func(r *http.Request) bool { return true } + router.GET(config.WebSocket.WebSocketEndpoint, wsServer.handleFunc) + wsServer.running = true } // Is the server currently running. -func (this *WebSocketServer) Running() bool { - return this.running +func (wsServer *WebSocketServer) Running() bool { + return wsServer.running } // Shut the server down. -func (this *WebSocketServer) ShutDown() { - this.sessionManager.Shutdown() - this.running = false +func (wsServer *WebSocketServer) ShutDown() { + wsServer.sessionManager.Shutdown() + wsServer.running = false } // Get the session-manager. -func (this *WebSocketServer) SessionManager() *SessionManager { - return this.sessionManager +func (wsServer *WebSocketServer) SessionManager() *SessionManager { + return wsServer.sessionManager } // Handler for websocket requests. -func (this *WebSocketServer) handleFunc(c *gin.Context) { +func (wsServer *WebSocketServer) handleFunc(c *gin.Context) { r := c.Request w := c.Writer // Upgrade to websocket. - wsConn, uErr := this.upgrader.Upgrade(w, r, nil) + wsConn, uErr := wsServer.upgrader.Upgrade(w, r, nil) if uErr != nil { - uErrStr := "Failed to upgrade to websocket connection: " + uErr.Error() - http.Error(w, uErrStr, 400) - log.Info(uErrStr) + 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) return } - session, cErr := this.sessionManager.createSession(wsConn) + session, cErr := wsServer.sessionManager.createSession(wsConn) if cErr != nil { - cErrStr := "Failed to establish websocket connection: " + cErr.Error() - http.Error(w, cErrStr, 503) - log.Info(cErrStr) + errMsg := "Failed to establish websocket connection" + http.Error(w, fmt.Sprintf("%s: %s", errMsg, cErr.Error()), 503) + logging.InfoMsg(wsServer.logger, errMsg, "error", cErr) return } // Start the connection. - log.Info("New websocket connection.", "sessionId", session.id) + logging.InfoMsg(wsServer.logger, "New websocket connection", + "session_id", session.id) session.Open() } @@ -148,57 +154,59 @@ type WSSession struct { service WebSocketService opened bool closed bool + logger logging_types.InfoTraceLogger } // Write a text message to the client. -func (this *WSSession) Write(msg []byte) error { - if this.closed { - log.Warn("Attempting to write to closed session.", "sessionId", this.id) +func (wsSession *WSSession) Write(msg []byte) error { + if wsSession.closed { + logging.InfoMsg(wsSession.logger, "Attempting to write to closed session.") return fmt.Errorf("Session is closed") } - this.writeChan <- msg + wsSession.writeChan <- msg return nil } // Private. Helper for writing control messages. -func (this *WSSession) write(mt int, payload []byte) error { - this.wsConn.SetWriteDeadline(time.Now().Add(writeWait)) - return this.wsConn.WriteMessage(mt, payload) +func (wsSession *WSSession) write(mt int, payload []byte) error { + wsSession.wsConn.SetWriteDeadline(time.Now().Add(writeWait)) + return wsSession.wsConn.WriteMessage(mt, payload) } // Get the session id number. -func (this *WSSession) Id() uint { - return this.id +func (wsSession *WSSession) Id() uint { + return wsSession.id } // Starts the read and write pumps. Blocks on the former. // Notifies all the observers. -func (this *WSSession) Open() { - this.opened = true - this.sessionManager.notifyOpened(this) - go this.writePump() - this.readPump() +func (wsSession *WSSession) Open() { + wsSession.opened = true + wsSession.sessionManager.notifyOpened(wsSession) + go wsSession.writePump() + wsSession.readPump() } // Closes the net connection and cleans up. Notifies all the observers. -func (this *WSSession) Close() { - if !this.closed { - this.closed = true - this.wsConn.Close() - this.sessionManager.removeSession(this.id) - log.Info("Closing websocket connection.", "sessionId", this.id, "remaining", len(this.sessionManager.activeSessions)) - this.sessionManager.notifyClosed(this) +func (wsSession *WSSession) Close() { + if !wsSession.closed { + wsSession.closed = true + wsSession.wsConn.Close() + wsSession.sessionManager.removeSession(wsSession.id) + logging.InfoMsg(wsSession.logger, "Closing websocket connection.", + "remaining_active_sessions", len(wsSession.sessionManager.activeSessions)) + wsSession.sessionManager.notifyClosed(wsSession) } } // Has the session been opened? -func (this *WSSession) Opened() bool { - return this.opened +func (wsSession *WSSession) Opened() bool { + return wsSession.opened } // Has the session been closed? -func (this *WSSession) Closed() bool { - return this.closed +func (wsSession *WSSession) Closed() bool { + return wsSession.closed } // Pump debugging @@ -210,7 +218,7 @@ var wpm *sync.Mutex = &sync.Mutex{} */ // Read loop. Will terminate on a failed read. -func (this *WSSession) readPump() { +func (wsSession *WSSession) readPump() { /* rpm.Lock() rp++ @@ -223,38 +231,40 @@ func (this *WSSession) readPump() { rpm.Unlock() }() */ - this.wsConn.SetReadLimit(maxMessageSize) + wsSession.wsConn.SetReadLimit(maxMessageSize) // this.wsConn.SetReadDeadline(time.Now().Add(pongWait)) // this.wsConn.SetPongHandler(func(string) error { this.wsConn.SetReadDeadline(time.Now().Add(pongWait)); return nil }) for { // Read - msgType, msg, err := this.wsConn.ReadMessage() + msgType, msg, err := wsSession.wsConn.ReadMessage() // Read error. if err != nil { // Socket could have been gracefully closed, so not really an error. - log.Info("Socket closed. Removing.", "error", err.Error()) - this.writeCloseChan <- struct{}{} + logging.InfoMsg(wsSession.logger, + "Socket closed. Removing.", "error", err) + wsSession.writeCloseChan <- struct{}{} return } if msgType != websocket.TextMessage { - log.Info("Receiving non text-message from client, closing.") - this.writeCloseChan <- struct{}{} + logging.InfoMsg(wsSession.logger, + "Receiving non text-message from client, closing.") + wsSession.writeCloseChan <- struct{}{} return } go func() { // Process the request. - this.service.Process(msg, this) + wsSession.service.Process(msg, wsSession) }() } } // Writes messages coming in on the write channel. Will terminate on failed writes, // if pings are not responded to, or if a message comes in on the write close channel. -func (this *WSSession) writePump() { +func (wsSession *WSSession) writePump() { /* wpm.Lock() wp++ @@ -271,23 +281,24 @@ func (this *WSSession) writePump() { defer func() { // ticker.Stop() - this.Close() + wsSession.Close() }() // Write loop. Blocks while waiting for data to come in over a channel. for { select { // Write request. - case msg := <-this.writeChan: + case msg := <-wsSession.writeChan: // Write the bytes to the socket. - err := this.wsConn.WriteMessage(websocket.TextMessage, msg) + err := wsSession.wsConn.WriteMessage(websocket.TextMessage, msg) if err != nil { // Could be due to the socket being closed so not really an error. - log.Info("Writing to socket failed. Closing.") + logging.InfoMsg(wsSession.logger, + "Writing to socket failed. Closing.") return } - case <-this.writeCloseChan: + case <-wsSession.writeCloseChan: return // Ticker run out. Time for another ping message. /* @@ -311,10 +322,12 @@ type SessionManager struct { service WebSocketService openEventChans []chan *WSSession closeEventChans []chan *WSSession + logger logging_types.InfoTraceLogger } // Create a new WebsocketManager. -func NewSessionManager(maxSessions uint16, wss WebSocketService) *SessionManager { +func NewSessionManager(maxSessions uint16, wss WebSocketService, + logger logging_types.InfoTraceLogger) *SessionManager { return &SessionManager{ maxSessions: maxSessions, activeSessions: make(map[uint]*WSSession), @@ -323,24 +336,25 @@ func NewSessionManager(maxSessions uint16, wss WebSocketService) *SessionManager service: wss, openEventChans: []chan *WSSession{}, closeEventChans: []chan *WSSession{}, + logger: logging.WithScope(logger, "SessionManager"), } } // TODO -func (this *SessionManager) Shutdown() { - this.activeSessions = nil +func (sessionManager *SessionManager) Shutdown() { + sessionManager.activeSessions = nil } // Add a listener to session open events. -func (this *SessionManager) SessionOpenEventChannel() <-chan *WSSession { +func (sessionManager *SessionManager) SessionOpenEventChannel() <-chan *WSSession { lChan := make(chan *WSSession, 1) - this.openEventChans = append(this.openEventChans, lChan) + sessionManager.openEventChans = append(sessionManager.openEventChans, lChan) return lChan } // Remove a listener from session open events. -func (this *SessionManager) RemoveSessionOpenEventChannel(lChan chan *WSSession) bool { - ec := this.openEventChans +func (sessionManager *SessionManager) RemoveSessionOpenEventChannel(lChan chan *WSSession) bool { + ec := sessionManager.openEventChans if len(ec) == 0 { return false } @@ -354,15 +368,15 @@ func (this *SessionManager) RemoveSessionOpenEventChannel(lChan chan *WSSession) } // Add a listener to session close events -func (this *SessionManager) SessionCloseEventChannel() <-chan *WSSession { +func (sessionManager *SessionManager) SessionCloseEventChannel() <-chan *WSSession { lChan := make(chan *WSSession, 1) - this.closeEventChans = append(this.closeEventChans, lChan) + sessionManager.closeEventChans = append(sessionManager.closeEventChans, lChan) return lChan } // Remove a listener from session close events. -func (this *SessionManager) RemoveSessionCloseEventChannel(lChan chan *WSSession) bool { - ec := this.closeEventChans +func (sessionManager *SessionManager) RemoveSessionCloseEventChannel(lChan chan *WSSession) bool { + ec := sessionManager.closeEventChans if len(ec) == 0 { return false } @@ -376,55 +390,57 @@ func (this *SessionManager) RemoveSessionCloseEventChannel(lChan chan *WSSession } // Used to notify all observers that a new session was opened. -func (this *SessionManager) notifyOpened(session *WSSession) { - for _, lChan := range this.openEventChans { +func (sessionManager *SessionManager) notifyOpened(session *WSSession) { + for _, lChan := range sessionManager.openEventChans { lChan <- session } } // Used to notify all observers that a new session was closed. -func (this *SessionManager) notifyClosed(session *WSSession) { - for _, lChan := range this.closeEventChans { +func (sessionManager *SessionManager) notifyClosed(session *WSSession) { + for _, lChan := range sessionManager.closeEventChans { lChan <- session } } // Creates a new session and adds it to the manager. -func (this *SessionManager) createSession(wsConn *websocket.Conn) (*WSSession, error) { +func (sessionManager *SessionManager) createSession(wsConn *websocket.Conn) (*WSSession, error) { // Check that the capacity hasn't been exceeded. - this.mtx.Lock() - defer this.mtx.Unlock() - if this.atCapacity() { + sessionManager.mtx.Lock() + defer sessionManager.mtx.Unlock() + if sessionManager.atCapacity() { return nil, fmt.Errorf("Already at capacity") } // Create and start - newId, _ := this.idPool.GetId() + newId, _ := sessionManager.idPool.GetId() conn := &WSSession{ - sessionManager: this, + sessionManager: sessionManager, id: newId, wsConn: wsConn, writeChan: make(chan []byte, maxMessageSize), writeCloseChan: make(chan struct{}), - service: this.service, + service: sessionManager.service, + logger: logging.WithScope(sessionManager.logger, "WSSession"). + With("session_id", newId), } - this.activeSessions[conn.id] = conn + sessionManager.activeSessions[conn.id] = conn return conn, nil } // Remove a session from the list. -func (this *SessionManager) removeSession(id uint) { - this.mtx.Lock() - defer this.mtx.Unlock() +func (sessionManager *SessionManager) removeSession(id uint) { + sessionManager.mtx.Lock() + defer sessionManager.mtx.Unlock() // Check that it exists. - _, ok := this.activeSessions[id] + _, ok := sessionManager.activeSessions[id] if ok { - delete(this.activeSessions, id) - this.idPool.ReleaseId(id) + delete(sessionManager.activeSessions, id) + sessionManager.idPool.ReleaseId(id) } } // True if the number of active connections is at the maximum. -func (this *SessionManager) atCapacity() bool { - return len(this.activeSessions) >= int(this.maxSessions) +func (sessionManager *SessionManager) atCapacity() bool { + return len(sessionManager.activeSessions) >= int(sessionManager.maxSessions) } diff --git a/test/server/scumbag.go b/test/server/scumbag_test.go similarity index 83% rename from test/server/scumbag.go rename to test/server/scumbag_test.go index a4d902036a236dad47b71116873dee3de845c7aa..7fcf23c28e6bf79bd87a8ab7fcbb938026bfe091 100644 --- a/test/server/scumbag.go +++ b/test/server/scumbag_test.go @@ -19,13 +19,17 @@ import ( "os" "runtime" - rpc "github.com/hyperledger/burrow/rpc" + "github.com/hyperledger/burrow/rpc" "github.com/hyperledger/burrow/server" "github.com/gin-gonic/gin" + "github.com/hyperledger/burrow/logging/lifecycle" + logging_types "github.com/hyperledger/burrow/logging/types" "github.com/tendermint/log15" ) +var logger logging_types.InfoTraceLogger = lifecycle.NewStdErrLogger() + func init() { runtime.GOMAXPROCS(runtime.NumCPU()) log15.Root().SetHandler(log15.LvlFilterHandler( @@ -68,13 +72,13 @@ func (this *ScumSocketService) Process(data []byte, session *server.WSSession) { func NewScumsocketServer(maxConnections uint16) *server.WebSocketServer { sss := &ScumSocketService{} - return server.NewWebSocketServer(maxConnections, sss) + return server.NewWebSocketServer(maxConnections, sss, logger) } func NewServeScumbag() (*server.ServeProcess, error) { cfg := server.DefaultServerConfig() cfg.Bind.Port = uint16(31400) - return server.NewServeProcess(cfg, NewScumbagServer()) + return server.NewServeProcess(cfg, logger, NewScumbagServer()) } func NewServeScumSocket(wsServer *server.WebSocketServer) (*server.ServeProcess, @@ -82,5 +86,5 @@ func NewServeScumSocket(wsServer *server.WebSocketServer) (*server.ServeProcess, cfg := server.DefaultServerConfig() cfg.WebSocket.WebSocketEndpoint = "/scumsocket" cfg.Bind.Port = uint16(31401) - return server.NewServeProcess(cfg, wsServer) + return server.NewServeProcess(cfg, logger, wsServer) } diff --git a/util/slice/slice.go b/util/slice/slice.go index 8c2b7f8914b86539c04051f7077830c82ec4b835..485510ff78e6da218bb3cd6abf8628f41a0e449f 100644 --- a/util/slice/slice.go +++ b/util/slice/slice.go @@ -14,6 +14,7 @@ package slice +// Convenience function func Slice(elements ...interface{}) []interface{} { return elements } diff --git a/util/snatives/templates/solidity_templates_test.go b/util/snatives/templates/solidity_templates_test.go index 6f77a6a08d70c312e6353e528d433f159fdf9b71..58fe37f7e461db87fbd9864263b312a5b6f5c300 100644 --- a/util/snatives/templates/solidity_templates_test.go +++ b/util/snatives/templates/solidity_templates_test.go @@ -16,9 +16,10 @@ package templates import ( "fmt" + "testing" + "github.com/hyperledger/burrow/manager/burrow-mint/evm" "github.com/stretchr/testify/assert" - "testing" ) func TestSNativeFuncTemplate(t *testing.T) {