From b5540a4008a4e27ca7ed46209c5addd9eead960f Mon Sep 17 00:00:00 2001 From: Mitja T Date: Fri, 29 Apr 2022 17:17:55 +0200 Subject: [PATCH] Address review comments - extract wrapper from helpers.go to a new logger.go - extract max buffer size constant - log lines with no specified level at INFO --- go/runtime/host/helpers.go | 118 ---------------- go/runtime/host/logger.go | 128 ++++++++++++++++++ .../host/{helpers_test.go => logger_test.go} | 6 +- 3 files changed, 132 insertions(+), 120 deletions(-) create mode 100644 go/runtime/host/logger.go rename go/runtime/host/{helpers_test.go => logger_test.go} (88%) diff --git a/go/runtime/host/helpers.go b/go/runtime/host/helpers.go index d0072e5e961..5d23e132e9c 100644 --- a/go/runtime/host/helpers.go +++ b/go/runtime/host/helpers.go @@ -2,14 +2,11 @@ package host import ( "context" - "encoding/json" "fmt" - "strings" beacon "github.com/oasisprotocol/oasis-core/go/beacon/api" "github.com/oasisprotocol/oasis-core/go/common/cbor" "github.com/oasisprotocol/oasis-core/go/common/errors" - "github.com/oasisprotocol/oasis-core/go/common/logging" consensus "github.com/oasisprotocol/oasis-core/go/consensus/api" "github.com/oasisprotocol/oasis-core/go/roothash/api/block" "github.com/oasisprotocol/oasis-core/go/runtime/host/protocol" @@ -171,118 +168,3 @@ func (r *richRuntime) ConsensusSync(ctx context.Context, height uint64) error { func NewRichRuntime(rt Runtime) RichRuntime { return &richRuntime{Runtime: rt} } - -// RuntimeLogger is a Writer that interprets data written to it as JSON-formatted -// runtime logs, and re-logs the messages as oasis-node logs. For example, it -// translates runtime log levels to oasis-node log levels, because the two have -// slightly different formats. -// -// It hardcodes some assumptions about the format of the runtime logs. -type RuntimeLogWrapper struct { - // Logger for wrapper-internal info/errors. - logger *logging.Logger - // Loggers for the runtime, one for each module inside the runtime. - rtLoggers map[string]*logging.Logger - // Key-value pairs to append to each log entry. - suffixes []interface{} - // Buffer for accumulating incoming log entries from the runtime. - buf []byte -} - -// NewRuntimeLogWrapper creates a new RuntimeLogWrapper. -func NewRuntimeLogWrapper(logger *logging.Logger, suffixes ...interface{}) *RuntimeLogWrapper { - return &RuntimeLogWrapper{ - logger: logger, - suffixes: suffixes, - rtLoggers: make(map[string]*logging.Logger), - } -} - -// Implements io.Writer -func (w *RuntimeLogWrapper) Write(chunk []byte) (int, error) { - w.buf = append(w.buf, chunk...) - - // Find and process any full lines that have accumulated in the buffer. - // We assume one line per log entry. - for i := len(w.buf) - len(chunk); i < len(w.buf); i++ { - if w.buf[i] == '\n' { - w.processLogLine(w.buf[:i]) - w.buf = w.buf[i+1:] - i = 0 - } - } - - // Prevent the buffer from growing indefinitely in case runtime logs - // don't contain newlines (e.g. because of unexpected log format). - if len(w.buf) > 10_000_000 { - w.logger.Warn("runtime log buffer is too large, dropping logs") - w.buf = w.buf[:0] - } - - // Always report success. Even if log lines were malformed, we processed them - // and reported the malformedness. - return len(chunk), nil -} - -// rtLogger returns the logger for the given module, creating it if needed. -func (w *RuntimeLogWrapper) rtLogger(module string) *logging.Logger { - if l, ok := w.rtLoggers[module]; ok { - return l - } - l := logging.GetBaseLogger(module).With(w.suffixes...) - w.rtLoggers[module] = l - return l -} - -func (w RuntimeLogWrapper) processLogLine(line []byte) { - // Interpret line as JSON. - var m map[string]interface{} - if err := json.Unmarshal(line, &m); err != nil { - w.logger.Warn("non-JSON log line from runtime", "log_line", string(line), "err", err) - return - } - - // Destructure JSON into key-value pairs, parse common fields. - var kv []interface{} - var msg string - var level string - var module string - for k, v := range m { - if k == "msg" { - if _msg, ok := v.(string); ok { - msg = _msg - } else { - w.logger.Warn("malformed log line from runtime", "log_line", string(line), "err", "msg is not a string") - return - } - } else if k == "level" { - level, _ = v.(string) - } else if k == "module" { - module, _ = v.(string) - if module == "" { - module = "runtime" - } - // Enforce "runtime" scope in the module name. - if !(module == "runtime" || strings.HasPrefix(module, "runtime/")) { - module = "runtime/" + module - } - } else { - kv = append(kv, k, v) - } - } - - // Output the log. - rtLogger := w.rtLogger(module) - switch level { - case "DEBG": - rtLogger.Debug(msg, kv...) - case "INFO": - rtLogger.Info(msg, kv...) - case "WARN": - rtLogger.Warn(msg, kv...) - case "ERRO": - rtLogger.Error(msg, kv...) - default: - w.logger.Warn("log line from runtime has no known error level set, using INFO", "log_line", string(line)) - } -} diff --git a/go/runtime/host/logger.go b/go/runtime/host/logger.go new file mode 100644 index 00000000000..8a27686c6e5 --- /dev/null +++ b/go/runtime/host/logger.go @@ -0,0 +1,128 @@ +package host + +import ( + "encoding/json" + "strings" + + "github.com/oasisprotocol/oasis-core/go/common/logging" +) + +// Max number of bytes to buffer in the runtime log wrapper, i.e. roughly +// the longest expected valid log line from the runtime. +const maxLogBufferSize = 10_000_000 + +// RuntimeLogWrapper is a Writer that interprets data written to it as JSON-formatted +// runtime logs, and re-logs the messages as oasis-node logs. For example, it +// translates runtime log levels to oasis-node log levels, because the two have +// slightly different formats. +// +// It hardcodes some assumptions about the format of the runtime logs. +type RuntimeLogWrapper struct { + // Logger for wrapper-internal info/errors. + logger *logging.Logger + // Loggers for the runtime, one for each module inside the runtime. + rtLoggers map[string]*logging.Logger + // Key-value pairs to append to each log entry. + suffixes []interface{} + // Buffer for accumulating incoming log entries from the runtime. + buf []byte +} + +// NewRuntimeLogWrapper creates a new RuntimeLogWrapper. +func NewRuntimeLogWrapper(logger *logging.Logger, suffixes ...interface{}) *RuntimeLogWrapper { + return &RuntimeLogWrapper{ + logger: logger, + suffixes: suffixes, + rtLoggers: make(map[string]*logging.Logger), + } +} + +// Implements io.Writer +func (w *RuntimeLogWrapper) Write(chunk []byte) (int, error) { + w.buf = append(w.buf, chunk...) + + // Find and process any full lines that have accumulated in the buffer. + // We assume one line per log entry. + for i := len(w.buf) - len(chunk); i < len(w.buf); i++ { + if w.buf[i] == '\n' { + w.processLogLine(w.buf[:i]) + w.buf = w.buf[i+1:] + i = 0 + } + } + + // Prevent the buffer from growing indefinitely in case runtime logs + // don't contain newlines (e.g. because of unexpected log format). + if len(w.buf) > maxLogBufferSize { + w.logger.Warn("runtime log buffer is too large, dropping logs") + w.buf = w.buf[:0] + } + + // Always report success. Even if log lines were malformed, we processed them + // and reported the malformedness. + return len(chunk), nil +} + +// rtLogger returns the logger for the given module, creating it if needed. +func (w *RuntimeLogWrapper) rtLogger(module string) *logging.Logger { + if l, ok := w.rtLoggers[module]; ok { + return l + } + l := logging.GetBaseLogger(module).With(w.suffixes...) + w.rtLoggers[module] = l + return l +} + +func (w RuntimeLogWrapper) processLogLine(line []byte) { + // Interpret line as JSON. + var m map[string]interface{} + if err := json.Unmarshal(line, &m); err != nil { + w.logger.Warn("non-JSON log line from runtime", "log_line", string(line), "err", err) + return + } + + // Destructure JSON into key-value pairs, parse common fields. + var kv []interface{} + var msg string + var level string + var module string + for k, v := range m { + if k == "msg" { + if _msg, ok := v.(string); ok { + msg = _msg + } else { + w.logger.Warn("malformed log line from runtime", "log_line", string(line), "err", "msg is not a string") + return + } + } else if k == "level" { + level, _ = v.(string) + } else if k == "module" { + module, _ = v.(string) + if module == "" { + module = "runtime" + } + // Enforce "runtime" scope in the module name. + if !(module == "runtime" || strings.HasPrefix(module, "runtime/")) { + module = "runtime/" + module + } + } else { + kv = append(kv, k, v) + } + } + + // Output the log. + rtLogger := w.rtLogger(module) + switch level { + case "DEBG": + rtLogger.Debug(msg, kv...) + case "INFO": + rtLogger.Info(msg, kv...) + case "WARN": + rtLogger.Warn(msg, kv...) + case "ERRO": + rtLogger.Error(msg, kv...) + default: + w.logger.Warn("log line from runtime has no known error level set, using INFO", "log_line", string(line)) + rtLogger.Info(msg, kv...) + } +} diff --git a/go/runtime/host/helpers_test.go b/go/runtime/host/logger_test.go similarity index 88% rename from go/runtime/host/helpers_test.go rename to go/runtime/host/logger_test.go index c100bebecda..cb807e7bf8b 100644 --- a/go/runtime/host/helpers_test.go +++ b/go/runtime/host/logger_test.go @@ -38,7 +38,9 @@ func TestRuntimeLogWrapper(t *testing.T) { // Feed data to RuntimeLogWrapper. w := NewRuntimeLogWrapper(logging.GetLogger("testenv")) for _, chunk := range logChunks { - w.Write([]byte(chunk)) + n, err := w.Write([]byte(chunk)) + require.Equal(len(chunk), n) + require.NoError(err) } actual := strings.Split(buf.String(), "\n") @@ -47,7 +49,7 @@ func TestRuntimeLogWrapper(t *testing.T) { `{"level":"info","module":"runtime","msg":"My info\\nwith a newline","ts":"2022"}`, `{"level":"debug","module":"runtime/dispatcher","msg":"My debug","ts":"2022-04-27"}`, `{"err":"some explanation","level":"error","module":"runtime/protocol","msg":"My error","ts":"2022-04-28"}`, - `{"caller":"helpers.go:\d+","err":"invalid character 'R' looking for beginning of value","level":"warn","log_line":"\\t\\tRandom crap","module":"testenv","msg":"non-JSON log line from runtime","ts":"[^"]+"}`, + `{"caller":"logger.go:\d+","err":"invalid character 'R' looking for beginning of value","level":"warn","log_line":"\\t\\tRandom crap","module":"testenv","msg":"non-JSON log line from runtime","ts":"[^"]+"}`, `{"level":"info","module":"runtime/foo","msg":"Should be recovered","ts":"2022"}`, ``, // Because we split on newline and the last log entry ends with a newline }