Skip to content

Commit

Permalink
Address review comments
Browse files Browse the repository at this point in the history
- extract wrapper from helpers.go to a new logger.go
- extract max buffer size constant
- log lines with no specified level at INFO
  • Loading branch information
mitjat authored and kostko committed May 24, 2022
1 parent 123d0f1 commit b5540a4
Show file tree
Hide file tree
Showing 3 changed files with 132 additions and 120 deletions.
118 changes: 0 additions & 118 deletions go/runtime/host/helpers.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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))
}
}
128 changes: 128 additions & 0 deletions go/runtime/host/logger.go
Original file line number Diff line number Diff line change
@@ -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...)
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand All @@ -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
}
Expand Down

0 comments on commit b5540a4

Please sign in to comment.