From 489899e9c5c4c90a4b7e3d0130a2657fa10175b4 Mon Sep 17 00:00:00 2001 From: Silas Davis <silas@erisindustries.com> Date: Thu, 1 Dec 2016 19:42:31 +0000 Subject: [PATCH] Logging draft --- cmd/eris-db.go | 45 ++-- cmd/serve.go | 221 +++++++++--------- config/config.go | 11 + config/config_test.go | 20 +- config/dump_config_test.go | 19 ++ config/viper.go | 29 +++ consensus/tendermint/config.go | 7 +- consensus/tendermint/tendermint.go | 4 +- core/config.go | 43 ++-- core/core.go | 16 +- docs/generator.go | 7 +- glide.lock | 14 +- glide.yaml | 13 +- logging/adapter/adapter.go | 1 + logging/adapter/logrus.go | 23 ++ logging/config.go | 11 + logging/lifecycle.go | 26 +++ logging/loggers/channel_logger.go | 73 ++++++ logging/loggers/channel_logger_test.go | 32 +++ logging/loggers/info_trace_logger.go | 90 +++++++ logging/loggers/info_trace_logger_test.go | 14 ++ logging/loggers/logging_test.go | 21 ++ logging/loggers/multiple_channel_logger.go | 84 +++++++ .../loggers/multiple_channel_logger_test.go | 26 +++ logging/loggers/multiple_output_logger.go | 48 ++++ .../loggers/multiple_output_logger_test.go | 18 ++ rpc/tendermint/test/shared.go | 4 +- txs/log.go | 7 - 28 files changed, 733 insertions(+), 194 deletions(-) create mode 100644 config/dump_config_test.go create mode 100644 config/viper.go create mode 100644 logging/adapter/adapter.go create mode 100644 logging/adapter/logrus.go create mode 100644 logging/config.go create mode 100644 logging/lifecycle.go create mode 100644 logging/loggers/channel_logger.go create mode 100644 logging/loggers/channel_logger_test.go create mode 100644 logging/loggers/info_trace_logger.go create mode 100644 logging/loggers/info_trace_logger_test.go create mode 100644 logging/loggers/logging_test.go create mode 100644 logging/loggers/multiple_channel_logger.go create mode 100644 logging/loggers/multiple_channel_logger_test.go create mode 100644 logging/loggers/multiple_output_logger.go create mode 100644 logging/loggers/multiple_output_logger_test.go delete mode 100644 txs/log.go diff --git a/cmd/eris-db.go b/cmd/eris-db.go index 605b1206..bcd555c5 100644 --- a/cmd/eris-db.go +++ b/cmd/eris-db.go @@ -21,17 +21,12 @@ import ( "strconv" "strings" - cobra "github.com/spf13/cobra" + "github.com/spf13/cobra" - log "github.com/eris-ltd/eris-logger" - - definitions "github.com/eris-ltd/eris-db/definitions" - version "github.com/eris-ltd/eris-db/version" + "github.com/eris-ltd/eris-db/definitions" + "github.com/eris-ltd/eris-db/version" ) -// Global Do struct -var do *definitions.Do - var ErisDbCmd = &cobra.Command{ Use: "eris-db", Short: "Eris-DB is the server side of the eris chain.", @@ -43,38 +38,26 @@ Made with <3 by Eris Industries. Complete documentation is available at https://monax.io/docs/documentation ` + "\nVERSION:\n " + version.VERSION, - PersistentPreRun: func(cmd *cobra.Command, args []string) { - - log.SetLevel(log.WarnLevel) - if do.Verbose { - log.SetLevel(log.InfoLevel) - } else if do.Debug { - log.SetLevel(log.DebugLevel) - } - }, Run: func(cmd *cobra.Command, args []string) { cmd.Help() }, } func Execute() { - InitErisDbCli() - AddGlobalFlags() - AddCommands() + do := definitions.NewDo() + AddGlobalFlags(do) + AddCommands(do) ErisDbCmd.Execute() } -func InitErisDbCli() { - // initialise an empty Do struct for command execution - do = definitions.NewDo() -} - -func AddGlobalFlags() { - ErisDbCmd.PersistentFlags().BoolVarP(&do.Verbose, "verbose", "v", defaultVerbose(), "verbose output; more output than no output flags; less output than debug level; default respects $ERIS_DB_VERBOSE") - ErisDbCmd.PersistentFlags().BoolVarP(&do.Debug, "debug", "d", defaultDebug(), "debug level output; the most output available for eris-db; if it is too chatty use verbose flag; default respects $ERIS_DB_DEBUG") +func AddGlobalFlags(do *definitions.Do) { + ErisDbCmd.PersistentFlags().BoolVarP(&do.Verbose, "verbose", "v", + defaultVerbose(), + "verbose output; more output than no output flags; less output than debug level; default respects $ERIS_DB_VERBOSE") + ErisDbCmd.PersistentFlags().BoolVarP(&do.Debug, "debug", "d", defaultDebug(), + "debug level output; the most output available for eris-db; if it is too chatty use verbose flag; default respects $ERIS_DB_DEBUG") } -func AddCommands() { - buildServeCommand() - ErisDbCmd.AddCommand(ServeCmd) +func AddCommands(do *definitions.Do) { + ErisDbCmd.AddCommand(buildServeCommand(do)) } //------------------------------------------------------------------------------ diff --git a/cmd/serve.go b/cmd/serve.go index eccf3388..55661118 100644 --- a/cmd/serve.go +++ b/cmd/serve.go @@ -17,19 +17,18 @@ package commands import ( + "fmt" "os" "os/signal" "path" "syscall" - cobra "github.com/spf13/cobra" - - log "github.com/eris-ltd/eris-logger" - - "fmt" + "github.com/spf13/cobra" - core "github.com/eris-ltd/eris-db/core" - util "github.com/eris-ltd/eris-db/util" + "github.com/eris-ltd/eris-db/core" + "github.com/eris-ltd/eris-db/definitions" + "github.com/eris-ltd/eris-db/logging" + "github.com/eris-ltd/eris-db/util" ) const ( @@ -41,148 +40,152 @@ var DefaultConfigFilename = fmt.Sprintf("%s.%s", DefaultConfigBasename, DefaultConfigType) -var ServeCmd = &cobra.Command{ - Use: "serve", - Short: "Eris-DB serve starts an eris-db node with client API enabled by default.", - Long: `Eris-DB serve starts an eris-db node with client API enabled by default. +// build the serve subcommand +func buildServeCommand(do *definitions.Do) *cobra.Command { + cmd := &cobra.Command{ + Use: "serve", + Short: "Eris-DB serve starts an eris-db node with client API enabled by default.", + Long: `Eris-DB serve starts an eris-db node with client API enabled by default. The Eris-DB node is modularly configured for the consensus engine and application manager. The client API can be disabled.`, - Example: fmt.Sprintf(`$ eris-db serve -- will start the Eris-DB node based on the configuration file "%s" in the current working directory + Example: fmt.Sprintf(`$ eris-db serve -- will start the Eris-DB node based on the configuration file "%s" in the current working directory $ eris-db serve --work-dir <path-to-working-directory> -- will start the Eris-DB node based on the configuration file "%s" in the provided working directory $ eris-db serve --chain-id <CHAIN_ID> -- will overrule the configuration entry assert_chain_id`, - DefaultConfigFilename, DefaultConfigFilename), - PreRun: func(cmd *cobra.Command, args []string) { - // if WorkDir was not set by a flag or by $ERIS_DB_WORKDIR - // NOTE [ben]: we can consider an `Explicit` flag that eliminates - // the use of any assumptions while starting Eris-DB - if do.WorkDir == "" { - if currentDirectory, err := os.Getwd(); err != nil { - log.Fatalf("No directory provided and failed to get current working directory: %v", err) + DefaultConfigFilename, DefaultConfigFilename), + PreRun: func(cmd *cobra.Command, args []string) { + // if WorkDir was not set by a flag or by $ERIS_DB_WORKDIR + // NOTE [ben]: we can consider an `Explicit` flag that eliminates + // the use of any assumptions while starting Eris-DB + if do.WorkDir == "" { + if currentDirectory, err := os.Getwd(); err != nil { + panic(fmt.Sprintf("No directory provided and failed to get current "+ + "working directory: %v", err)) + os.Exit(1) + } else { + do.WorkDir = currentDirectory + } + } + if !util.IsDir(do.WorkDir) { + panic(fmt.Sprintf("Provided working directory %s is not a directory", + do.WorkDir)) os.Exit(1) - } else { - do.WorkDir = currentDirectory } - } - if !util.IsDir(do.WorkDir) { - log.Fatalf("Provided working directory %s is not a directory", do.WorkDir) - } - }, - Run: Serve, -} - -// build the serve subcommand -func buildServeCommand() { - addServeFlags() + }, + Run: ServeRunner(do), + } + addServeFlags(do, cmd) + return cmd } -func addServeFlags() { - ServeCmd.PersistentFlags().StringVarP(&do.ChainId, "chain-id", "c", +func addServeFlags(do *definitions.Do, serveCmd *cobra.Command) { + serveCmd.PersistentFlags().StringVarP(&do.ChainId, "chain-id", "c", defaultChainId(), "specify the chain id to use for assertion against the genesis file or the existing state. If omitted, and no id is set in $CHAIN_ID, then assert_chain_id is used from the configuration file.") - ServeCmd.PersistentFlags().StringVarP(&do.WorkDir, "work-dir", "w", + serveCmd.PersistentFlags().StringVarP(&do.WorkDir, "work-dir", "w", defaultWorkDir(), "specify the working directory for the chain to run. If omitted, and no path set in $ERIS_DB_WORKDIR, the current working directory is taken.") - ServeCmd.PersistentFlags().StringVarP(&do.DataDir, "data-dir", "", + serveCmd.PersistentFlags().StringVarP(&do.DataDir, "data-dir", "", defaultDataDir(), "specify the data directory. If omitted and not set in $ERIS_DB_DATADIR, <working_directory>/data is taken.") - ServeCmd.PersistentFlags().BoolVarP(&do.DisableRpc, "disable-rpc", "", + serveCmd.PersistentFlags().BoolVarP(&do.DisableRpc, "disable-rpc", "", defaultDisableRpc(), "indicate for the RPC to be disabled. If omitted the RPC is enabled by default, unless (deprecated) $ERISDB_API is set to false.") } //------------------------------------------------------------------------------ // functions - -// serve() prepares the environment and sets up the core for Eris_DB to run. -// After the setup succeeds, serve() starts the core and halts for core to -// terminate. -func Serve(cmd *cobra.Command, args []string) { - // load configuration from a single location to avoid a wrong configuration - // file is loaded. - err := do.ReadConfig(do.WorkDir, DefaultConfigBasename, DefaultConfigType) - if err != nil { - log.WithFields(log.Fields{ - "directory": do.WorkDir, - "file": DefaultConfigFilename, - }).Fatalf("Fatal error reading configuration") - os.Exit(1) - } - // if do.ChainId is not yet set, load chain_id for assertion from configuration file - if do.ChainId == "" { - if do.ChainId = do.Config.GetString("chain.assert_chain_id"); do.ChainId == "" { - log.Fatalf("Failed to read non-empty string for ChainId from config.") - os.Exit(1) - } - } +func NewCoreFromDo(do *definitions.Do) (*core.Core, error) { // load the genesis file path do.GenesisFile = path.Join(do.WorkDir, do.Config.GetString("chain.genesis_file")) + if do.Config.GetString("chain.genesis_file") == "" { - log.Fatalf("Failed to read non-empty string for genesis file from config.") - os.Exit(1) + return nil, fmt.Errorf("The config value chain.genesis_file is empty, " + + "but should be set to the location of the genesis.json file.") } // Ensure data directory is set and accessible if err := do.InitialiseDataDirectory(); err != nil { - log.Fatalf("Failed to initialise data directory (%s): %v", do.DataDir, err) - os.Exit(1) + return nil, fmt.Errorf("Failed to initialise data directory (%s): %v", do.DataDir, err) } - log.WithFields(log.Fields{ - "chainId": do.ChainId, - "workingDirectory": do.WorkDir, - "dataDirectory": do.DataDir, - "genesisFile": do.GenesisFile, - }).Info("Eris-DB serve configuring") - consensusConfig, err := core.LoadConsensusModuleConfig(do) + loggerConfig, err := core.LoadLoggingConfig(do) if err != nil { - log.Fatalf("Failed to load consensus module configuration: %s.", err) - os.Exit(1) + return nil, fmt.Errorf("Failed to load logging config: %s", err) } - managerConfig, err := core.LoadApplicationManagerModuleConfig(do) + logger := logging.NewLogger(*loggerConfig) + cmdLogger := logger.With("command", "serve") + // if do.ChainId is not yet set, load chain_id for assertion from configuration file + + if do.ChainId == "" { + if do.ChainId = do.Config.GetString("chain.assert_chain_id"); do.ChainId == "" { + return nil, fmt.Errorf("The config chain.assert_chain_id is empty, " + + "but should be set to the chain_id of the chain we are trying to run.") + } + } + + cmdLogger.Info("chainId", do.ChainId, + "workingDirectory", do.WorkDir, + "dataDirectory", do.DataDir, + "genesisFile", do.GenesisFile, + logging.MessageKey, "Loading configuration for serve command") + + consensusConfig, err := core.LoadConsensusModuleConfig(do) if err != nil { - log.Fatalf("Failed to load application manager module configuration: %s.", err) - os.Exit(1) + return nil, fmt.Errorf("Failed to load consensus module configuration: %s.", err) } - log.WithFields(log.Fields{ - "consensusModule": consensusConfig.Version, - "applicationManager": managerConfig.Version, - }).Debug("Modules configured") - newCore, err := core.NewCore(do.ChainId, consensusConfig, managerConfig) + managerConfig, err := core.LoadApplicationManagerModuleConfig(do) if err != nil { - log.Fatalf("Failed to load core: %s", err) + return nil, fmt.Errorf("Failed to load application manager module configuration: %s.", err) } - if !do.DisableRpc { - serverConfig, err := core.LoadServerConfig(do) - if err != nil { - log.Fatalf("Failed to load server configuration: %s.", err) - os.Exit(1) - } + cmdLogger.Info("consensusModule", consensusConfig.Version, + "applicationManager", managerConfig.Version, + logging.MessageKey, "Modules configured") - serverProcess, err := newCore.NewGatewayV0(serverConfig) + return core.NewCore(do.ChainId, consensusConfig, managerConfig, logger) +} + +// ServeRunner() returns a command runner that prepares the environment and sets +// up the core for Eris-DB to run. After the setup succeeds, it starts the core +// and waits for the core to terminate. +func ServeRunner(do *definitions.Do) func(*cobra.Command, []string) { + return func(cmd *cobra.Command, args []string) { + // load configuration from a single location to avoid a wrong configuration + // file is loaded. + err := do.ReadConfig(do.WorkDir, DefaultConfigBasename, DefaultConfigType) if err != nil { - log.Fatalf("Failed to load servers: %s.", err) - os.Exit(1) + util.Fatalf("Fatal error reading configuration from %s/%s", do.WorkDir, + DefaultConfigFilename) } - err = serverProcess.Start() + + newCore, err := NewCoreFromDo(do) + if err != nil { - log.Fatalf("Failed to start servers: %s.", err) - os.Exit(1) + util.Fatalf("Failed to load core: %s", err) } - _, err = newCore.NewGatewayTendermint(serverConfig) - if err != nil { - log.Fatalf("Failed to start Tendermint gateway") + + if !do.DisableRpc { + serverConfig, err := core.LoadServerConfig(do) + if err != nil { + util.Fatalf("Failed to load server configuration: %s.", err) + } + + serverProcess, err := newCore.NewGatewayV0(serverConfig) + if err != nil { + util.Fatalf("Failed to load servers: %s.", err) + } + err = serverProcess.Start() + if err != nil { + util.Fatalf("Failed to start servers: %s.", err) + } + _, err = newCore.NewGatewayTendermint(serverConfig) + if err != nil { + util.Fatalf("Failed to start Tendermint gateway") + } + <-serverProcess.StopEventChannel() + } else { + signals := make(chan os.Signal, 1) + signal.Notify(signals, syscall.SIGINT, syscall.SIGTERM) + fmt.Fprintf(os.Stderr, "Received %s signal. Marmots out.", <-signals) } - <-serverProcess.StopEventChannel() - } else { - signals := make(chan os.Signal, 1) - done := make(chan bool, 1) - signal.Notify(signals, syscall.SIGINT, syscall.SIGTERM) - go func() { - signal := <-signals - // TODO: [ben] clean up core; in a manner consistent with enabled rpc - log.Fatalf("Received %s signal. Marmots out.", signal) - done <- true - }() - <-done } } diff --git a/config/config.go b/config/config.go index a37cf96f..32dc2c32 100644 --- a/config/config.go +++ b/config/config.go @@ -174,3 +174,14 @@ func GetConfigurationFileBytes(chainId, moniker, seeds string, chainImageName st return buffer.Bytes(), nil } + +func GetExampleConfigFileBytes() ([]byte, error) { + return GetConfigurationFileBytes( + "simplechain", + "delectable_marmot", + "192.168.168.255", + "db:latest", + true, + "46657", + "eris-db") +} diff --git a/config/config_test.go b/config/config_test.go index 79286f35..e01346e8 100644 --- a/config/config_test.go +++ b/config/config_test.go @@ -17,13 +17,21 @@ package config import ( + "bytes" "testing" + + "github.com/spf13/viper" + "github.com/stretchr/testify/assert" ) -func TestConfigurationFileBytes(t *testing.T) { - // TODO: [ben] parse written bytes for comparison with expected parameters - if _, err := GetConfigurationFileBytes("simplechain", "marmot", "noseeds", "db:latest", - true, "", "eris-db"); err != nil { - t.Errorf("Error writing configuration file bytes: %s", err) - } +// Since the logic for generating configuration files (in eris-cm) is split from +// the logic for consuming them +func TestGeneratedConfigIsUsable(t *testing.T) { + bs, err := GetExampleConfigFileBytes() + assert.NoError(t, err, "Should be able to create example config") + buf := bytes.NewBuffer(bs) + conf := viper.New() + viper.SetConfigType("toml") + err = conf.ReadConfig(buf) + assert.NoError(t, err, "Should be able to read example config into Viper") } diff --git a/config/dump_config_test.go b/config/dump_config_test.go new file mode 100644 index 00000000..ed71746c --- /dev/null +++ b/config/dump_config_test.go @@ -0,0 +1,19 @@ +// +build dumpconfig + +// Space above matters +package config + +import ( + "io/ioutil" + "testing" + "github.com/stretchr/testify/assert" +) + +// This is a little convenience for getting a config file dump. Just run: +// go test -tags dumpconfig ./config +// This pseudo test won't run unless the dumpconfig tag is +func TestDumpConfig(t *testing.T) { + bs, err := GetExampleConfigFileBytes() + assert.NoError(t, err, "Should be able to create example config") + ioutil.WriteFile("config_dump.toml", bs, 0644) +} diff --git a/config/viper.go b/config/viper.go new file mode 100644 index 00000000..fd56d89e --- /dev/null +++ b/config/viper.go @@ -0,0 +1,29 @@ +package config + +import ( + "fmt" + "github.com/spf13/viper" +) + +// 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 + // character (eg, a dash). + defer func() { + if r := recover(); r != nil { + err = fmt.Errorf("Viper panicked trying to read config subtree: %s", + configSubtreePath) + } + }() + if !conf.IsSet(configSubtreePath) { + return nil, fmt.Errorf("Failed to read config subtree: %s", + configSubtreePath) + } + subConfig = conf.Sub(configSubtreePath) + if subConfig == nil { + return nil, fmt.Errorf("Failed to read config subtree: %s", + configSubtreePath) + } + return subConfig, err +} diff --git a/consensus/tendermint/config.go b/consensus/tendermint/config.go index 1bbb74bd..094d7979 100644 --- a/consensus/tendermint/config.go +++ b/consensus/tendermint/config.go @@ -23,10 +23,10 @@ import ( "path" "time" - viper "github.com/spf13/viper" + "github.com/spf13/viper" tendermintConfig "github.com/tendermint/go-config" - config "github.com/eris-ltd/eris-db/config" + "github.com/eris-ltd/eris-db/config" ) // NOTE [ben] Compiler check to ensure TendermintConfig successfully implements @@ -147,7 +147,8 @@ func (tmintConfig *TendermintConfig) GetMapString(key string) map[string]string func (tmintConfig *TendermintConfig) GetConfig(key string) tendermintConfig.Config { // TODO: [ben] log out a warning as this indicates a potentially breaking code // change from Tendermints side - if !tmintConfig.subTree.IsSet(key) { + subTree, _ := config.ViperSubConfig(tmintConfig.subTree, key) + if subTree == nil { return &TendermintConfig{ subTree: viper.New(), } diff --git a/consensus/tendermint/tendermint.go b/consensus/tendermint/tendermint.go index 237fb4a0..87553697 100644 --- a/consensus/tendermint/tendermint.go +++ b/consensus/tendermint/tendermint.go @@ -71,10 +71,10 @@ func NewTendermint(moduleConfig *config.ModuleConfig, if !moduleConfig.Config.IsSet("configuration") { return nil, fmt.Errorf("Failed to extract Tendermint configuration subtree.") } - tendermintConfigViper := moduleConfig.Config.Sub("configuration") + tendermintConfigViper, err := config.ViperSubConfig(moduleConfig.Config, "configuration") if tendermintConfigViper == nil { return nil, - fmt.Errorf("Failed to extract Tendermint configuration subtree.") + fmt.Errorf("Failed to extract Tendermint configuration subtree: %s", err) } // wrap a copy of the viper config in a tendermint/go-config interface tmintConfig := GetTendermintConfig(tendermintConfigViper) diff --git a/core/config.go b/core/config.go index a2a82dbd..cb8239ff 100644 --- a/core/config.go +++ b/core/config.go @@ -24,13 +24,14 @@ import ( "os" "path" - config "github.com/eris-ltd/eris-db/config" - consensus "github.com/eris-ltd/eris-db/consensus" - definitions "github.com/eris-ltd/eris-db/definitions" - manager "github.com/eris-ltd/eris-db/manager" - server "github.com/eris-ltd/eris-db/server" - util "github.com/eris-ltd/eris-db/util" - version "github.com/eris-ltd/eris-db/version" + "github.com/eris-ltd/eris-db/config" + "github.com/eris-ltd/eris-db/consensus" + "github.com/eris-ltd/eris-db/definitions" + "github.com/eris-ltd/eris-db/logging" + "github.com/eris-ltd/eris-db/manager" + "github.com/eris-ltd/eris-db/server" + "github.com/eris-ltd/eris-db/util" + "github.com/eris-ltd/eris-db/version" "github.com/spf13/viper" ) @@ -75,17 +76,14 @@ func LoadModuleConfig(conf *viper.Viper, rootWorkDir, rootDataDir, fmt.Errorf("Failed to create module data directory %s.", dataDir) } // load configuration subtree for module - // TODO: [ben] Viper internally panics if `moduleName` contains an unallowed - // character (eg, a dash). Either this needs to be wrapped in a go-routine - // and recovered from or a PR to viper is needed to address this bug. if !conf.IsSet(moduleName) { return nil, fmt.Errorf("Failed to read configuration section for %s", moduleName) } - subConfig := conf.Sub(moduleName) + subConfig, err := config.ViperSubConfig(conf, moduleName) if subConfig == nil { - return nil, - fmt.Errorf("Failed to read configuration section for %s.", moduleName) + return nil, fmt.Errorf("Failed to read configuration section for %s: %s", + moduleName, err) } return &config.ModuleConfig{ @@ -104,19 +102,24 @@ func LoadModuleConfig(conf *viper.Viper, rootWorkDir, rootDataDir, // LoadServerModuleConfig wraps specifically for the servers run by core func LoadServerConfig(do *definitions.Do) (*server.ServerConfig, error) { // load configuration subtree for servers - if !do.Config.IsSet("servers") { - return nil, fmt.Errorf("Failed to read configuration section for servers") - } - subConfig := do.Config.Sub("servers") - if subConfig == nil { - return nil, - fmt.Errorf("Failed to read configuration section for servers") + subConfig, err := config.ViperSubConfig(do.Config, "servers") + if err != nil { + return nil, err } serverConfig, err := server.ReadServerConfig(subConfig) + if err != nil { + return nil, err + } serverConfig.ChainId = do.ChainId return serverConfig, err } +func LoadLoggingConfig(do *definitions.Do) (*logging.LoggingConfig, error) { + //subConfig, err := SubConfig(conf, "logging") + loggingConfig := &logging.LoggingConfig{} + return loggingConfig, nil +} + //------------------------------------------------------------------------------ // Helper functions diff --git a/core/core.go b/core/core.go index 03f56b56..489b8291 100644 --- a/core/core.go +++ b/core/core.go @@ -32,6 +32,8 @@ import ( // rpc_v0 is carried over from Eris-DBv0.11 and before on port 1337 rpc_v0 "github.com/eris-ltd/eris-db/rpc/v0" // rpc_tendermint is carried over from Eris-DBv0.11 and before on port 46657 + + "github.com/eris-ltd/eris-db/logging/loggers" rpc_tendermint "github.com/eris-ltd/eris-db/rpc/tendermint/core" server "github.com/eris-ltd/eris-db/server" ) @@ -42,10 +44,13 @@ type Core struct { evsw *events.EventSwitch pipe definitions.Pipe tendermintPipe definitions.TendermintPipe + logger loggers.InfoTraceLogger } -func NewCore(chainId string, consensusConfig *config.ModuleConfig, - managerConfig *config.ModuleConfig) (*Core, error) { +func NewCore(chainId string, + consensusConfig *config.ModuleConfig, + managerConfig *config.ModuleConfig, + logger loggers.InfoTraceLogger) (*Core, error) { // start new event switch, TODO: [ben] replace with eris-db/event evsw := events.NewEventSwitch() evsw.Start() @@ -65,18 +70,13 @@ func NewCore(chainId string, consensusConfig *config.ModuleConfig, if err != nil { log.Warn(fmt.Sprintf("Tendermint gateway not supported by %s", managerConfig.Version)) - return &Core{ - chainId: chainId, - evsw: evsw, - pipe: pipe, - tendermintPipe: nil, - }, nil } return &Core{ chainId: chainId, evsw: evsw, pipe: pipe, tendermintPipe: tendermintPipe, + logger: logger, }, nil } diff --git a/docs/generator.go b/docs/generator.go index fb430fc0..2d34fb2a 100644 --- a/docs/generator.go +++ b/docs/generator.go @@ -13,6 +13,7 @@ import ( clientCommands "github.com/eris-ltd/eris-db/client/cmd" "github.com/eris-ltd/eris-db/version" "github.com/spf13/cobra" + "github.com/eris-ltd/eris-db/definitions" ) // Repository maintainers should customize the next two lines. @@ -115,9 +116,9 @@ func AddClientToDB(dbCmd, clientCmd *cobra.Command) error { func main() { // Repository maintainers should populate the top level command object. erisDbCommand := commands.ErisDbCmd - commands.InitErisDbCli() - commands.AddCommands() - commands.AddGlobalFlags() + do := definitions.NewDo() + commands.AddGlobalFlags(do) + commands.AddCommands(do) erisClientCommand := clientCommands.ErisClientCmd clientCommands.InitErisClientInit() diff --git a/glide.lock b/glide.lock index 76c7e0b2..d809346f 100644 --- a/glide.lock +++ b/glide.lock @@ -30,8 +30,6 @@ imports: - go/common - name: github.com/eris-ltd/eris-keys version: 114ebc77443db9a153692233294e48bc7e184215 -- name: github.com/eris-ltd/eris-logger - version: ea48a395d6ecc0eccc67a26da9fc7a6106fabb84 - name: github.com/fsnotify/fsnotify version: 30411dbcefb7a1da7e84f75530ad3abe4011b4f8 - name: github.com/gin-gonic/gin @@ -215,4 +213,16 @@ imports: version: ecde8c8f16df93a994dda8936c8f60f0c26c28ab - name: gopkg.in/yaml.v2 version: a83829b6f1293c91addabc89d0571c246397bbf4 +- name: github.com/go-kit/kit + version: f66b0e13579bfc5a48b9e2a94b1209c107ea1f41 + subpackages: + - log +- name: github.com/eapache/channels + version: 47238d5aae8c0fefd518ef2bee46290909cf8263 +- name: github.com/eapache/queue + version: 44cc805cf13205b55f69e14bcb69867d1ae92f98 +- name: github.com/go-logfmt/logfmt + version: 390ab7935ee28ec6b286364bba9b4dd6410cb3d5 +- name: github.com/go-stack/stack + version: 100eb0c0a9c5b306ca2fb4f165df21d80ada4b82 devImports: [] diff --git a/glide.yaml b/glide.yaml index ca8e52b5..faeed635 100644 --- a/glide.yaml +++ b/glide.yaml @@ -1,6 +1,5 @@ package: github.com/eris-ltd/eris-db import: -- package: github.com/eris-ltd/eris-logger - package: github.com/eris-ltd/eris-keys - package: github.com/spf13/cobra - package: github.com/spf13/viper @@ -15,5 +14,15 @@ import: - ripemd160 - package: gopkg.in/fatih/set.v0 - package: gopkg.in/tylerb/graceful.v1 -- package: golang.org/x/net/http2 +- package: golang.org/x/net + subpackages: + - http2 - package: github.com/eris-ltd/common +- package: github.com/go-kit/kit + version: ^0.3.0 +- package: github.com/eapache/channels + version: ~1.1.0 +- package: github.com/go-logfmt/logfmt + version: ^0.3.0 +- package: github.com/go-stack/stack + version: ^1.5.2 diff --git a/logging/adapter/adapter.go b/logging/adapter/adapter.go new file mode 100644 index 00000000..b8e8da30 --- /dev/null +++ b/logging/adapter/adapter.go @@ -0,0 +1 @@ +package adapter diff --git a/logging/adapter/logrus.go b/logging/adapter/logrus.go new file mode 100644 index 00000000..fd20c067 --- /dev/null +++ b/logging/adapter/logrus.go @@ -0,0 +1,23 @@ +package adapter + +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/config.go b/logging/config.go new file mode 100644 index 00000000..b43b1b55 --- /dev/null +++ b/logging/config.go @@ -0,0 +1,11 @@ +package logging + +type ( + SinkConfig struct { + Channels []string + } + + LoggingConfig struct { + Sinks []SinkConfig + } +) diff --git a/logging/lifecycle.go b/logging/lifecycle.go new file mode 100644 index 00000000..97e2a52b --- /dev/null +++ b/logging/lifecycle.go @@ -0,0 +1,26 @@ +package logging + +import ( + "os" + + "github.com/eris-ltd/eris-db/logging/loggers" + kitlog "github.com/go-kit/kit/log" +) + +const ( + MessageKey = "message" + // To get the Caller information correct on the log, we need to count the + // number of calls from a log call in the code to the time it hits a kitlog + // context: [log call site (5), Info/Trace (4), MultipleChannelLogger.Log (3), + // kitlog.Context.Log (2), kitlog.bindValues (1) (binding occurs), + // kitlog.Caller (0), stack.caller] + infoTraceLoggerCallDepth = 5 +) + +func NewLogger(LoggingConfig LoggingConfig) loggers.InfoTraceLogger { + infoLogger := kitlog.NewLogfmtLogger(os.Stderr) + traceLogger := kitlog.NewLogfmtLogger(os.Stderr) + return loggers.NewInfoTraceLogger(infoLogger, traceLogger). + With("timestamp_utc", kitlog.DefaultTimestampUTC, + "caller", kitlog.Caller(infoTraceLoggerCallDepth)) +} diff --git a/logging/loggers/channel_logger.go b/logging/loggers/channel_logger.go new file mode 100644 index 00000000..c527d432 --- /dev/null +++ b/logging/loggers/channel_logger.go @@ -0,0 +1,73 @@ +package loggers + +import ( + "github.com/eapache/channels" + kitlog "github.com/go-kit/kit/log" +) + +const ( + LoggingRingBufferCap channels.BufferCap = 100 +) + +type ChannelLogger struct { + ch channels.Channel +} + +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 { + return &ChannelLogger{ + ch: channels.NewRingChannel(LoggingRingBufferCap), + } +} + +func (cl *ChannelLogger) Log(keyvals ...interface{}) error { + cl.ch.In() <- keyvals + // 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 +} + +// 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{}) +} + +// 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{}) + default: + return nil + } +} + +// 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()...) + } +} + +// Wraps an underlying Logger baseLogger to provide a Logger that is +// is non-blocking on calls to Log. +func NonBlockingLogger(baseLogger kitlog.Logger) *ChannelLogger { + cl := newChannelLogger() + go cl.DrainChannelToLogger(baseLogger) + return cl +} diff --git a/logging/loggers/channel_logger_test.go b/logging/loggers/channel_logger_test.go new file mode 100644 index 00000000..087bd5b4 --- /dev/null +++ b/logging/loggers/channel_logger_test.go @@ -0,0 +1,32 @@ +package loggers + +import ( + "testing" + + "github.com/stretchr/testify/assert" + "fmt" +) + +func TestChannelLogger(t *testing.T) { + cl := newChannelLogger() + + // Push a larger number of log messages than will fit into ring buffer + 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++ { + ll := cl.WaitReadLogLine() + assert.Equal(t, 10+i, ll[1]) + } + + assert.Nil(t, cl.ReadLogLine(), "Since we have drained the buffer there "+ + "should be no more log lines.") +} + +func TestBlether(t *testing.T) { + var bs []byte + ext := append(bs, ) + fmt.Println(ext) +} \ No newline at end of file diff --git a/logging/loggers/info_trace_logger.go b/logging/loggers/info_trace_logger.go new file mode 100644 index 00000000..ddb7cd02 --- /dev/null +++ b/logging/loggers/info_trace_logger.go @@ -0,0 +1,90 @@ +package loggers + +import kitlog "github.com/go-kit/kit/log" + +const ( + InfoChannelName = "INFO" + TraceChannelName = "TRACE" +) + +type infoTraceLogger struct { + mcl MultipleChannelLogger +} + +// 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 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 +} + +func NewInfoTraceLogger(infoLogger, traceLogger kitlog.Logger) InfoTraceLogger { + return &infoTraceLogger{ + mcl: NewMultipleChannelLogger(map[string]kitlog.Logger{ + InfoChannelName: infoLogger, + TraceChannelName: traceLogger, + }), + } +} + +func NewNoopInfoTraceLogger() InfoTraceLogger { + return &infoTraceLogger{ + mcl: NewMultipleChannelLogger(map[string]kitlog.Logger{ + InfoChannelName: kitlog.NewNopLogger(), + TraceChannelName: kitlog.NewNopLogger(), + }), + } +} + +func (l *infoTraceLogger) With(keyvals ...interface{}) InfoTraceLogger { + return &infoTraceLogger{ + mcl: l.mcl.With(keyvals...), + } +} + +func (l *infoTraceLogger) WithPrefix(keyvals ...interface{}) InfoTraceLogger { + return &infoTraceLogger{ + mcl: l.mcl.WithPrefix(keyvals...), + } +} + +func (l *infoTraceLogger) Info(keyvals ...interface{}) error { + return l.mcl.Log(InfoChannelName, keyvals...) +} + +func (l *infoTraceLogger) Trace(keyvals ...interface{}) error { + return l.mcl.Log(TraceChannelName, keyvals...) +} diff --git a/logging/loggers/info_trace_logger_test.go b/logging/loggers/info_trace_logger_test.go new file mode 100644 index 00000000..505f2606 --- /dev/null +++ b/logging/loggers/info_trace_logger_test.go @@ -0,0 +1,14 @@ +package loggers + +import ( + "os" + "testing" + + kitlog "github.com/go-kit/kit/log" +) + +func TestLogger(t *testing.T) { + stderrLogger := kitlog.NewLogfmtLogger(os.Stderr) + logger := NewInfoTraceLogger(stderrLogger, stderrLogger) + logger.Trace("hello", "barry") +} diff --git a/logging/loggers/logging_test.go b/logging/loggers/logging_test.go new file mode 100644 index 00000000..78166fc9 --- /dev/null +++ b/logging/loggers/logging_test.go @@ -0,0 +1,21 @@ +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 new file mode 100644 index 00000000..43665f8e --- /dev/null +++ b/logging/loggers/multiple_channel_logger.go @@ -0,0 +1,84 @@ +package loggers + +import ( + "fmt" + + kitlog "github.com/go-kit/kit/log" +) + +// We use go-kit log's Context (a Logger with a context from which you can +// generate further nested contexts) as our main logger type. In order to have +// independently consumed channels of logs we maintain a map of contexts. +// +// This intended as a primitive to implement a routing logger or leveled logger +// where the channel names are compile-time constants of such a module. +type MultipleChannelLogger interface { + // Log the message formed of keyvals to the the channelName logging channel + Log(channelName string, keyvals ...interface{}) error + + // Establish a context by appending contextual key-values to any existing + // contextual values + With(keyvals ...interface{}) MultipleChannelLogger + + // Establish a context by prepending contextual key-values to any existing + // contextual values + WithPrefix(keyvals ...interface{}) MultipleChannelLogger +} + +type multipleChannelLogger struct { + loggers map[string]*kitlog.Context +} + +// Pass in the map of named output loggers and get back a MultipleChannelLogger +// Each output logger will be wrapped as a ChannelLogger so will be non-blocking +// on calls to Log and provided the output loggers are not written to by any other +// means calls to MultipleChannelLogger will be safe for concurrent access +func NewMultipleChannelLogger(channelLoggers map[string]kitlog.Logger) MultipleChannelLogger { + mcl := multipleChannelLogger{ + loggers: make(map[string]*kitlog.Context, len(channelLoggers)), + } + for name, logger := range channelLoggers { + // Make a channel with a nil logger a noop + if logger != nil { + mcl.loggers[name] = kitlog.NewContext(NonBlockingLogger(logger)). + With("channel", name) + } + } + return &mcl +} + +// 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(channelName string, keyvals ...interface{}) error { + logger := mcl.loggers[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...) +} + +// Like go-kit log's With method only it establishes a new Context for each +// logging channel +func (mcl *multipleChannelLogger) With(keyvals ...interface{}) MultipleChannelLogger { + loggers := make(map[string]*kitlog.Context, len(mcl.loggers)) + for name, logger := range mcl.loggers { + loggers[name] = logger.With(keyvals...) + } + return &multipleChannelLogger{ + loggers: loggers, + } +} + +// Like go-kit log's With method only it establishes a new Context for each +// logging channel +func (mcl *multipleChannelLogger) WithPrefix(keyvals ...interface{}) MultipleChannelLogger { + loggers := make(map[string]*kitlog.Context, len(mcl.loggers)) + for name, logger := range mcl.loggers { + loggers[name] = logger.WithPrefix(keyvals...) + } + return &multipleChannelLogger{ + loggers: loggers, + } +} diff --git a/logging/loggers/multiple_channel_logger_test.go b/logging/loggers/multiple_channel_logger_test.go new file mode 100644 index 00000000..99a2cdc9 --- /dev/null +++ b/logging/loggers/multiple_channel_logger_test.go @@ -0,0 +1,26 @@ +package loggers + +import ( + "runtime" + "testing" + "time" + + kitlog "github.com/go-kit/kit/log" + "github.com/stretchr/testify/assert" +) + +func TestMultipleChannelLogger(t *testing.T) { + boringLogger, interestingLogger := newTestLogger(), newTestLogger() + mcl := NewMultipleChannelLogger(map[string]kitlog.Logger{ + "Boring": boringLogger, + "Interesting": interestingLogger, + }) + err := mcl.With("time", kitlog.Valuer(func() interface{} { return "aa" })). + Log("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", "foo", "bar"}, + boringLogger.logLines[0]) +} diff --git a/logging/loggers/multiple_output_logger.go b/logging/loggers/multiple_output_logger.go new file mode 100644 index 00000000..1eb7bf2d --- /dev/null +++ b/logging/loggers/multiple_output_logger.go @@ -0,0 +1,48 @@ +package loggers + +import ( + "strings" + + kitlog "github.com/go-kit/kit/log" +) + +type MultipleOutputLogger []kitlog.Logger + +var _ kitlog.Logger = MultipleOutputLogger(nil) + +func (mol MultipleOutputLogger) Log(keyvals ...interface{}) error { + var errs []error + for _, logger := range mol { + err := logger.Log(keyvals...) + if err != nil { + errs = append(errs, err) + } + } + return combineErrors(errs) +} + +// Creates a logger that forks log messages to each of its outputLoggers +func NewMultipleOutputLogger(outputLoggers ...kitlog.Logger) kitlog.Logger { + return MultipleOutputLogger(outputLoggers) +} + +type multipleErrors []error + +func combineErrors(errs []error) error { + switch len(errs) { + case 0: + return nil + case 1: + return errs[0] + default: + return multipleErrors(errs) + } +} + +func (errs multipleErrors) Error() string { + var errStrings []string + for _, err := range errs { + errStrings = append(errStrings, err.Error()) + } + return strings.Join(errStrings, ";") +} diff --git a/logging/loggers/multiple_output_logger_test.go b/logging/loggers/multiple_output_logger_test.go new file mode 100644 index 00000000..786c6006 --- /dev/null +++ b/logging/loggers/multiple_output_logger_test.go @@ -0,0 +1,18 @@ +package loggers + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +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...) + expected := [][]interface{}{logLine} + assert.Equal(t, expected, a.logLines) + assert.Equal(t, expected, b.logLines) + assert.IsType(t, multipleErrors{}, err) +} diff --git a/rpc/tendermint/test/shared.go b/rpc/tendermint/test/shared.go index d211bd5d..633ec041 100644 --- a/rpc/tendermint/test/shared.go +++ b/rpc/tendermint/test/shared.go @@ -21,6 +21,7 @@ import ( "path" + "github.com/eris-ltd/eris-db/logging/loggers" state_types "github.com/eris-ltd/eris-db/manager/eris-mint/state/types" "github.com/spf13/viper" tm_common "github.com/tendermint/go-common" @@ -83,7 +84,8 @@ func initGlobalVariables(ffs *fixtures.FileFixtures) error { // Set up priv_validator.json before we start tendermint (otherwise it will // create its own one. saveNewPriv() - testCore, err = core.NewCore("testCore", consensusConfig, managerConfig) + testCore, err = core.NewCore("testCore", consensusConfig, managerConfig, + loggers.NewNoopInfoTraceLogger()) if err != nil { return err } diff --git a/txs/log.go b/txs/log.go deleted file mode 100644 index b967a58d..00000000 --- a/txs/log.go +++ /dev/null @@ -1,7 +0,0 @@ -package txs - -import ( - "github.com/tendermint/go-logger" -) - -var log = logger.New("module", "types") -- GitLab