From 0dcd415b04a937398c6137018396ea19a25ff2f2 Mon Sep 17 00:00:00 2001 From: Hamza El-Saawy Date: Thu, 21 Apr 2022 16:02:38 -0400 Subject: [PATCH 1/3] 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 --- internal/hcserror/helper.go | 13 ++++ internal/log/format.go | 90 ++++++++++++++++++++++++++++ internal/log/hook.go | 116 +++++++++++++++++++++++++++++++++++- internal/log/scrub.go | 22 ++----- internal/oc/errors.go | 60 +++++++++++++++++++ internal/oc/exporter.go | 100 +++++++++++++++++++++++++------ internal/oc/span.go | 14 ++++- 7 files changed, 378 insertions(+), 37 deletions(-) create mode 100644 internal/hcserror/helper.go create mode 100644 internal/log/format.go create mode 100644 internal/oc/errors.go diff --git a/internal/hcserror/helper.go b/internal/hcserror/helper.go new file mode 100644 index 0000000000..2c52ea25e1 --- /dev/null +++ b/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 +} diff --git a/internal/log/format.go b/internal/log/format.go new file mode 100644 index 0000000000..6588139afe --- /dev/null +++ b/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 +} diff --git a/internal/log/hook.go b/internal/log/hook.go index 8f89405923..cbaab8aa89 100644 --- a/internal/log/hook.go +++ b/internal/log/hook.go @@ -1,23 +1,53 @@ 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 { @@ -25,11 +55,93 @@ func (h *Hook) Levels() []logrus.Level { } 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 { diff --git a/internal/log/scrub.go b/internal/log/scrub.go index d51e0fd89f..d1ef15096e 100644 --- a/internal/log/scrub.go +++ b/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 { diff --git a/internal/oc/errors.go b/internal/oc/errors.go new file mode 100644 index 0000000000..85767f52be --- /dev/null +++ b/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 + } +} diff --git a/internal/oc/exporter.go b/internal/oc/exporter.go index f428bdaf72..279d1e406b 100644 --- a/internal/oc/exporter.go +++ b/internal/oc/exporter.go @@ -3,19 +3,26 @@ package oc import ( "github.com/sirupsen/logrus" "go.opencensus.io/trace" + "google.golang.org/grpc/codes" + + "github.com/Microsoft/hcsshim/internal/log" + "github.com/Microsoft/hcsshim/internal/logfields" ) -var _ = (trace.Exporter)(&LogrusExporter{}) +const spanMessage = "Span" + +var _errorCodeKey = logrus.ErrorKey + "Code" // LogrusExporter is an OpenCensus `trace.Exporter` that exports // `trace.SpanData` to logrus output. -type LogrusExporter struct { -} +type LogrusExporter struct{} + +var _ trace.Exporter = &LogrusExporter{} // ExportSpan exports `s` based on the the following rules: // -// 1. All output will contain `s.Attributes`, `s.TraceID`, `s.SpanID`, -// `s.ParentSpanID` for correlation +// 1. All output will contain `s.Attributes`, `s.SpanKind`, `s.TraceID`, +// `s.SpanID`, and `s.ParentSpanID` for correlation // // 2. Any calls to .Annotate will not be supported. // @@ -23,21 +30,80 @@ type LogrusExporter struct { // `s.Status.Code != 0` in which case it will be written at `logrus.ErrorLevel` // providing `s.Status.Message` as the error value. func (le *LogrusExporter) ExportSpan(s *trace.SpanData) { - // Combine all span annotations with traceID, spanID, parentSpanID - baseEntry := logrus.WithFields(logrus.Fields(s.Attributes)) - baseEntry.Data["traceID"] = s.TraceID.String() - baseEntry.Data["spanID"] = s.SpanID.String() - baseEntry.Data["parentSpanID"] = s.ParentSpanID.String() - baseEntry.Data["startTime"] = s.StartTime - baseEntry.Data["endTime"] = s.EndTime - baseEntry.Data["duration"] = s.EndTime.Sub(s.StartTime).String() - baseEntry.Data["name"] = s.Name - baseEntry.Time = s.StartTime + if s.DroppedAnnotationCount > 0 { + logrus.WithFields(logrus.Fields{ + "name": s.Name, + logfields.TraceID: s.TraceID.String(), + logfields.SpanID: s.SpanID.String(), + "dropped": s.DroppedAttributeCount, + "maxAttributes": len(s.Attributes), + }).Warning("span had dropped attributes") + } + + entry := log.L.Dup() + // Combine all span annotations with span data (eg, trace ID, span ID, parent span ID, + // error, status code) + // (OC) Span attributes are guaranteed to be strings, bools, or int64s, so we can + // can skip overhead in entry.WithFields() and add them directly to entry.Data. + // Preallocate ahead of time, since we should add, at most, 10 additional entries + data := make(logrus.Fields, len(entry.Data)+len(s.Attributes)+10) + + // Default log entry may have prexisting/application-wide data + for k, v := range entry.Data { + data[k] = v + } + for k, v := range s.Attributes { + data[k] = v + } + + data[logfields.Name] = s.Name + data[logfields.TraceID] = s.TraceID.String() + data[logfields.SpanID] = s.SpanID.String() + data[logfields.ParentSpanID] = s.ParentSpanID.String() + data[logfields.StartTime] = s.StartTime + data[logfields.EndTime] = s.EndTime + data[logfields.Duration] = s.EndTime.Sub(s.StartTime) + if sk := spanKindToString(s.SpanKind); sk != "" { + data["spanKind"] = sk + } level := logrus.InfoLevel if s.Status.Code != 0 { level = logrus.ErrorLevel - baseEntry.Data[logrus.ErrorKey] = s.Status.Message + + // don't overwrite an existing "error" or "errorCode" attributes + if _, ok := data[logrus.ErrorKey]; !ok { + data[logrus.ErrorKey] = s.Status.Message + } + if _, ok := data[_errorCodeKey]; !ok { + data[_errorCodeKey] = codes.Code(s.Status.Code).String() + } + } + + // // if caller information wont be overridden, use that to store span name + // if entry.Logger == nil || !entry.Logger.ReportCaller { + // entry.Caller = &runtime.Frame{ + // Function: s.Name, + // } + // } + + entry.Data = data + entry.Time = s.StartTime + entry.Log(level, spanMessage) +} + +// todo: after adding GetSpanName option to etwlogrus, switch from Name field in data +// to overridding entry.Caller information (and ensuring `logger.ReportCaller == false`) + +// GetSpanName checks if the entry appears to be span entry exported by the `LogrusExporter` +// and returns the span name. +// +// This is intended to be used with "github.com/Microsoft/go-winio/pkg/etwlogrus".WithGetName. +func GetSpanName(e *logrus.Entry) string { + // prioritize span name entry caller + if s, ok := (e.Data[logfields.Name]).(string); ok && e.Message == spanMessage { + return s } - baseEntry.Log(level, "Span") + + return log.GetCallerName(e) } diff --git a/internal/oc/span.go b/internal/oc/span.go index 0e2b7e9bf6..7260784326 100644 --- a/internal/oc/span.go +++ b/internal/oc/span.go @@ -14,8 +14,7 @@ var DefaultSampler = trace.AlwaysSample() func SetSpanStatus(span *trace.Span, err error) { status := trace.Status{} if err != nil { - // TODO: JTERRY75 - Handle errors in a non-generic way - status.Code = trace.StatusCodeUnknown + status.Code = int32(toStatusCode(err)) status.Message = err.Error() } span.SetStatus(status) @@ -46,3 +45,14 @@ func update(ctx context.Context, s *trace.Span) (context.Context, *trace.Span) { var WithServerSpanKind = trace.WithSpanKind(trace.SpanKindServer) var WithClientSpanKind = trace.WithSpanKind(trace.SpanKindClient) + +func spanKindToString(sk int) string { + switch sk { + case trace.SpanKindClient: + return "client" + case trace.SpanKindServer: + return "server" + default: + return "" + } +} From ff7acbf3274166c4937be1904e0d023fdccefcd6 Mon Sep 17 00:00:00 2001 From: Hamza El-Saawy Date: Tue, 4 Oct 2022 12:51:12 -0400 Subject: [PATCH 2/3] PR: docs, un-exported func, vestigial code Remove unused commented out code and left-over function. Signed-off-by: Hamza El-Saawy --- internal/hcserror/helper.go | 13 --------- internal/log/format.go | 13 +++++++-- internal/log/hook.go | 55 +++++++++++++++++++++++-------------- internal/oc/errors.go | 43 +++++++++++++++++------------ internal/oc/exporter.go | 23 ---------------- 5 files changed, 72 insertions(+), 75 deletions(-) delete mode 100644 internal/hcserror/helper.go diff --git a/internal/hcserror/helper.go b/internal/hcserror/helper.go deleted file mode 100644 index 2c52ea25e1..0000000000 --- a/internal/hcserror/helper.go +++ /dev/null @@ -1,13 +0,0 @@ -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 -} diff --git a/internal/log/format.go b/internal/log/format.go index 6588139afe..045215380f 100644 --- a/internal/log/format.go +++ b/internal/log/format.go @@ -19,6 +19,15 @@ func FormatTime(t time.Time) string { return t.Format(TimeFormat) } +// DurationFormat formats a [time.Duration] log entry. +// +// A nil value signals an error with the formatting. +type DurationFormat func(time.Duration) interface{} + +func DurationFormatString(d time.Duration) interface{} { return d.String() } +func DurationFormatSeconds(d time.Duration) interface{} { return d.Seconds() } +func DurationFormatMilliseconds(d time.Duration) interface{} { return d.Milliseconds() } + // FormatIO formats net.Conn and other types that have an `Addr()` or `Name()`. // // See FormatEnabled for more information. @@ -28,8 +37,8 @@ func FormatIO(ctx context.Context, v interface{}) string { switch t := v.(type) { case net.Conn: - m["local_address"] = formatAddr(t.LocalAddr()) - m["remote_address"] = formatAddr(t.RemoteAddr()) + m["localAddress"] = formatAddr(t.LocalAddr()) + m["remoteAddress"] = formatAddr(t.RemoteAddr()) case interface{ Addr() net.Addr }: m["address"] = formatAddr(t.Addr()) default: diff --git a/internal/log/hook.go b/internal/log/hook.go index cbaab8aa89..50c1c72fb8 100644 --- a/internal/log/hook.go +++ b/internal/log/hook.go @@ -13,27 +13,32 @@ import ( const nullString = "null" -// Hook serves to intercept and format `logrus.Entry`s before they are passed -// to the ETW hook. +// Hook intercepts and formats a [logrus.Entry] before it logged. // -// 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. +// The shim either outputs the logs through an ETW hook, discarding the (formatted) output +// or logs output to a pipe for logging binaries to consume. +// The Linux GCS outputs logrus entries over stdout, which is then consumed and re-output +// by the shim. type Hook struct { - // EncodeAsJSON formats structs, maps, arrays, slices, and `bytes.Buffer` as JSON. - // Variables of `bytes.Buffer` will be converted to `[]byte`. + // 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. + // FormatTime specifies the format for [time.Time] variables. // An empty string disabled formatting. // - // Default is `"github.com/containerd/containerd/log".RFC3339NanoFixed`. + // 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. + // Duration format converts a [time.Duration] fields to an appropriate encoding. + // + // Default is [DurationFormatSeconds]. + DurationFormat DurationFormat + + // AddSpanContext adds [logfields.TraceID] and [logfields.SpanID] fields to + // the entry from the span context stored in [logrus.Entry.Context], if it exists. AddSpanContext bool // Whether to encode errors or keep them as is. @@ -46,6 +51,7 @@ func NewHook() *Hook { return &Hook{ EncodeAsJSON: true, TimeFormat: log.RFC3339NanoFixed, + DurationFormat: DurationFormatSeconds, AddSpanContext: true, } } @@ -62,15 +68,23 @@ func (h *Hook) Fire(e *logrus.Entry) (err error) { return nil } +// encode loops through all the fields in the [logrus.Entry] and encodes them according to +// the settings in [Hook]. +// If [Hook.TimeFormat] is non-empty, it will be passed to [time.Time.Format] for +// fields of type [time.Time]. +// If [Hook.EncodeAsJSON] is true, then fields that are numeric, boolean, strings, or +// errors will be encoded via a [json.NewEncoder] in encode(). +// +// If [Hook.TimeFormat] is empty and [Hook.EncodeAsJSON] is false, then this is a no-op. func (h *Hook) encode(e *logrus.Entry) { d := e.Data - formatTime := len(h.TimeFormat) > 0 + formatTime := h.TimeFormat != "" if !(h.EncodeAsJSON || formatTime) { return } - // todo: replace these with constraints.Integer, constraints.Float, etc with go1.18 + // todo: replace these with constraints.Integer, constraints.Float, etc in go1.18 for k, v := range d { if !h.EncodeError { if _, ok := v.(error); k == logrus.ErrorKey || ok { @@ -78,12 +92,9 @@ func (h *Hook) encode(e *logrus.Entry) { } } - if formatTime { - switch vv := v.(type) { - case time.Time: - d[k] = vv.Format(h.TimeFormat) - continue - } + if t, ok := v.(time.Time); formatTime && ok { + d[k] = t.Format(h.TimeFormat) + continue } if !h.EncodeAsJSON { @@ -99,7 +110,11 @@ func (h *Hook) encode(e *logrus.Entry) { continue case time.Duration: - d[k] = vv.String() + if h.DurationFormat != nil { + if i := h.DurationFormat(vv); i != nil { + d[k] = i + } + } continue // Rather than setting d[k] = vv.String(), JSON encode []byte value, since it diff --git a/internal/oc/errors.go b/internal/oc/errors.go index 85767f52be..e63b4785d9 100644 --- a/internal/oc/errors.go +++ b/internal/oc/errors.go @@ -1,6 +1,7 @@ package oc import ( + "errors" "io" "net" "os" @@ -8,8 +9,6 @@ import ( "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 @@ -24,37 +23,47 @@ func toStatusCode(err error) codes.Code { } switch { - // case hcserror.IsAny(err): + // case IsAny(err): // return codes.Cancelled - case hcserror.IsAny(err, os.ErrInvalid): + case isAny(err, os.ErrInvalid): return codes.InvalidArgument - case hcserror.IsAny(err, os.ErrDeadlineExceeded): + case isAny(err, os.ErrDeadlineExceeded): return codes.DeadlineExceeded - case hcserror.IsAny(err, os.ErrNotExist): + case isAny(err, os.ErrNotExist): return codes.NotFound - case hcserror.IsAny(err, os.ErrExist): + case isAny(err, os.ErrExist): return codes.AlreadyExists - case hcserror.IsAny(err, os.ErrPermission): + case isAny(err, os.ErrPermission): return codes.PermissionDenied - // case hcserror.IsAny(err): + // case IsAny(err): // return codes.ResourceExhausted - case hcserror.IsAny(err, os.ErrClosed, net.ErrClosed, io.ErrClosedPipe, io.ErrShortBuffer): + case isAny(err, os.ErrClosed, net.ErrClosed, io.ErrClosedPipe, io.ErrShortBuffer): return codes.FailedPrecondition - // case hcserror.IsAny(err): + // case IsAny(err): // return codes.Aborted - // case hcserror.IsAny(err): + // case IsAny(err): // return codes.OutOfRange - // case hcserror.IsAny(err): + // case IsAny(err): // return codes.Unimplemented - case hcserror.IsAny(err, io.ErrNoProgress): + case isAny(err, io.ErrNoProgress): return codes.Internal - // case hcserror.IsAny(err): + // case IsAny(err): // return codes.Unavailable - case hcserror.IsAny(err, io.ErrShortWrite, io.ErrUnexpectedEOF): + case isAny(err, io.ErrShortWrite, io.ErrUnexpectedEOF): return codes.DataLoss - // case hcserror.IsAny(err): + // case IsAny(err): // return codes.Unauthenticated default: return codes.Unknown } } + +// 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 +} diff --git a/internal/oc/exporter.go b/internal/oc/exporter.go index 279d1e406b..28f8f43a93 100644 --- a/internal/oc/exporter.go +++ b/internal/oc/exporter.go @@ -80,30 +80,7 @@ func (le *LogrusExporter) ExportSpan(s *trace.SpanData) { } } - // // if caller information wont be overridden, use that to store span name - // if entry.Logger == nil || !entry.Logger.ReportCaller { - // entry.Caller = &runtime.Frame{ - // Function: s.Name, - // } - // } - entry.Data = data entry.Time = s.StartTime entry.Log(level, spanMessage) } - -// todo: after adding GetSpanName option to etwlogrus, switch from Name field in data -// to overridding entry.Caller information (and ensuring `logger.ReportCaller == false`) - -// GetSpanName checks if the entry appears to be span entry exported by the `LogrusExporter` -// and returns the span name. -// -// This is intended to be used with "github.com/Microsoft/go-winio/pkg/etwlogrus".WithGetName. -func GetSpanName(e *logrus.Entry) string { - // prioritize span name entry caller - if s, ok := (e.Data[logfields.Name]).(string); ok && e.Message == spanMessage { - return s - } - - return log.GetCallerName(e) -} From e443898969914b502e2321b7924ed1dd15a13c59 Mon Sep 17 00:00:00 2001 From: Hamza El-Saawy Date: Tue, 14 Mar 2023 15:50:36 -0400 Subject: [PATCH 3/3] PR: docs, defaults, AddSpanContext/EncodeError bug Clarified documentation. Disable JSON encoding by default. Bug: `AddSpanContext` wasn't checked when adding span information. Bug: `EncodeError` was unneeded. Signed-off-by: Hamza El-Saawy --- internal/log/format.go | 14 --------- internal/log/hook.go | 64 ++++++++++++++++++++++-------------------- internal/oc/errors.go | 16 +++++------ 3 files changed, 41 insertions(+), 53 deletions(-) diff --git a/internal/log/format.go b/internal/log/format.go index 045215380f..4b65003334 100644 --- a/internal/log/format.go +++ b/internal/log/format.go @@ -10,7 +10,6 @@ import ( "time" "github.com/containerd/containerd/log" - "github.com/sirupsen/logrus" ) const TimeFormat = log.RFC3339NanoFixed @@ -84,16 +83,3 @@ func encodeBuffer(buf *bytes.Buffer, v interface{}) ([]byte, error) { // 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 -} diff --git a/internal/log/hook.go b/internal/log/hook.go index 50c1c72fb8..94c6d0918f 100644 --- a/internal/log/hook.go +++ b/internal/log/hook.go @@ -23,35 +23,34 @@ 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. + // Default is false. EncodeAsJSON bool // FormatTime specifies the format for [time.Time] variables. - // An empty string disabled formatting. + // An empty string disables formatting. + // When disabled, the fall back will the JSON encoding, if enabled. // // Default is [github.com/containerd/containerd/log.RFC3339NanoFixed]. TimeFormat string // Duration format converts a [time.Duration] fields to an appropriate encoding. + // nil disables formatting. + // When disabled, the fall back will the JSON encoding, if enabled. // - // Default is [DurationFormatSeconds]. + // Default is [DurationFormatString], which appends a duration unit after the value. DurationFormat DurationFormat // AddSpanContext adds [logfields.TraceID] and [logfields.SpanID] fields to // the entry from the span context stored in [logrus.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{ - EncodeAsJSON: true, TimeFormat: log.RFC3339NanoFixed, - DurationFormat: DurationFormatSeconds, + DurationFormat: DurationFormatString, AddSpanContext: true, } } @@ -72,51 +71,50 @@ func (h *Hook) Fire(e *logrus.Entry) (err error) { // the settings in [Hook]. // If [Hook.TimeFormat] is non-empty, it will be passed to [time.Time.Format] for // fields of type [time.Time]. -// If [Hook.EncodeAsJSON] is true, then fields that are numeric, boolean, strings, or -// errors will be encoded via a [json.NewEncoder] in encode(). // -// If [Hook.TimeFormat] is empty and [Hook.EncodeAsJSON] is false, then this is a no-op. +// If [Hook.EncodeAsJSON] is true, then fields that are not numeric, boolean, strings, or +// errors will be encoded via a [json.Marshal] (with HTML escaping disabled). +// Chanel- and function-typed fields, as well as unsafe pointers are left alone and not encoded. +// +// If [Hook.TimeFormat] and [Hook.DurationFormat] are empty and [Hook.EncodeAsJSON] is false, +// then this is a no-op. func (h *Hook) encode(e *logrus.Entry) { d := e.Data formatTime := h.TimeFormat != "" - if !(h.EncodeAsJSON || formatTime) { + formatDuration := h.DurationFormat != nil + if !(h.EncodeAsJSON || formatTime || formatDuration) { return } - // todo: replace these with constraints.Integer, constraints.Float, etc in go1.18 for k, v := range d { - if !h.EncodeError { - if _, ok := v.(error); k == logrus.ErrorKey || ok { - continue - } + // encode types with dedicated formatting options first + + if vv, ok := v.(time.Time); formatTime && ok { + d[k] = vv.Format(h.TimeFormat) + continue } - if t, ok := v.(time.Time); formatTime && ok { - d[k] = t.Format(h.TimeFormat) + if vv, ok := v.(time.Duration); formatDuration && ok { + d[k] = h.DurationFormat(vv) continue } + // general case JSON encoding + if !h.EncodeAsJSON { continue } switch vv := v.(type) { // built in types + // "json" marshals errors as "{}", so leave alone here case bool, string, error, uintptr, int8, int16, int32, int64, int, uint8, uint32, uint64, uint, float32, float64: continue - case time.Duration: - if h.DurationFormat != nil { - if i := h.DurationFormat(vv); i != nil { - d[k] = i - } - } - 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{}`, @@ -130,7 +128,7 @@ func (h *Hook) encode(e *logrus.Entry) { v = vv.Bytes() } - // dereference any pointers + // dereference pointer or interface variables rv := reflect.Indirect(reflect.ValueOf(v)) // check if `v` is a null pointer if !rv.IsValid() { @@ -141,6 +139,10 @@ func (h *Hook) encode(e *logrus.Entry) { switch rv.Kind() { case reflect.Map, reflect.Struct, reflect.Array, reflect.Slice: default: + // Bool, [U]?Int*, Float*, Complex*, Uintptr, String: encoded as normal + // Chan, Func: not supported by json + // Interface, Pointer: dereferenced above + // UnsafePointer: not supported by json, not safe to de-reference; leave alone continue } @@ -150,16 +152,16 @@ func (h *Hook) encode(e *logrus.Entry) { // 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() + // keep the original `v` as the value, + continue } - - // 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 { + if !h.AddSpanContext || ctx == nil { return } span := trace.FromContext(ctx) diff --git a/internal/oc/errors.go b/internal/oc/errors.go index e63b4785d9..71df25b8df 100644 --- a/internal/oc/errors.go +++ b/internal/oc/errors.go @@ -11,7 +11,7 @@ import ( "google.golang.org/grpc/status" ) -// todo: break import cycle with "internal/hcs" and errors errors defined there +// todo: break import cycle with "internal/hcs/errors.go" and reference errors defined there // todo: add errors defined in "internal/guest/gcserror" (Hresult does not implement error) func toStatusCode(err error) codes.Code { @@ -23,7 +23,7 @@ func toStatusCode(err error) codes.Code { } switch { - // case IsAny(err): + // case isAny(err): // return codes.Cancelled case isAny(err, os.ErrInvalid): return codes.InvalidArgument @@ -35,23 +35,23 @@ func toStatusCode(err error) codes.Code { return codes.AlreadyExists case isAny(err, os.ErrPermission): return codes.PermissionDenied - // case IsAny(err): + // case isAny(err): // return codes.ResourceExhausted case isAny(err, os.ErrClosed, net.ErrClosed, io.ErrClosedPipe, io.ErrShortBuffer): return codes.FailedPrecondition - // case IsAny(err): + // case isAny(err): // return codes.Aborted - // case IsAny(err): + // case isAny(err): // return codes.OutOfRange - // case IsAny(err): + // case isAny(err): // return codes.Unimplemented case isAny(err, io.ErrNoProgress): return codes.Internal - // case IsAny(err): + // case isAny(err): // return codes.Unavailable case isAny(err, io.ErrShortWrite, io.ErrUnexpectedEOF): return codes.DataLoss - // case IsAny(err): + // case isAny(err): // return codes.Unauthenticated default: return codes.Unknown