From 0c24967776071ed8d264c6891c9433bfe93f08c7 Mon Sep 17 00:00:00 2001
From: Silas Davis <github@silasdavis.net>
Date: Wed, 24 Jan 2018 20:48:21 +0000
Subject: [PATCH] Added back FileLogger and ability to send Sync message
(needed for other buffered loggers), fixed a few logging-related things, and
added cooldown wait in shutdown to Gosched the logging ring buffer.
Signed-off-by: Silas Davis <silas@monax.io>
---
core/kernel.go | 7 +++
logging/config/sinks.go | 58 +++++++++++++++++++------
logging/config/sinks_test.go | 18 ++++++++
logging/convention.go | 19 ++++++++
logging/loggers/burrow_format_logger.go | 6 +--
logging/loggers/output_loggers.go | 31 +++++++++++--
logging/loggers/output_loggers_test.go | 43 ++++++++++++++++++
logging/structure/structure.go | 6 +++
8 files changed, 168 insertions(+), 20 deletions(-)
create mode 100644 logging/loggers/output_loggers_test.go
diff --git a/core/kernel.go b/core/kernel.go
index 5465f046..46376d4b 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 c96712f2..3974fd5f 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 fbe035bb..a0d78358 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 0772efcc..65dc2e5b 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 d3a61864..d0a9a410 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 a9a88ffe..6cd2e3d2 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 00000000..7c229c66
--- /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 6946270c..f929c474 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
}
+
+
--
GitLab