Log (JSON) formatting hook; span export

Added formatting for logrus export hook to marshal structs as JSON
strings, as well as format other known types (eg, time.Time).

Updated span export to:
* include span kind
* include status code
* log if span attributes were dropped

Added helper `log.Format*` functions to format Time and other structs
to JSON. This is already done by the logging hook, but allows spans
format their attributes consistently, since they must be converted to
strings before being exported.

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>

internal/hcserror/helper.go

@@ -0,0 +1,13 @@
+package hcserror
+
+import "errors"
+
+// IsAny returns true if errors.Is is true for any of the provided errors, errs.
+func IsAny(err error, errs ...error) bool {
+ for _, e := range errs {
+ if errors.Is(err, e) {
+ return true
+ }
+ }
+ return false
+}

internal/log/format.go

@@ -0,0 +1,90 @@
+package log
+
+import (
+ "bytes"
+ "context"
+ "encoding/json"
+ "fmt"
+ "net"
+ "reflect"
+ "time"
+
+ "github.com/containerd/containerd/log"
+ "github.com/sirupsen/logrus"
+)
+
+const TimeFormat = log.RFC3339NanoFixed
+
+func FormatTime(t time.Time) string {
+ return t.Format(TimeFormat)
+}
+
+// FormatIO formats net.Conn and other types that have an `Addr()` or `Name()`.
+//
+// See FormatEnabled for more information.
+func FormatIO(ctx context.Context, v interface{}) string {
+ m := make(map[string]string)
+ m["type"] = reflect.TypeOf(v).String()
+
+ switch t := v.(type) {
+ case net.Conn:
+ m["local_address"] = formatAddr(t.LocalAddr())
+ m["remote_address"] = formatAddr(t.RemoteAddr())
+ case interface{ Addr() net.Addr }:
+ m["address"] = formatAddr(t.Addr())
+ default:
+ return Format(ctx, t)
+ }
+
+ return Format(ctx, m)
+}
+
+func formatAddr(a net.Addr) string {
+ return a.Network() + "://" + a.String()
+}
+
+// Format formats an object into a JSON string, without any indendtation or
+// HTML escapes.
+// Context is used to output a log waring if the conversion fails.
+//
+// This is intended primarily for `trace.StringAttribute()`
+func Format(ctx context.Context, v interface{}) string {
+ b, err := encode(v)
+ if err != nil {
+ G(ctx).WithError(err).Warning("could not format value")
+ return ""
+ }
+
+ return string(b)
+}
+
+func encode(v interface{}) ([]byte, error) {
+ return encodeBuffer(&bytes.Buffer{}, v)
+}
+
+func encodeBuffer(buf *bytes.Buffer, v interface{}) ([]byte, error) {
+ enc := json.NewEncoder(buf)
+ enc.SetEscapeHTML(false)
+ enc.SetIndent("", "")
+
+ if err := enc.Encode(v); err != nil {
+ err = fmt.Errorf("could not marshall %T to JSON for logging: %w", v, err)
+ return nil, err
+ }
+
+ // encoder.Encode appends a newline to the end
+ return bytes.TrimSpace(buf.Bytes()), nil
+}
+
+// GetCallerName checks if the entry appears caller caller information and returns the function name.
+//
+// This is intended to be used with "github.com/Microsoft/go-winio/pkg/etwlogrus".WithGetName.
+func GetCallerName(e *logrus.Entry) string {
+ if e.Caller == nil {
+ return ""
+ }
+ if e.Caller.Func != nil {
+ return e.Caller.Func.Name()
+ }
+ return e.Caller.Function
+}

internal/log/hook.go

@@ -1,35 +1,147 @@
 package log
 
 import (
+ "bytes"
+ "reflect"
+ "time"
+
  "github.com/Microsoft/hcsshim/internal/logfields"
+ "github.com/containerd/containerd/log"
  "github.com/sirupsen/logrus"
  "go.opencensus.io/trace"
 )
 
+const nullString = "null"
+
 // Hook serves to intercept and format `logrus.Entry`s before they are passed
 // to the ETW hook.
 //
 // The containerd shim discards the (formatted) logrus output, and outputs only via ETW.
 // The Linux GCS outputs logrus entries over stdout, which is consumed by the shim and
 // then re-output via the ETW hook.
-type Hook struct{}
+type Hook struct {
+ // EncodeAsJSON formats structs, maps, arrays, slices, and `bytes.Buffer` as JSON.
+ // Variables of `bytes.Buffer` will be converted to `[]byte`.
+ //
+ // Default is true.
+ EncodeAsJSON bool
+
+ // FormatTime specifies the format for `time.Time` variables.
+ // An empty string disabled formatting.
+ //
+ // Default is `"github.com/containerd/containerd/log".RFC3339NanoFixed`.
+ TimeFormat string
+
+ // AddSpanContext adds `logfields.TraceID` and `logfields.SpanID` fields to
+ // the entry from the span context stored in `(*entry).Context`, if it exists.
+ AddSpanContext bool
+
+ // Whether to encode errors or keep them as is.
+ EncodeError bool
+}
 
 var _ logrus.Hook = &Hook{}
 
 func NewHook() *Hook {
- return &Hook{}
+ return &Hook{
+ EncodeAsJSON: true,
+ TimeFormat: log.RFC3339NanoFixed,
+ AddSpanContext: true,
+ }
 }
 
 func (h *Hook) Levels() []logrus.Level {
  return logrus.AllLevels
 }
 
 func (h *Hook) Fire(e *logrus.Entry) (err error) {
+ // JSON encode, if necessary, then add span information
+ h.encode(e)
  h.addSpanContext(e)
 
  return nil
 }
 
+func (h *Hook) encode(e *logrus.Entry) {
+ d := e.Data
+
+ formatTime := len(h.TimeFormat) > 0
+ if !(h.EncodeAsJSON || formatTime) {
+ return
+ }
+
+ // todo: replace these with constraints.Integer, constraints.Float, etc with go1.18
+ for k, v := range d {
+ if !h.EncodeError {
+ if _, ok := v.(error); k == logrus.ErrorKey || ok {
+ continue
+ }
+ }
+
+ if formatTime {
+ switch vv := v.(type) {
+ case time.Time:
+ d[k] = vv.Format(h.TimeFormat)
+ continue
+ }
+ }
+
+ if !h.EncodeAsJSON {
+ continue
+ }
+
+ switch vv := v.(type) {
+ // built in types
+ case bool, string, error, uintptr,
+ int8, int16, int32, int64, int,
+ uint8, uint32, uint64, uint,
+ float32, float64:
+ continue
+
+ case time.Duration:
+ d[k] = vv.String()
+ continue
+
+ // Rather than setting d[k] = vv.String(), JSON encode []byte value, since it
+ // may be a binary payload and not representable as a string.
+ // `case bytes.Buffer,*bytes.Buffer:` resolves `vv` to `interface{}`,
+ // so cannot use `vv.Bytes`.
+ // Could move to below the `reflect.Indirect()` call below, but
+ // that would require additional typematching and dereferencing.
+ // Easier to keep these duplicate branches here.
+ case bytes.Buffer:
+ v = vv.Bytes()
+ case *bytes.Buffer:
+ v = vv.Bytes()
+ }
+
+ // dereference any pointers
+ rv := reflect.Indirect(reflect.ValueOf(v))
+ // check if `v` is a null pointer
+ if !rv.IsValid() {
+ d[k] = nullString
+ continue
+ }
+
+ switch rv.Kind() {
+ case reflect.Map, reflect.Struct, reflect.Array, reflect.Slice:
+ default:
+ continue
+ }
+
+ b, err := encode(v)
+ if err != nil {
+ // Errors are written to stderr (ie, to `panic.log`) and stops the remaining
+ // hooks (ie, exporting to ETW) from firing. So add encoding errors to
+ // the entry data to be written out, but keep on processing.
+ d[k+"-"+logrus.ErrorKey] = err.Error()
+ }
+
+ // if `err != nil`, then `b == nil` and this will be the empty string
+ d[k] = string(b)
+ }
+}
+
 func (h *Hook) addSpanContext(e *logrus.Entry) {
  ctx := e.Context
  if ctx == nil {

internal/log/scrub.go

@@ -4,7 +4,6 @@ import (
  "bytes"
  "encoding/json"
  "errors"
- "strings"
  "sync/atomic"
 
  hcsschema "github.com/Microsoft/hcsshim/internal/hcs/schema2"
@@ -56,11 +55,11 @@ func ScrubProcessParameters(s string) (string, error) {
  }
  pp.Environment = map[string]string{_scrubbedReplacement: _scrubbedReplacement}
 
- buf := bytes.NewBuffer(b[:0])
- if err := encode(buf, pp); err != nil {
+ b, err := encodeBuffer(bytes.NewBuffer(b[:0]), pp)
+ if err != nil {
  return "", err
  }
- return strings.TrimSpace(buf.String()), nil
+ return string(b), nil
 }
 
 // ScrubBridgeCreate scrubs requests sent over the bridge of type
@@ -150,21 +149,12 @@ func scrubBytes(b []byte, scrub scrubberFunc) ([]byte, error) {
  return nil, err
  }
 
- buf := &bytes.Buffer{}
- if err := encode(buf, m); err != nil {
+ b, err := encode(m)
+ if err != nil {
  return nil, err
  }
 
- return bytes.TrimSpace(buf.Bytes()), nil
-}
-
-func encode(buf *bytes.Buffer, v interface{}) error {
- enc := json.NewEncoder(buf)
- enc.SetEscapeHTML(false)
- if err := enc.Encode(v); err != nil {
- return err
- }
- return nil
+ return b, nil
 }
 
 func isRequestBase(m genMap) bool {

internal/oc/errors.go

@@ -0,0 +1,60 @@
+package oc
+
+import (
+ "io"
+ "net"
+ "os"
+
+ "github.com/containerd/containerd/errdefs"
+ "google.golang.org/grpc/codes"
+ "google.golang.org/grpc/status"
+
+ "github.com/Microsoft/hcsshim/internal/hcserror"
+)
+
+// todo: break import cycle with "internal/hcs" and errors errors defined there
+// todo: add errors defined in "internal/guest/gcserror" (Hresult does not implement error)
+
+func toStatusCode(err error) codes.Code {
+ // checks if err implements GRPCStatus() *"google.golang.org/grpc/status".Status,
+ // wraps an error defined in "github.com/containerd/containerd/errdefs", or is a
+ // context timeout or cancelled error
+ if s, ok := status.FromError(errdefs.ToGRPC(err)); ok {
+ return s.Code()
+ }
+
+ switch {
+ // case hcserror.IsAny(err):
+ // return codes.Cancelled
+ case hcserror.IsAny(err, os.ErrInvalid):
+ return codes.InvalidArgument
+ case hcserror.IsAny(err, os.ErrDeadlineExceeded):
+ return codes.DeadlineExceeded
+ case hcserror.IsAny(err, os.ErrNotExist):
+ return codes.NotFound
+ case hcserror.IsAny(err, os.ErrExist):
+ return codes.AlreadyExists
+ case hcserror.IsAny(err, os.ErrPermission):
+ return codes.PermissionDenied
+ // case hcserror.IsAny(err):
+ // return codes.ResourceExhausted
+ case hcserror.IsAny(err, os.ErrClosed, net.ErrClosed, io.ErrClosedPipe, io.ErrShortBuffer):
+ return codes.FailedPrecondition
+ // case hcserror.IsAny(err):
+ // return codes.Aborted
+ // case hcserror.IsAny(err):
+ // return codes.OutOfRange
+ // case hcserror.IsAny(err):
+ // return codes.Unimplemented
+ case hcserror.IsAny(err, io.ErrNoProgress):
+ return codes.Internal
+ // case hcserror.IsAny(err):
+ // return codes.Unavailable
+ case hcserror.IsAny(err, io.ErrShortWrite, io.ErrUnexpectedEOF):
+ return codes.DataLoss
+ // case hcserror.IsAny(err):
+ // return codes.Unauthenticated
+ default:
+ return codes.Unknown
+ }
+}