diff --git a/core/kernel.go b/core/kernel.go index 5465f0462007ace8a6262aadf0022d2785900a2b..46376d4b3c2c467159ee55bf50c3a2fa8f48ef9e 100644 --- a/core/kernel.go +++ b/core/kernel.go @@ -19,6 +19,7 @@ import ( "os" "os/signal" "sync" + "time" "fmt" @@ -40,6 +41,8 @@ import ( "github.com/tendermint/tmlibs/events" ) +const CooldownMilliseconds = 1000 + // Kernel is the root structure of Burrow type Kernel struct { eventSwitch events.EventSwitch @@ -160,6 +163,10 @@ func (kern *Kernel) Shutdown() (err error) { logging.InfoMsg(logger, "Shutting down Tendermint node") kern.tmNode.Stop() logging.InfoMsg(logger, "Shutdown complete") + logging.Sync(kern.logger) + // We don't want to wait for them, but yielding for a cooldown Let other goroutines flush + // potentially interesting final output (e.g. log messages) + time.Sleep(time.Millisecond * CooldownMilliseconds) close(kern.shutdownNotify) }) return diff --git a/logging/config/sinks.go b/logging/config/sinks.go index c96712f2339db5164c22b5ebca0d2bf3e934ea04..3974fd5fafdef85f761c74c5fd784eec863b5087 100644 --- a/logging/config/sinks.go +++ b/logging/config/sinks.go @@ -6,6 +6,7 @@ import ( "github.com/eapache/channels" kitlog "github.com/go-kit/kit/log" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/loggers" "github.com/hyperledger/burrow/logging/structure" ) @@ -22,6 +23,7 @@ const ( NoOutput outputType = "" Stdout outputType = "stdout" Stderr outputType = "stderr" + File outputType = "file" // TransformType NoTransform transformType = "" @@ -78,9 +80,7 @@ func (mode filterMode) MatchAny() bool { // Sink configuration types type ( // Outputs - GraylogConfig struct { - } - + // TODO: reintroduce syslog removed when we dropped log15 dependency SyslogConfig struct { Url string Tag string @@ -91,11 +91,10 @@ type ( } OutputConfig struct { - OutputType outputType - Format string - *GraylogConfig `json:",omitempty" toml:",omitempty"` - *FileConfig `json:",omitempty" toml:",omitempty"` - *SyslogConfig `json:",omitempty" toml:",omitempty"` + OutputType outputType + Format string + *FileConfig `json:",omitempty" toml:",omitempty"` + *SyslogConfig `json:",omitempty" toml:",omitempty"` } // Transforms @@ -191,6 +190,15 @@ func StderrOutput() *OutputConfig { } } +func FileOutput(path string) *OutputConfig { + return &OutputConfig{ + OutputType: File, + FileConfig: &FileConfig{ + Path: path, + }, + } +} + func CaptureTransform(name string, bufferCap int, passthrough bool) *TransformConfig { return &TransformConfig{ TransformType: Capture, @@ -272,8 +280,9 @@ func (sinkConfig *SinkConfig) BuildLogger() (kitlog.Logger, map[string]*loggers. return BuildLoggerFromSinkConfig(sinkConfig, make(map[string]*loggers.CaptureLogger)) } -func BuildLoggerFromSinkConfig(sinkConfig *SinkConfig, - captures map[string]*loggers.CaptureLogger) (kitlog.Logger, map[string]*loggers.CaptureLogger, error) { +func BuildLoggerFromSinkConfig(sinkConfig *SinkConfig, captures map[string]*loggers.CaptureLogger) (kitlog.Logger, + map[string]*loggers.CaptureLogger, error) { + if sinkConfig == nil { return kitlog.NewNopLogger(), captures, nil } @@ -282,11 +291,11 @@ func BuildLoggerFromSinkConfig(sinkConfig *SinkConfig, // 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) + var err error + outputLoggers[i], captures, err = BuildLoggerFromSinkConfig(sc, captures) if err != nil { - return nil, captures, err + return nil, nil, err } - outputLoggers[i] = l } // Grab the outputs after we have terminated any children sinks above @@ -301,7 +310,7 @@ func BuildLoggerFromSinkConfig(sinkConfig *SinkConfig, outputLogger := loggers.NewMultipleOutputLogger(outputLoggers...) if sinkConfig.Transform != nil && sinkConfig.Transform.TransformType != NoTransform { - return BuildTransformLogger(sinkConfig.Transform, captures, outputLogger) + return BuildTransformLoggerPassthrough(sinkConfig.Transform, captures, outputLogger) } return outputLogger, captures, nil } @@ -310,6 +319,8 @@ func BuildOutputLogger(outputConfig *OutputConfig) (kitlog.Logger, error) { switch outputConfig.OutputType { case NoOutput: return kitlog.NewNopLogger(), nil + case File: + return loggers.NewFileLogger(outputConfig.FileConfig.Path, outputConfig.Format) case Stdout: return loggers.NewStreamLogger(os.Stdout, outputConfig.Format), nil case Stderr: @@ -320,6 +331,16 @@ func BuildOutputLogger(outputConfig *OutputConfig) (kitlog.Logger, error) { } } +func BuildTransformLoggerPassthrough(transformConfig *TransformConfig, captures map[string]*loggers.CaptureLogger, + outputLogger kitlog.Logger) (kitlog.Logger, map[string]*loggers.CaptureLogger, error) { + + transformThenOutputLogger, captures, err := BuildTransformLogger(transformConfig, captures, outputLogger) + if err != nil { + return nil, nil, err + } + return signalPassthroughLogger(outputLogger, transformThenOutputLogger), captures, nil +} + func BuildTransformLogger(transformConfig *TransformConfig, captures map[string]*loggers.CaptureLogger, outputLogger kitlog.Logger) (kitlog.Logger, map[string]*loggers.CaptureLogger, error) { @@ -387,3 +408,12 @@ func BuildTransformLogger(transformConfig *TransformConfig, captures map[string] return nil, captures, fmt.Errorf("could not build logger for transform: '%s'", transformConfig.TransformType) } } + +func signalPassthroughLogger(ifSignalLogger kitlog.Logger, otherwiseLogger kitlog.Logger) kitlog.Logger { + return kitlog.LoggerFunc(func(keyvals ...interface{}) error { + if logging.Signal(keyvals) != "" { + return ifSignalLogger.Log(keyvals...) + } + return otherwiseLogger.Log(keyvals...) + }) +} diff --git a/logging/config/sinks_test.go b/logging/config/sinks_test.go index fbe035bb410310ba7b3b13e993ff924973f4121a..a0d7835863d55fc97e61a1fe942844530928700f 100644 --- a/logging/config/sinks_test.go +++ b/logging/config/sinks_test.go @@ -3,6 +3,11 @@ package config import ( "testing" + "fmt" + + "encoding/json" + + "github.com/hyperledger/burrow/logging" "github.com/stretchr/testify/assert" ) @@ -28,6 +33,19 @@ func TestBuildLoggerFromSinkConfig(t *testing.T) { captures["cap"].BufferLogger().FlushLogLines()) } +func TestFileLoggerSink(t *testing.T) { + sinkConfig := Sink(). + SetOutput(FileOutput("/tmp/logmclogface")).AddSinks( + Sink().SetOutput(FileOutput("/tmp/doubleloglog"))) + + bs, err := json.Marshal(sinkConfig) + assert.NoError(t, err) + + fmt.Println(string(bs)) + _, _, err = sinkConfig.BuildLogger() + assert.NoError(t, err) +} + func TestFilterSinks(t *testing.T) { sinkConfig := Sink(). SetOutput(StderrOutput()). diff --git a/logging/convention.go b/logging/convention.go index 0772efccd6578c07a0e318e7b8eb76b92f274a00..65dc2e5b98106caa86768139dbf509e0c321e92d 100644 --- a/logging/convention.go +++ b/logging/convention.go @@ -48,3 +48,22 @@ func Msg(logger kitlog.Logger, message string, keyvals ...interface{}) error { prepended := structure.CopyPrepend(keyvals, structure.MessageKey, message) return logger.Log(prepended...) } + +// Sends the sync signal which causes any syncing loggers to sync. +// loggers receiving the signal should drop the signal logline from output +func Sync(logger kitlog.Logger) error { + return logger.Log(structure.SignalKey, structure.SyncSignal) +} + +// Tried to interpret the logline as a signal by matching the last key-value pair as a signal, returns empty string if +// no match +func Signal(keyvals []interface{}) string { + last := len(keyvals) - 1 + if last > 0 && keyvals[last-1] == structure.SignalKey { + signal, ok := keyvals[last].(string) + if ok { + return signal + } + } + return "" +} diff --git a/logging/loggers/burrow_format_logger.go b/logging/loggers/burrow_format_logger.go index d3a61864a2dc6f0334000b8cf4b484de801b3340..d0a9a41031a70145f724de881f9e769bb09e89e9 100644 --- a/logging/loggers/burrow_format_logger.go +++ b/logging/loggers/burrow_format_logger.go @@ -33,15 +33,15 @@ type burrowFormatLogger struct { var _ kitlog.Logger = &burrowFormatLogger{} -func (efl *burrowFormatLogger) Log(keyvals ...interface{}) error { - if efl.logger == nil { +func (bfl *burrowFormatLogger) Log(keyvals ...interface{}) error { + if bfl.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)...) + return bfl.logger.Log(structure.MapKeyValues(keyvals, burrowFormatKeyValueMapper)...) } func burrowFormatKeyValueMapper(key, value interface{}) (interface{}, interface{}) { diff --git a/logging/loggers/output_loggers.go b/logging/loggers/output_loggers.go index a9a88ffe29e610d9386aa66bccff11f201d72711..6cd2e3d292742b317bbb84b5bfe6cf8ad2ceb91f 100644 --- a/logging/loggers/output_loggers.go +++ b/logging/loggers/output_loggers.go @@ -3,8 +3,11 @@ package loggers import ( "io" + "os" + kitlog "github.com/go-kit/kit/log" "github.com/go-kit/kit/log/term" + "github.com/hyperledger/burrow/logging" "github.com/hyperledger/burrow/logging/structure" "github.com/hyperledger/burrow/logging/types" ) @@ -17,13 +20,14 @@ const ( ) func NewStreamLogger(writer io.Writer, formatName string) kitlog.Logger { + var logger kitlog.Logger switch formatName { case JSONFormat: - return kitlog.NewJSONLogger(writer) + logger = kitlog.NewJSONLogger(writer) case LogfmtFormat: - return kitlog.NewLogfmtLogger(writer) + logger = kitlog.NewLogfmtLogger(writer) default: - return term.NewLogger(writer, kitlog.NewLogfmtLogger, func(keyvals ...interface{}) term.FgBgColor { + logger = term.NewLogger(writer, kitlog.NewLogfmtLogger, func(keyvals ...interface{}) term.FgBgColor { switch structure.Value(keyvals, structure.ChannelKey) { case types.TraceChannelName: return term.FgBgColor{Fg: term.DarkGreen} @@ -32,4 +36,25 @@ func NewStreamLogger(writer io.Writer, formatName string) kitlog.Logger { } }) } + // Don't log signals + return kitlog.LoggerFunc(func(keyvals ...interface{}) error { + if logging.Signal(keyvals) != "" { + return nil + } + return logger.Log(keyvals...) + }) +} + +func NewFileLogger(path string, formatName string) (kitlog.Logger, error) { + f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) + if err != nil { + return nil, err + } + streamLogger := NewStreamLogger(f, formatName) + return kitlog.LoggerFunc(func(keyvals ...interface{}) error { + if logging.Signal(keyvals) == structure.SyncSignal { + return f.Sync() + } + return streamLogger.Log(keyvals...) + }), nil } diff --git a/logging/loggers/output_loggers_test.go b/logging/loggers/output_loggers_test.go new file mode 100644 index 0000000000000000000000000000000000000000..7c229c66e108698150850dc8a4d8ad2c2346ea1b --- /dev/null +++ b/logging/loggers/output_loggers_test.go @@ -0,0 +1,43 @@ +package loggers + +import ( + "bytes" + "io/ioutil" + "testing" + + "github.com/hyperledger/burrow/logging" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestNewFileLogger(t *testing.T) { + f, err := ioutil.TempFile("", "TestNewFileLogger.log") + require.NoError(t, err) + logPath := f.Name() + f.Close() + fileLogger, err := NewFileLogger(logPath, JSONFormat) + require.NoError(t, err) + + err = fileLogger.Log("foo", "bar") + require.NoError(t, err) + + err = logging.Sync(fileLogger) + require.NoError(t, err) + + bs, err := ioutil.ReadFile(logPath) + + require.NoError(t, err) + assert.Equal(t, "{\"foo\":\"bar\"}\n", string(bs)) +} + +func TestNewStreamLogger(t *testing.T) { + buf := new(bytes.Buffer) + logger := NewStreamLogger(buf, LogfmtFormat) + err := logger.Log("oh", "my") + require.NoError(t, err) + + err = logging.Sync(logger) + require.NoError(t, err) + + assert.Equal(t, "oh=my\n", string(buf.Bytes())) +} diff --git a/logging/structure/structure.go b/logging/structure/structure.go index 6946270c8819770d4aa6ab5640949734b7492b8a..f929c4747453b91b6673822cf866ff30aa354409 100644 --- a/logging/structure/structure.go +++ b/logging/structure/structure.go @@ -36,6 +36,10 @@ const ( // Globally unique identifier persisting while a single instance (root process) // of this program/service is running RunId = "run_id" + // Provides special instructions (that may be ignored) to downstream loggers + SignalKey = "__signal__" + // The sync signal instructs sync-able loggers to sync + SyncSignal = "__sync__" ) // Pull the specified values from a structured log line into a map. @@ -182,3 +186,5 @@ func CopyPrepend(slice []interface{}, elements ...interface{}) []interface{} { } return newSlice } + +