From 4daf5a506eb5a3e57483ec3d378221e2264b4d44 Mon Sep 17 00:00:00 2001 From: Hamza El-Saawy Date: Thu, 21 Apr 2022 16:02:38 -0400 Subject: [PATCH] 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 ++- .../hcsshim/internal/hcserror/helper.go | 13 ++ .../Microsoft/hcsshim/internal/log/format.go | 90 ++++++++++++++ .../Microsoft/hcsshim/internal/log/hook.go | 116 +++++++++++++++++- .../Microsoft/hcsshim/internal/log/scrub.go | 22 +--- .../Microsoft/hcsshim/internal/oc/errors.go | 60 +++++++++ .../Microsoft/hcsshim/internal/oc/exporter.go | 100 ++++++++++++--- .../Microsoft/hcsshim/internal/oc/span.go | 14 ++- 14 files changed, 756 insertions(+), 74 deletions(-) create mode 100644 internal/hcserror/helper.go create mode 100644 internal/log/format.go create mode 100644 internal/oc/errors.go create mode 100644 test/vendor/github.com/Microsoft/hcsshim/internal/hcserror/helper.go create mode 100644 test/vendor/github.com/Microsoft/hcsshim/internal/log/format.go create mode 100644 test/vendor/github.com/Microsoft/hcsshim/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 "" + } +} diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/hcserror/helper.go b/test/vendor/github.com/Microsoft/hcsshim/internal/hcserror/helper.go new file mode 100644 index 0000000000..2c52ea25e1 --- /dev/null +++ b/test/vendor/github.com/Microsoft/hcsshim/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/test/vendor/github.com/Microsoft/hcsshim/internal/log/format.go b/test/vendor/github.com/Microsoft/hcsshim/internal/log/format.go new file mode 100644 index 0000000000..6588139afe --- /dev/null +++ b/test/vendor/github.com/Microsoft/hcsshim/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/test/vendor/github.com/Microsoft/hcsshim/internal/log/hook.go b/test/vendor/github.com/Microsoft/hcsshim/internal/log/hook.go index 8f89405923..cbaab8aa89 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/log/hook.go +++ b/test/vendor/github.com/Microsoft/hcsshim/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/test/vendor/github.com/Microsoft/hcsshim/internal/log/scrub.go b/test/vendor/github.com/Microsoft/hcsshim/internal/log/scrub.go index d51e0fd89f..d1ef15096e 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/log/scrub.go +++ b/test/vendor/github.com/Microsoft/hcsshim/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/test/vendor/github.com/Microsoft/hcsshim/internal/oc/errors.go b/test/vendor/github.com/Microsoft/hcsshim/internal/oc/errors.go new file mode 100644 index 0000000000..85767f52be --- /dev/null +++ b/test/vendor/github.com/Microsoft/hcsshim/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/test/vendor/github.com/Microsoft/hcsshim/internal/oc/exporter.go b/test/vendor/github.com/Microsoft/hcsshim/internal/oc/exporter.go index f428bdaf72..279d1e406b 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/oc/exporter.go +++ b/test/vendor/github.com/Microsoft/hcsshim/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/test/vendor/github.com/Microsoft/hcsshim/internal/oc/span.go b/test/vendor/github.com/Microsoft/hcsshim/internal/oc/span.go index 0e2b7e9bf6..7260784326 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/oc/span.go +++ b/test/vendor/github.com/Microsoft/hcsshim/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 "" + } +}