From b2113b6815dc8cffadeadc8c60ef61c34ac1783e Mon Sep 17 00:00:00 2001 From: Hamza El-Saawy Date: Thu, 21 Apr 2022 16:02:38 -0400 Subject: [PATCH 1/2] Log/span ctx; (JSON) formatting; logrus hook Added logrus hook that intercepts entries headed for ETW or stdout (for the Linux GCS case). Hook allows formatting structs, maps, arrays, etc. as JSON strings, as well formatting `time.Time` and `time.Duration` consistently. Added hook to shim and Linux GCS. Updated span export to: * include span kind * include status code * format time as string * log if span attributes were dropped Added helper `log.Format*` functions to format Time and other structs to JSON. This is done by the logging hook, but allows spans to also format their attributes consistently, since they must be converted to strings. Added `log.S()` to set the log entry stored in the context with provided fields. `log.G()` now checks the context for a stored context. Added `log.Copy()` to add log entry and trace span from source context to destination, allowing for duplicating contexts but not cancellation. Added `log.U()` to update the context an entry (in the context) points to, allowing it to reference the latest span and other information. Added `oc.StartSpan[WithRemoteParent]` to set the context for log entries to reference the newly created context. Signed-off-by: Hamza El-Saawy --- internal/log/format.go | 74 ++++++++++++ internal/log/hook.go | 106 +++++++++++++++++- internal/log/scrub.go | 24 ++-- internal/oc/errors.go | 66 +++++++++++ internal/oc/exporter.go | 80 ++++++++++--- internal/oc/span.go | 16 ++- .../Microsoft/hcsshim/internal/log/format.go | 74 ++++++++++++ .../Microsoft/hcsshim/internal/log/hook.go | 106 +++++++++++++++++- .../Microsoft/hcsshim/internal/log/scrub.go | 24 ++-- .../Microsoft/hcsshim/internal/oc/errors.go | 66 +++++++++++ .../Microsoft/hcsshim/internal/oc/exporter.go | 80 ++++++++++--- .../Microsoft/hcsshim/internal/oc/span.go | 16 ++- 12 files changed, 656 insertions(+), 76 deletions(-) create mode 100644 internal/log/format.go create mode 100644 internal/oc/errors.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/log/format.go b/internal/log/format.go new file mode 100644 index 0000000000..b6981a50e0 --- /dev/null +++ b/internal/log/format.go @@ -0,0 +1,74 @@ +package log + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "net" + "reflect" + "time" +) + +const TimeFormat = time.RFC3339Nano + +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 +} diff --git a/internal/log/hook.go b/internal/log/hook.go index 8f89405923..dcb3eb9f42 100644 --- a/internal/log/hook.go +++ b/internal/log/hook.go @@ -1,23 +1,50 @@ 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 +} 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 +52,86 @@ 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 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 + + // `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, + // regardless. + // 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..1b7487d8a4 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 @@ -97,10 +96,12 @@ func scrubLinuxHostedSystem(m genMap) error { if m, ok := index(m, "process"); ok { if _, ok := m["env"]; ok { m["env"] = []string{_scrubbedReplacement} + return nil } } } + return ErrUnknownType } @@ -150,21 +151,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..d43c5c04b1 --- /dev/null +++ b/internal/oc/errors.go @@ -0,0 +1,66 @@ +package oc + +import ( + "context" + "errors" + "io" + "net" + "os" + + "github.com/containerd/containerd/errdefs" + "go.opencensus.io/trace" +) + +// todo: break import cycle with "internal/hcs" +// todo: unify or add in "internal/guest/gcserror" +// todo: move go-winio errors (ErrTimeout, ErrFileClosed, ErrPipeListenerClosed) to OS-neutral location + +// via https://pkg.go.dev/go.opencensus.io/trace#pkg-constants + +func toStatusCode(err error) uint32 { + switch { + case checkErrors(err, context.Canceled): + return trace.StatusCodeCancelled + case checkErrors(err, os.ErrInvalid, errdefs.ErrInvalidArgument): + return trace.StatusCodeInvalidArgument + case checkErrors(err, context.DeadlineExceeded, os.ErrDeadlineExceeded): + return trace.StatusCodeDeadlineExceeded + case checkErrors(err, os.ErrNotExist, errdefs.ErrNotFound): + return trace.StatusCodeNotFound + case checkErrors(err, os.ErrExist, errdefs.ErrAlreadyExists): + return trace.StatusCodeAlreadyExists + case checkErrors(err, os.ErrPermission): + return trace.StatusCodePermissionDenied + // case checkErrors(err): + // return trace.StatusCodeResourceExhausted + case checkErrors(err, os.ErrClosed, net.ErrClosed, + errdefs.ErrFailedPrecondition, io.ErrClosedPipe): + return trace.StatusCodeFailedPrecondition + // case checkErrors(err): + // return trace.StatusCodeAborted + // case checkErrors(err): + // return trace.StatusCodeOutOfRange + case checkErrors(err, errdefs.ErrNotImplemented): + return trace.StatusCodeUnimplemented + // case checkErrors(err): + // return trace.StatusCodeInternal + case checkErrors(err, errdefs.ErrUnavailable): + return trace.StatusCodeUnavailable + // case checkErrors(err): + // return trace.StatusCodeDataLoss + // case checkErrors(err): + // return trace.StatusCodeUnauthenticated + default: + return trace.StatusCodeUnknown + } +} + +func checkErrors(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 f428bdaf72..53a14064a9 100644 --- a/internal/oc/exporter.go +++ b/internal/oc/exporter.go @@ -3,19 +3,25 @@ package oc import ( "github.com/sirupsen/logrus" "go.opencensus.io/trace" + + "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 +29,61 @@ 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") + } + + // Combine all span annotations with traceID, spanID, parentSpanID, and error + entry := logrus.WithFields(logrus.Fields(s.Attributes)) + // All span fields are string, so we can safely skip overhead in entry.WithFields + // and add them directly to entry.Data. + // Avoid growing the entry.Data map and reallocating buckets by creating new + // `logrus.Fields` and copying data over. + data := make(logrus.Fields, len(entry.Data)+10) // should only add 10 new entries, max + //copy old data + for k, v := range entry.Data { + 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] = log.FormatTime(s.StartTime) + data[logfields.EndTime] = log.FormatTime(s.EndTime) + data[logfields.Duration] = s.EndTime.Sub(s.StartTime).String() + 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 + data[logrus.ErrorKey] = s.Status.Message + + if _, ok := data[_errorCodeKey]; !ok { + data[_errorCodeKey] = s.Status.Code + } } - baseEntry.Log(level, "Span") + + entry.Data = data + entry.Time = s.StartTime + entry.Log(level, spanMessage) +} + +// GetSpanName checks if the entry appears to be span entry exported by the `LogrusExporter` +// and returns the the span name. +// +// This is intended to be used with the winio ETW exporter. +func GetSpanName(e *logrus.Entry) string { + if s, ok := (e.Data[logfields.Name]).(string); ok && e.Message == spanMessage { + return s + } + + return "" } diff --git a/internal/oc/span.go b/internal/oc/span.go index 0e2b7e9bf6..8c828f830a 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) @@ -45,4 +44,15 @@ func update(ctx context.Context, s *trace.Span) (context.Context, *trace.Span) { } var WithServerSpanKind = trace.WithSpanKind(trace.SpanKindServer) -var WithClientSpanKind = trace.WithSpanKind(trace.SpanKindClient) +var WithClientSpanKind = trace.WithSpanKind(trace.SpanKindServer) + +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/log/format.go b/test/vendor/github.com/Microsoft/hcsshim/internal/log/format.go new file mode 100644 index 0000000000..b6981a50e0 --- /dev/null +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/log/format.go @@ -0,0 +1,74 @@ +package log + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "net" + "reflect" + "time" +) + +const TimeFormat = time.RFC3339Nano + +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 +} 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..dcb3eb9f42 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,50 @@ 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 +} 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 +52,86 @@ 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 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 + + // `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, + // regardless. + // 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..1b7487d8a4 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 @@ -97,10 +96,12 @@ func scrubLinuxHostedSystem(m genMap) error { if m, ok := index(m, "process"); ok { if _, ok := m["env"]; ok { m["env"] = []string{_scrubbedReplacement} + return nil } } } + return ErrUnknownType } @@ -150,21 +151,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..d43c5c04b1 --- /dev/null +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/oc/errors.go @@ -0,0 +1,66 @@ +package oc + +import ( + "context" + "errors" + "io" + "net" + "os" + + "github.com/containerd/containerd/errdefs" + "go.opencensus.io/trace" +) + +// todo: break import cycle with "internal/hcs" +// todo: unify or add in "internal/guest/gcserror" +// todo: move go-winio errors (ErrTimeout, ErrFileClosed, ErrPipeListenerClosed) to OS-neutral location + +// via https://pkg.go.dev/go.opencensus.io/trace#pkg-constants + +func toStatusCode(err error) uint32 { + switch { + case checkErrors(err, context.Canceled): + return trace.StatusCodeCancelled + case checkErrors(err, os.ErrInvalid, errdefs.ErrInvalidArgument): + return trace.StatusCodeInvalidArgument + case checkErrors(err, context.DeadlineExceeded, os.ErrDeadlineExceeded): + return trace.StatusCodeDeadlineExceeded + case checkErrors(err, os.ErrNotExist, errdefs.ErrNotFound): + return trace.StatusCodeNotFound + case checkErrors(err, os.ErrExist, errdefs.ErrAlreadyExists): + return trace.StatusCodeAlreadyExists + case checkErrors(err, os.ErrPermission): + return trace.StatusCodePermissionDenied + // case checkErrors(err): + // return trace.StatusCodeResourceExhausted + case checkErrors(err, os.ErrClosed, net.ErrClosed, + errdefs.ErrFailedPrecondition, io.ErrClosedPipe): + return trace.StatusCodeFailedPrecondition + // case checkErrors(err): + // return trace.StatusCodeAborted + // case checkErrors(err): + // return trace.StatusCodeOutOfRange + case checkErrors(err, errdefs.ErrNotImplemented): + return trace.StatusCodeUnimplemented + // case checkErrors(err): + // return trace.StatusCodeInternal + case checkErrors(err, errdefs.ErrUnavailable): + return trace.StatusCodeUnavailable + // case checkErrors(err): + // return trace.StatusCodeDataLoss + // case checkErrors(err): + // return trace.StatusCodeUnauthenticated + default: + return trace.StatusCodeUnknown + } +} + +func checkErrors(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/oc/exporter.go b/test/vendor/github.com/Microsoft/hcsshim/internal/oc/exporter.go index f428bdaf72..53a14064a9 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,25 @@ package oc import ( "github.com/sirupsen/logrus" "go.opencensus.io/trace" + + "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 +29,61 @@ 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") + } + + // Combine all span annotations with traceID, spanID, parentSpanID, and error + entry := logrus.WithFields(logrus.Fields(s.Attributes)) + // All span fields are string, so we can safely skip overhead in entry.WithFields + // and add them directly to entry.Data. + // Avoid growing the entry.Data map and reallocating buckets by creating new + // `logrus.Fields` and copying data over. + data := make(logrus.Fields, len(entry.Data)+10) // should only add 10 new entries, max + //copy old data + for k, v := range entry.Data { + 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] = log.FormatTime(s.StartTime) + data[logfields.EndTime] = log.FormatTime(s.EndTime) + data[logfields.Duration] = s.EndTime.Sub(s.StartTime).String() + 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 + data[logrus.ErrorKey] = s.Status.Message + + if _, ok := data[_errorCodeKey]; !ok { + data[_errorCodeKey] = s.Status.Code + } } - baseEntry.Log(level, "Span") + + entry.Data = data + entry.Time = s.StartTime + entry.Log(level, spanMessage) +} + +// GetSpanName checks if the entry appears to be span entry exported by the `LogrusExporter` +// and returns the the span name. +// +// This is intended to be used with the winio ETW exporter. +func GetSpanName(e *logrus.Entry) string { + if s, ok := (e.Data[logfields.Name]).(string); ok && e.Message == spanMessage { + return s + } + + return "" } 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..8c828f830a 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) @@ -45,4 +44,15 @@ func update(ctx context.Context, s *trace.Span) (context.Context, *trace.Span) { } var WithServerSpanKind = trace.WithSpanKind(trace.SpanKindServer) -var WithClientSpanKind = trace.WithSpanKind(trace.SpanKindClient) +var WithClientSpanKind = trace.WithSpanKind(trace.SpanKindServer) + +func spanKindToString(sk int) string { + switch sk { + case trace.SpanKindClient: + return "client" + case trace.SpanKindServer: + return "server" + default: + return "" + } +} From 38d6a0eecee89f3cecec3e73cd0e1a1699c64444 Mon Sep 17 00:00:00 2001 From: Hamza El-Saawy Date: Thu, 21 Apr 2022 16:29:30 -0400 Subject: [PATCH 2/2] Code update to use new trace/log functionality Replaced `trace.StartSpan[WithRemoteParent]` to use `oc.`. Use `log.Format*` in span attributes and to format specific objects. Use `log.G()` or `log.L` instead of `logrus.*`. Signed-off-by: Hamza El-Saawy --- cmd/containerd-shim-runhcs-v1/events.go | 4 ++-- cmd/containerd-shim-runhcs-v1/service.go | 10 ++++---- cmd/containerd-shim-runhcs-v1/task_hcs.go | 3 ++- internal/cmd/io.go | 24 +++++++++++++------ internal/gcs/container.go | 10 ++++---- internal/gcs/iochannel.go | 4 ++++ internal/guest/bridge/bridge.go | 2 +- internal/hcsoci/create.go | 22 +++++++++-------- internal/hcsoci/hcsdoc_wcow.go | 12 +++++++--- internal/hcsoci/resources_lcow.go | 8 +++---- internal/hcsoci/resources_wcow.go | 11 +++++---- internal/uvm/computeagent.go | 2 +- internal/uvm/create_lcow.go | 2 +- internal/uvm/create_wcow.go | 2 +- internal/uvm/network.go | 7 +----- internal/uvm/vsmb.go | 6 ++--- .../Microsoft/hcsshim/internal/cmd/io.go | 24 +++++++++++++------ .../hcsshim/internal/gcs/container.go | 10 ++++---- .../hcsshim/internal/gcs/iochannel.go | 4 ++++ .../hcsshim/internal/hcsoci/create.go | 22 +++++++++-------- .../hcsshim/internal/hcsoci/hcsdoc_wcow.go | 12 +++++++--- .../hcsshim/internal/hcsoci/resources_lcow.go | 8 +++---- .../hcsshim/internal/hcsoci/resources_wcow.go | 11 +++++---- .../hcsshim/internal/uvm/computeagent.go | 2 +- .../hcsshim/internal/uvm/create_lcow.go | 2 +- .../hcsshim/internal/uvm/create_wcow.go | 2 +- .../Microsoft/hcsshim/internal/uvm/network.go | 7 +----- .../Microsoft/hcsshim/internal/uvm/vsmb.go | 6 ++--- 28 files changed, 138 insertions(+), 101 deletions(-) diff --git a/cmd/containerd-shim-runhcs-v1/events.go b/cmd/containerd-shim-runhcs-v1/events.go index fd791e7adf..b603afe38c 100644 --- a/cmd/containerd-shim-runhcs-v1/events.go +++ b/cmd/containerd-shim-runhcs-v1/events.go @@ -4,8 +4,8 @@ package main import ( "context" - "fmt" + "github.com/Microsoft/hcsshim/internal/log" "github.com/Microsoft/hcsshim/internal/oc" "github.com/containerd/containerd/namespaces" shim "github.com/containerd/containerd/runtime/v2/shim" @@ -44,7 +44,7 @@ func (e *eventPublisher) publishEvent(ctx context.Context, topic string, event i defer func() { oc.SetSpanStatus(span, err) }() span.AddAttributes( trace.StringAttribute("topic", topic), - trace.StringAttribute("event", fmt.Sprintf("%+v", event))) + trace.StringAttribute("event", log.Format(ctx, event))) if e == nil { return nil diff --git a/cmd/containerd-shim-runhcs-v1/service.go b/cmd/containerd-shim-runhcs-v1/service.go index 2d900ab41b..1baa6b0211 100644 --- a/cmd/containerd-shim-runhcs-v1/service.go +++ b/cmd/containerd-shim-runhcs-v1/service.go @@ -12,6 +12,7 @@ import ( "time" "github.com/Microsoft/hcsshim/internal/extendedtask" + "github.com/Microsoft/hcsshim/internal/log" "github.com/Microsoft/hcsshim/internal/oc" "github.com/Microsoft/hcsshim/internal/shimdiag" "github.com/containerd/containerd/errdefs" @@ -105,7 +106,7 @@ func (s *service) State(ctx context.Context, req *task.StateRequest) (resp *task span.AddAttributes( trace.StringAttribute("status", resp.Status.String()), trace.Int64Attribute("exitStatus", int64(resp.ExitStatus)), - trace.StringAttribute("exitedAt", resp.ExitedAt.String())) + trace.StringAttribute("exitedAt", log.FormatTime(resp.ExitedAt))) } oc.SetSpanStatus(span, err) }() @@ -135,8 +136,7 @@ func (s *service) Create(ctx context.Context, req *task.CreateTaskRequest) (resp span.AddAttributes( trace.StringAttribute("tid", req.ID), trace.StringAttribute("bundle", req.Bundle), - // trace.StringAttribute("rootfs", req.Rootfs), TODO: JTERRY75 - - // OpenCensus doesnt support slice like our logrus hook + trace.StringAttribute("rootfs", log.Format(ctx, req.Rootfs)), trace.BoolAttribute("terminal", req.Terminal), trace.StringAttribute("stdin", req.Stdin), trace.StringAttribute("stdout", req.Stdout), @@ -182,7 +182,7 @@ func (s *service) Delete(ctx context.Context, req *task.DeleteRequest) (resp *ta span.AddAttributes( trace.Int64Attribute("pid", int64(resp.Pid)), trace.Int64Attribute("exitStatus", int64(resp.ExitStatus)), - trace.StringAttribute("exitedAt", resp.ExitedAt.String())) + trace.StringAttribute("exitedAt", log.FormatTime(resp.ExitedAt))) } oc.SetSpanStatus(span, err) }() @@ -399,7 +399,7 @@ func (s *service) Wait(ctx context.Context, req *task.WaitRequest) (resp *task.W if resp != nil { span.AddAttributes( trace.Int64Attribute("exitStatus", int64(resp.ExitStatus)), - trace.StringAttribute("exitedAt", resp.ExitedAt.String())) + trace.StringAttribute("exitedAt", log.FormatTime(resp.ExitedAt))) } oc.SetSpanStatus(span, err) }() diff --git a/cmd/containerd-shim-runhcs-v1/task_hcs.go b/cmd/containerd-shim-runhcs-v1/task_hcs.go index b2aaa5b6b5..f7845a2748 100644 --- a/cmd/containerd-shim-runhcs-v1/task_hcs.go +++ b/cmd/containerd-shim-runhcs-v1/task_hcs.go @@ -695,7 +695,8 @@ func (ht *hcsTask) Wait() *task.StateResponse { func (ht *hcsTask) waitInitExit(destroyContainer bool) { ctx, span := oc.StartSpan(context.Background(), "hcsTask::waitInitExit") defer span.End() - span.AddAttributes(trace.StringAttribute("tid", ht.id)) + span.AddAttributes(trace.StringAttribute("tid", ht.id), + trace.BoolAttribute("destroyContainer", destroyContainer)) // Wait for it to exit on its own ht.init.Wait() diff --git a/internal/cmd/io.go b/internal/cmd/io.go index 75ddd1f355..1e77c0fe14 100644 --- a/internal/cmd/io.go +++ b/internal/cmd/io.go @@ -10,6 +10,9 @@ import ( "github.com/pkg/errors" "github.com/sirupsen/logrus" + + "github.com/Microsoft/hcsshim/internal/log" + "github.com/Microsoft/hcsshim/internal/logfields" ) // UpstreamIO is an interface describing the IO to connect to above the shim. @@ -64,19 +67,26 @@ func NewUpstreamIO(ctx context.Context, id, stdout, stderr, stdin string, termin } // relayIO is a glorified io.Copy that also logs when the copy has completed. -func relayIO(w io.Writer, r io.Reader, log *logrus.Entry, name string) (int64, error) { +func relayIO(w io.Writer, r io.Reader, entry *logrus.Entry, name string) (int64, error) { n, err := io.Copy(w, r) - if log != nil { + if entry != nil { + ctx := entry.Context + if ctx == nil { + ctx = context.Background() + } + lvl := logrus.DebugLevel - log = log.WithFields(logrus.Fields{ - "file": name, - "bytes": n, + entry = entry.WithFields(logrus.Fields{ + logfields.File: name, + "bytes": n, + "reader": log.FormatIO(ctx, r), + "writer": log.FormatIO(ctx, w), }) if err != nil { lvl = logrus.ErrorLevel - log = log.WithError(err) + entry = entry.WithError(err) } - log.Log(lvl, "Cmd IO relay complete") + entry.Log(lvl, "Cmd IO relay complete") } return n, err } diff --git a/internal/gcs/container.go b/internal/gcs/container.go index 84889a8608..9d3161d3b9 100644 --- a/internal/gcs/container.go +++ b/internal/gcs/container.go @@ -91,11 +91,11 @@ func (c *Container) IsOCI() bool { // Close releases associated with the container. func (c *Container) Close() error { - c.closeOnce.Do(func() { - _, span := oc.StartSpan(context.Background(), "gcs::Container::Close") - defer span.End() - span.AddAttributes(trace.StringAttribute("cid", c.id)) - }) + _, span := oc.StartSpan(context.Background(), "gcs::Container::Close") + defer span.End() + span.AddAttributes(trace.StringAttribute("cid", c.id)) + + c.closeOnce.Do(func() {}) return nil } diff --git a/internal/gcs/iochannel.go b/internal/gcs/iochannel.go index 5af6b81aaf..a2a032a12d 100644 --- a/internal/gcs/iochannel.go +++ b/internal/gcs/iochannel.go @@ -65,3 +65,7 @@ func (c *ioChannel) Write(b []byte) (int, error) { } return c.c.Write(b) } + +func (c *ioChannel) Addr() net.Addr { + return c.l.Addr() +} diff --git a/internal/guest/bridge/bridge.go b/internal/guest/bridge/bridge.go index 5b3f1e2bf4..e4743b7966 100644 --- a/internal/guest/bridge/bridge.go +++ b/internal/guest/bridge/bridge.go @@ -423,7 +423,7 @@ func (b *Bridge) PublishNotification(n *prot.ContainerNotification) { ctx, span := oc.StartSpan(context.Background(), "opengcs::bridge::PublishNotification", oc.WithClientSpanKind) - span.AddAttributes(trace.StringAttribute("notification", fmt.Sprintf("%+v", n))) + span.AddAttributes(trace.StringAttribute("notification", log.Format(ctx, n))) // DONT defer span.End() here. Publish is odd because bridgeResponse calls // `End` on the `ctx` after the response is sent. diff --git a/internal/hcsoci/create.go b/internal/hcsoci/create.go index 6df67ee876..41d0e5bd89 100644 --- a/internal/hcsoci/create.go +++ b/internal/hcsoci/create.go @@ -18,6 +18,7 @@ import ( "github.com/Microsoft/hcsshim/internal/hcs" hcsschema "github.com/Microsoft/hcsshim/internal/hcs/schema2" "github.com/Microsoft/hcsshim/internal/log" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/Microsoft/hcsshim/internal/oci" "github.com/Microsoft/hcsshim/internal/resources" "github.com/Microsoft/hcsshim/internal/schemaversion" @@ -216,9 +217,9 @@ func initializeCreateOptions(ctx context.Context, createOptions *CreateOptions) coi.templateID = oci.ParseAnnotationsTemplateID(ctx, createOptions.Spec) log.G(ctx).WithFields(logrus.Fields{ - "options": fmt.Sprintf("%+v", createOptions), - "schema": coi.actualSchemaVersion, - }).Debug("hcsshim::initializeCreateOptions") + logfields.Options: createOptions, + "schema": coi.actualSchemaVersion, + }).Debug("hcsshim::initializeCreateOptions options") return coi, nil } @@ -321,12 +322,13 @@ func CreateContainer(ctx context.Context, createOptions *CreateOptions) (_ cow.C } var hcsDocument, gcsDocument interface{} - log.G(ctx).Debug("hcsshim::CreateContainer allocating resources") + entry := log.G(ctx) + entry.Debug("hcsshim::CreateContainer allocating resources") if coi.Spec.Linux != nil { if schemaversion.IsV10(coi.actualSchemaVersion) { return nil, r, errors.New("LCOW v1 not supported") } - log.G(ctx).Debug("hcsshim::CreateContainer allocateLinuxResources") + entry.Debug("hcsshim::CreateContainer allocateLinuxResources") err = allocateLinuxResources(ctx, coi, r, isSandbox) if err != nil { log.G(ctx).WithError(err).Debug("failed to allocateLinuxResources") @@ -334,19 +336,19 @@ func CreateContainer(ctx context.Context, createOptions *CreateOptions) (_ cow.C } gcsDocument, err = createLinuxContainerDocument(ctx, coi, r.ContainerRootInUVM()) if err != nil { - log.G(ctx).WithError(err).Debug("failed createHCSContainerDocument") + log.G(ctx).WithError(err).Error("failed createHCSContainerDocument") return nil, r, err } } else { err = allocateWindowsResources(ctx, coi, r, isSandbox) if err != nil { - log.G(ctx).WithError(err).Debug("failed to allocateWindowsResources") + entry.WithError(err).Error("failed to allocateWindowsResources") return nil, r, err } - log.G(ctx).Debug("hcsshim::CreateContainer creating container document") + entry.Debug("hcsshim::CreateContainer creating container document") v1, v2, err := createWindowsContainerDocument(ctx, coi) if err != nil { - log.G(ctx).WithError(err).Debug("failed createHCSContainerDocument") + entry.WithError(err).Error("failed createHCSContainerDocument") return nil, r, err } @@ -370,7 +372,7 @@ func CreateContainer(ctx context.Context, createOptions *CreateOptions) (_ cow.C } } - log.G(ctx).Debug("hcsshim::CreateContainer creating compute system") + entry.Debug("hcsshim::CreateContainer creating compute system") if gcsDocument != nil { c, err := coi.HostingSystem.CreateContainer(ctx, coi.actualID, gcsDocument) if err != nil { diff --git a/internal/hcsoci/hcsdoc_wcow.go b/internal/hcsoci/hcsdoc_wcow.go index 1d25b44438..3cc0eba7e1 100644 --- a/internal/hcsoci/hcsdoc_wcow.go +++ b/internal/hcsoci/hcsdoc_wcow.go @@ -19,6 +19,7 @@ import ( hcsschema "github.com/Microsoft/hcsshim/internal/hcs/schema2" "github.com/Microsoft/hcsshim/internal/layers" "github.com/Microsoft/hcsshim/internal/log" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/Microsoft/hcsshim/internal/oci" "github.com/Microsoft/hcsshim/internal/processorinfo" "github.com/Microsoft/hcsshim/internal/uvm" @@ -143,7 +144,12 @@ func ConvertCPULimits(ctx context.Context, cid string, spec *specs.Spec, maxCPUC // a container, both hosted and process isolated. It creates both v1 and v2 // container objects, WCOW only. The containers storage should have been mounted already. func createWindowsContainerDocument(ctx context.Context, coi *createOptionsInternal) (*schema1.ContainerConfig, *hcsschema.Container, error) { - log.G(ctx).Debug("hcsshim: CreateHCSContainerDocument") + ctx, etr := log.S(ctx, logrus.Fields{ + logfields.Name: coi.actualID, + "owner": coi.actualOwner, + }) + etr.Trace("hcsshim: CreateHCSContainerDocument") + // TODO: Make this safe if exported so no null pointer dereferences. if coi.Spec == nil { @@ -227,12 +233,12 @@ func createWindowsContainerDocument(ctx context.Context, coi *createOptionsInter } else if newCPULimit > 10000 { newCPULimit = 10000 } - log.G(ctx).WithFields(logrus.Fields{ + etr.WithFields(logrus.Fields{ "hostCPUCount": hostCPUCount, "uvmCPUCount": uvmCPUCount, "oldCPULimit": cpuLimit, "newCPULimit": newCPULimit, - }).Info("rescaling CPU limit for UVM sandbox") + }).Debug("rescaling CPU limit for UVM sandbox") cpuLimit = newCPULimit } diff --git a/internal/hcsoci/resources_lcow.go b/internal/hcsoci/resources_lcow.go index d438738c28..e190e48e05 100644 --- a/internal/hcsoci/resources_lcow.go +++ b/internal/hcsoci/resources_lcow.go @@ -78,9 +78,9 @@ func allocateLinuxResources(ctx context.Context, coi *createOptionsInternal, r * } } - l := log.G(ctx).WithField("mount", fmt.Sprintf("%+v", mount)) + entry := log.G(ctx).WithField("mount", mount) if mount.Type == "physical-disk" { - l.Debug("hcsshim::allocateLinuxResources Hot-adding SCSI physical disk for OCI mount") + entry.Debug("hcsshim::allocateLinuxResources Hot-adding SCSI physical disk for OCI mount") uvmPathForShare = fmt.Sprintf(guestpath.LCOWGlobalMountPrefixFmt, coi.HostingSystem.UVMMountCounter()) scsiMount, err := coi.HostingSystem.AddSCSIPhysicalDisk(ctx, hostPath, uvmPathForShare, readOnly, mount.Options) if err != nil { @@ -91,7 +91,7 @@ func allocateLinuxResources(ctx context.Context, coi *createOptionsInternal, r * r.Add(scsiMount) coi.Spec.Mounts[i].Type = "none" } else if mount.Type == "virtual-disk" { - l.Debug("hcsshim::allocateLinuxResources Hot-adding SCSI virtual disk for OCI mount") + entry.Debug("hcsshim::allocateLinuxResources Hot-adding SCSI virtual disk for OCI mount") uvmPathForShare = fmt.Sprintf(guestpath.LCOWGlobalMountPrefixFmt, coi.HostingSystem.UVMMountCounter()) // if the scsi device is already attached then we take the uvm path that the function below returns @@ -149,7 +149,7 @@ func allocateLinuxResources(ctx context.Context, coi *createOptionsInternal, r * restrictAccess = true uvmPathForFile = path.Join(uvmPathForShare, fileName) } - l.Debug("hcsshim::allocateLinuxResources Hot-adding Plan9 for OCI mount") + entry.Debug("hcsshim::allocateLinuxResources Hot-adding Plan9 for OCI mount") share, err := coi.HostingSystem.AddPlan9(ctx, hostPath, uvmPathForShare, readOnly, restrictAccess, allowedNames) if err != nil { diff --git a/internal/hcsoci/resources_wcow.go b/internal/hcsoci/resources_wcow.go index fa22c8047e..76e21546b2 100644 --- a/internal/hcsoci/resources_wcow.go +++ b/internal/hcsoci/resources_wcow.go @@ -150,16 +150,17 @@ func setupMounts(ctx context.Context, coi *createOptionsInternal, r *resources.R break } } - l := log.G(ctx).WithField("mount", fmt.Sprintf("%+v", mount)) + + entry := log.G(ctx).WithField("mount", mount) if mount.Type == "physical-disk" { - l.Debug("hcsshim::allocateWindowsResources Hot-adding SCSI physical disk for OCI mount") + entry.Debug("hcsshim::allocateWindowsResources Hot-adding SCSI physical disk for OCI mount") scsiMount, err := coi.HostingSystem.AddSCSIPhysicalDisk(ctx, mount.Source, uvmPath, readOnly, mount.Options) if err != nil { return errors.Wrapf(err, "adding SCSI physical disk mount %+v", mount) } r.Add(scsiMount) } else if mount.Type == "virtual-disk" { - l.Debug("hcsshim::allocateWindowsResources Hot-adding SCSI virtual disk for OCI mount") + entry.Debug("hcsshim::allocateWindowsResources Hot-adding SCSI virtual disk for OCI mount") scsiMount, err := coi.HostingSystem.AddSCSI( ctx, mount.Source, @@ -174,7 +175,7 @@ func setupMounts(ctx context.Context, coi *createOptionsInternal, r *resources.R } r.Add(scsiMount) } else if mount.Type == "extensible-virtual-disk" { - l.Debug("hcsshim::allocateWindowsResource Hot-adding ExtensibleVirtualDisk") + entry.Debug("hcsshim::allocateWindowsResource Hot-adding ExtensibleVirtualDisk") scsiMount, err := coi.HostingSystem.AddSCSIExtensibleVirtualDisk(ctx, mount.Source, uvmPath, readOnly) if err != nil { return errors.Wrapf(err, "adding SCSI EVD mount failed %+v", mount) @@ -214,7 +215,7 @@ func setupMounts(ctx context.Context, coi *createOptionsInternal, r *resources.R } r.Add(pipe) } else { - l.Debug("hcsshim::allocateWindowsResources Hot-adding VSMB share for OCI mount") + entry.Debug("hcsshim::allocateWindowsResources Hot-adding VSMB share for OCI mount") options := coi.HostingSystem.DefaultVSMBOptions(readOnly) share, err := coi.HostingSystem.AddVSMB(ctx, mount.Source, options) if err != nil { diff --git a/internal/uvm/computeagent.go b/internal/uvm/computeagent.go index 44b328ad37..a3d35a230e 100644 --- a/internal/uvm/computeagent.go +++ b/internal/uvm/computeagent.go @@ -240,7 +240,7 @@ func setupAndServe(ctx context.Context, caAddr string, vm *UtilityVM) error { } computeagent.RegisterComputeAgentService(s, &computeAgent{vm}) - log.G(ctx).WithField("address", l.Addr().String()).Info("serving compute agent") + log.G(ctx).WithField("address", log.FormatIO(ctx, l)).Debug("serving compute agent") go func() { defer l.Close() if err := trapClosedConnErr(s.Serve(ctx, l)); err != nil { diff --git a/internal/uvm/create_lcow.go b/internal/uvm/create_lcow.go index 3792307ab5..23819af75e 100644 --- a/internal/uvm/create_lcow.go +++ b/internal/uvm/create_lcow.go @@ -720,7 +720,7 @@ func CreateLCOW(ctx context.Context, opts *OptionsLCOW) (_ *UtilityVM, err error } span.AddAttributes(trace.StringAttribute(logfields.UVMID, opts.ID)) - log.G(ctx).WithField("options", fmt.Sprintf("%+v", opts)).Debug("uvm::CreateLCOW options") + log.G(ctx).WithField(logfields.Options, opts).Debug("uvm::CreateLCOW options") // We dont serialize OutputHandler so if it is missing we need to put it back to the default. if opts.OutputHandler == nil { diff --git a/internal/uvm/create_wcow.go b/internal/uvm/create_wcow.go index 662fe69149..21e999443f 100644 --- a/internal/uvm/create_wcow.go +++ b/internal/uvm/create_wcow.go @@ -246,7 +246,7 @@ func CreateWCOW(ctx context.Context, opts *OptionsWCOW) (_ *UtilityVM, err error } span.AddAttributes(trace.StringAttribute(logfields.UVMID, opts.ID)) - log.G(ctx).WithField("options", fmt.Sprintf("%+v", opts)).Debug("uvm::CreateWCOW options") + log.G(ctx).WithField(logfields.Options, opts).Debug("uvm::CreateWCOW options") uvm := &UtilityVM{ id: opts.ID, diff --git a/internal/uvm/network.go b/internal/uvm/network.go index 03509ad882..a9cae55282 100644 --- a/internal/uvm/network.go +++ b/internal/uvm/network.go @@ -99,12 +99,7 @@ func (uvm *UtilityVM) SetupNetworkNamespace(ctx context.Context, nsid string) er // GetNamespaceEndpoints gets all endpoints in `netNS` func GetNamespaceEndpoints(ctx context.Context, netNS string) ([]*hns.HNSEndpoint, error) { - op := "uvm::GetNamespaceEndpoints" - l := log.G(ctx).WithField("netns-id", netNS) - l.Debug(op + " - Begin") - defer func() { - l.Debug(op + " - End") - }() + log.G(ctx).WithField("netns-id", netNS).Trace("uvm::GetNamespaceEndpoints") ids, err := hns.GetNamespaceEndpoints(netNS) if err != nil { diff --git a/internal/uvm/vsmb.go b/internal/uvm/vsmb.go index 348058c7ef..a7a62b9ae5 100644 --- a/internal/uvm/vsmb.go +++ b/internal/uvm/vsmb.go @@ -197,7 +197,7 @@ func (uvm *UtilityVM) AddVSMB(ctx context.Context, hostPath string, options *hcs if force, err := forceNoDirectMap(hostPath); err != nil { return nil, err } else if force { - log.G(ctx).WithField("path", hostPath).Info("Forcing NoDirectmap for VSMB mount") + log.G(ctx).WithField("hostPath", hostPath).Debug("Forcing NoDirectmap for VSMB mount") options.NoDirectmap = true } @@ -230,9 +230,9 @@ func (uvm *UtilityVM) AddVSMB(ctx context.Context, hostPath string, options *hcs log.G(ctx).WithFields(logrus.Fields{ "name": share.name, "path": hostPath, - "options": fmt.Sprintf("%+#v", options), + "options": options, "operation": requestType, - }).Info("Modifying VSMB share") + }).Debug("Modifying VSMB share") modification := &hcsschema.ModifySettingRequest{ RequestType: requestType, Settings: hcsschema.VirtualSmbShare{ diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/cmd/io.go b/test/vendor/github.com/Microsoft/hcsshim/internal/cmd/io.go index 75ddd1f355..1e77c0fe14 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/cmd/io.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/cmd/io.go @@ -10,6 +10,9 @@ import ( "github.com/pkg/errors" "github.com/sirupsen/logrus" + + "github.com/Microsoft/hcsshim/internal/log" + "github.com/Microsoft/hcsshim/internal/logfields" ) // UpstreamIO is an interface describing the IO to connect to above the shim. @@ -64,19 +67,26 @@ func NewUpstreamIO(ctx context.Context, id, stdout, stderr, stdin string, termin } // relayIO is a glorified io.Copy that also logs when the copy has completed. -func relayIO(w io.Writer, r io.Reader, log *logrus.Entry, name string) (int64, error) { +func relayIO(w io.Writer, r io.Reader, entry *logrus.Entry, name string) (int64, error) { n, err := io.Copy(w, r) - if log != nil { + if entry != nil { + ctx := entry.Context + if ctx == nil { + ctx = context.Background() + } + lvl := logrus.DebugLevel - log = log.WithFields(logrus.Fields{ - "file": name, - "bytes": n, + entry = entry.WithFields(logrus.Fields{ + logfields.File: name, + "bytes": n, + "reader": log.FormatIO(ctx, r), + "writer": log.FormatIO(ctx, w), }) if err != nil { lvl = logrus.ErrorLevel - log = log.WithError(err) + entry = entry.WithError(err) } - log.Log(lvl, "Cmd IO relay complete") + entry.Log(lvl, "Cmd IO relay complete") } return n, err } diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/container.go b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/container.go index 84889a8608..9d3161d3b9 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/container.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/container.go @@ -91,11 +91,11 @@ func (c *Container) IsOCI() bool { // Close releases associated with the container. func (c *Container) Close() error { - c.closeOnce.Do(func() { - _, span := oc.StartSpan(context.Background(), "gcs::Container::Close") - defer span.End() - span.AddAttributes(trace.StringAttribute("cid", c.id)) - }) + _, span := oc.StartSpan(context.Background(), "gcs::Container::Close") + defer span.End() + span.AddAttributes(trace.StringAttribute("cid", c.id)) + + c.closeOnce.Do(func() {}) return nil } diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/iochannel.go b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/iochannel.go index 5af6b81aaf..a2a032a12d 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/iochannel.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/iochannel.go @@ -65,3 +65,7 @@ func (c *ioChannel) Write(b []byte) (int, error) { } return c.c.Write(b) } + +func (c *ioChannel) Addr() net.Addr { + return c.l.Addr() +} diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/create.go b/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/create.go index 6df67ee876..41d0e5bd89 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/create.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/create.go @@ -18,6 +18,7 @@ import ( "github.com/Microsoft/hcsshim/internal/hcs" hcsschema "github.com/Microsoft/hcsshim/internal/hcs/schema2" "github.com/Microsoft/hcsshim/internal/log" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/Microsoft/hcsshim/internal/oci" "github.com/Microsoft/hcsshim/internal/resources" "github.com/Microsoft/hcsshim/internal/schemaversion" @@ -216,9 +217,9 @@ func initializeCreateOptions(ctx context.Context, createOptions *CreateOptions) coi.templateID = oci.ParseAnnotationsTemplateID(ctx, createOptions.Spec) log.G(ctx).WithFields(logrus.Fields{ - "options": fmt.Sprintf("%+v", createOptions), - "schema": coi.actualSchemaVersion, - }).Debug("hcsshim::initializeCreateOptions") + logfields.Options: createOptions, + "schema": coi.actualSchemaVersion, + }).Debug("hcsshim::initializeCreateOptions options") return coi, nil } @@ -321,12 +322,13 @@ func CreateContainer(ctx context.Context, createOptions *CreateOptions) (_ cow.C } var hcsDocument, gcsDocument interface{} - log.G(ctx).Debug("hcsshim::CreateContainer allocating resources") + entry := log.G(ctx) + entry.Debug("hcsshim::CreateContainer allocating resources") if coi.Spec.Linux != nil { if schemaversion.IsV10(coi.actualSchemaVersion) { return nil, r, errors.New("LCOW v1 not supported") } - log.G(ctx).Debug("hcsshim::CreateContainer allocateLinuxResources") + entry.Debug("hcsshim::CreateContainer allocateLinuxResources") err = allocateLinuxResources(ctx, coi, r, isSandbox) if err != nil { log.G(ctx).WithError(err).Debug("failed to allocateLinuxResources") @@ -334,19 +336,19 @@ func CreateContainer(ctx context.Context, createOptions *CreateOptions) (_ cow.C } gcsDocument, err = createLinuxContainerDocument(ctx, coi, r.ContainerRootInUVM()) if err != nil { - log.G(ctx).WithError(err).Debug("failed createHCSContainerDocument") + log.G(ctx).WithError(err).Error("failed createHCSContainerDocument") return nil, r, err } } else { err = allocateWindowsResources(ctx, coi, r, isSandbox) if err != nil { - log.G(ctx).WithError(err).Debug("failed to allocateWindowsResources") + entry.WithError(err).Error("failed to allocateWindowsResources") return nil, r, err } - log.G(ctx).Debug("hcsshim::CreateContainer creating container document") + entry.Debug("hcsshim::CreateContainer creating container document") v1, v2, err := createWindowsContainerDocument(ctx, coi) if err != nil { - log.G(ctx).WithError(err).Debug("failed createHCSContainerDocument") + entry.WithError(err).Error("failed createHCSContainerDocument") return nil, r, err } @@ -370,7 +372,7 @@ func CreateContainer(ctx context.Context, createOptions *CreateOptions) (_ cow.C } } - log.G(ctx).Debug("hcsshim::CreateContainer creating compute system") + entry.Debug("hcsshim::CreateContainer creating compute system") if gcsDocument != nil { c, err := coi.HostingSystem.CreateContainer(ctx, coi.actualID, gcsDocument) if err != nil { diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/hcsdoc_wcow.go b/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/hcsdoc_wcow.go index 1d25b44438..3cc0eba7e1 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/hcsdoc_wcow.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/hcsdoc_wcow.go @@ -19,6 +19,7 @@ import ( hcsschema "github.com/Microsoft/hcsshim/internal/hcs/schema2" "github.com/Microsoft/hcsshim/internal/layers" "github.com/Microsoft/hcsshim/internal/log" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/Microsoft/hcsshim/internal/oci" "github.com/Microsoft/hcsshim/internal/processorinfo" "github.com/Microsoft/hcsshim/internal/uvm" @@ -143,7 +144,12 @@ func ConvertCPULimits(ctx context.Context, cid string, spec *specs.Spec, maxCPUC // a container, both hosted and process isolated. It creates both v1 and v2 // container objects, WCOW only. The containers storage should have been mounted already. func createWindowsContainerDocument(ctx context.Context, coi *createOptionsInternal) (*schema1.ContainerConfig, *hcsschema.Container, error) { - log.G(ctx).Debug("hcsshim: CreateHCSContainerDocument") + ctx, etr := log.S(ctx, logrus.Fields{ + logfields.Name: coi.actualID, + "owner": coi.actualOwner, + }) + etr.Trace("hcsshim: CreateHCSContainerDocument") + // TODO: Make this safe if exported so no null pointer dereferences. if coi.Spec == nil { @@ -227,12 +233,12 @@ func createWindowsContainerDocument(ctx context.Context, coi *createOptionsInter } else if newCPULimit > 10000 { newCPULimit = 10000 } - log.G(ctx).WithFields(logrus.Fields{ + etr.WithFields(logrus.Fields{ "hostCPUCount": hostCPUCount, "uvmCPUCount": uvmCPUCount, "oldCPULimit": cpuLimit, "newCPULimit": newCPULimit, - }).Info("rescaling CPU limit for UVM sandbox") + }).Debug("rescaling CPU limit for UVM sandbox") cpuLimit = newCPULimit } diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/resources_lcow.go b/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/resources_lcow.go index d438738c28..e190e48e05 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/resources_lcow.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/resources_lcow.go @@ -78,9 +78,9 @@ func allocateLinuxResources(ctx context.Context, coi *createOptionsInternal, r * } } - l := log.G(ctx).WithField("mount", fmt.Sprintf("%+v", mount)) + entry := log.G(ctx).WithField("mount", mount) if mount.Type == "physical-disk" { - l.Debug("hcsshim::allocateLinuxResources Hot-adding SCSI physical disk for OCI mount") + entry.Debug("hcsshim::allocateLinuxResources Hot-adding SCSI physical disk for OCI mount") uvmPathForShare = fmt.Sprintf(guestpath.LCOWGlobalMountPrefixFmt, coi.HostingSystem.UVMMountCounter()) scsiMount, err := coi.HostingSystem.AddSCSIPhysicalDisk(ctx, hostPath, uvmPathForShare, readOnly, mount.Options) if err != nil { @@ -91,7 +91,7 @@ func allocateLinuxResources(ctx context.Context, coi *createOptionsInternal, r * r.Add(scsiMount) coi.Spec.Mounts[i].Type = "none" } else if mount.Type == "virtual-disk" { - l.Debug("hcsshim::allocateLinuxResources Hot-adding SCSI virtual disk for OCI mount") + entry.Debug("hcsshim::allocateLinuxResources Hot-adding SCSI virtual disk for OCI mount") uvmPathForShare = fmt.Sprintf(guestpath.LCOWGlobalMountPrefixFmt, coi.HostingSystem.UVMMountCounter()) // if the scsi device is already attached then we take the uvm path that the function below returns @@ -149,7 +149,7 @@ func allocateLinuxResources(ctx context.Context, coi *createOptionsInternal, r * restrictAccess = true uvmPathForFile = path.Join(uvmPathForShare, fileName) } - l.Debug("hcsshim::allocateLinuxResources Hot-adding Plan9 for OCI mount") + entry.Debug("hcsshim::allocateLinuxResources Hot-adding Plan9 for OCI mount") share, err := coi.HostingSystem.AddPlan9(ctx, hostPath, uvmPathForShare, readOnly, restrictAccess, allowedNames) if err != nil { diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/resources_wcow.go b/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/resources_wcow.go index fa22c8047e..76e21546b2 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/resources_wcow.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/hcsoci/resources_wcow.go @@ -150,16 +150,17 @@ func setupMounts(ctx context.Context, coi *createOptionsInternal, r *resources.R break } } - l := log.G(ctx).WithField("mount", fmt.Sprintf("%+v", mount)) + + entry := log.G(ctx).WithField("mount", mount) if mount.Type == "physical-disk" { - l.Debug("hcsshim::allocateWindowsResources Hot-adding SCSI physical disk for OCI mount") + entry.Debug("hcsshim::allocateWindowsResources Hot-adding SCSI physical disk for OCI mount") scsiMount, err := coi.HostingSystem.AddSCSIPhysicalDisk(ctx, mount.Source, uvmPath, readOnly, mount.Options) if err != nil { return errors.Wrapf(err, "adding SCSI physical disk mount %+v", mount) } r.Add(scsiMount) } else if mount.Type == "virtual-disk" { - l.Debug("hcsshim::allocateWindowsResources Hot-adding SCSI virtual disk for OCI mount") + entry.Debug("hcsshim::allocateWindowsResources Hot-adding SCSI virtual disk for OCI mount") scsiMount, err := coi.HostingSystem.AddSCSI( ctx, mount.Source, @@ -174,7 +175,7 @@ func setupMounts(ctx context.Context, coi *createOptionsInternal, r *resources.R } r.Add(scsiMount) } else if mount.Type == "extensible-virtual-disk" { - l.Debug("hcsshim::allocateWindowsResource Hot-adding ExtensibleVirtualDisk") + entry.Debug("hcsshim::allocateWindowsResource Hot-adding ExtensibleVirtualDisk") scsiMount, err := coi.HostingSystem.AddSCSIExtensibleVirtualDisk(ctx, mount.Source, uvmPath, readOnly) if err != nil { return errors.Wrapf(err, "adding SCSI EVD mount failed %+v", mount) @@ -214,7 +215,7 @@ func setupMounts(ctx context.Context, coi *createOptionsInternal, r *resources.R } r.Add(pipe) } else { - l.Debug("hcsshim::allocateWindowsResources Hot-adding VSMB share for OCI mount") + entry.Debug("hcsshim::allocateWindowsResources Hot-adding VSMB share for OCI mount") options := coi.HostingSystem.DefaultVSMBOptions(readOnly) share, err := coi.HostingSystem.AddVSMB(ctx, mount.Source, options) if err != nil { diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/computeagent.go b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/computeagent.go index 44b328ad37..a3d35a230e 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/computeagent.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/computeagent.go @@ -240,7 +240,7 @@ func setupAndServe(ctx context.Context, caAddr string, vm *UtilityVM) error { } computeagent.RegisterComputeAgentService(s, &computeAgent{vm}) - log.G(ctx).WithField("address", l.Addr().String()).Info("serving compute agent") + log.G(ctx).WithField("address", log.FormatIO(ctx, l)).Debug("serving compute agent") go func() { defer l.Close() if err := trapClosedConnErr(s.Serve(ctx, l)); err != nil { diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/create_lcow.go b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/create_lcow.go index 3792307ab5..23819af75e 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/create_lcow.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/create_lcow.go @@ -720,7 +720,7 @@ func CreateLCOW(ctx context.Context, opts *OptionsLCOW) (_ *UtilityVM, err error } span.AddAttributes(trace.StringAttribute(logfields.UVMID, opts.ID)) - log.G(ctx).WithField("options", fmt.Sprintf("%+v", opts)).Debug("uvm::CreateLCOW options") + log.G(ctx).WithField(logfields.Options, opts).Debug("uvm::CreateLCOW options") // We dont serialize OutputHandler so if it is missing we need to put it back to the default. if opts.OutputHandler == nil { diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/create_wcow.go b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/create_wcow.go index 662fe69149..21e999443f 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/create_wcow.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/create_wcow.go @@ -246,7 +246,7 @@ func CreateWCOW(ctx context.Context, opts *OptionsWCOW) (_ *UtilityVM, err error } span.AddAttributes(trace.StringAttribute(logfields.UVMID, opts.ID)) - log.G(ctx).WithField("options", fmt.Sprintf("%+v", opts)).Debug("uvm::CreateWCOW options") + log.G(ctx).WithField(logfields.Options, opts).Debug("uvm::CreateWCOW options") uvm := &UtilityVM{ id: opts.ID, diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/network.go b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/network.go index 03509ad882..a9cae55282 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/network.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/network.go @@ -99,12 +99,7 @@ func (uvm *UtilityVM) SetupNetworkNamespace(ctx context.Context, nsid string) er // GetNamespaceEndpoints gets all endpoints in `netNS` func GetNamespaceEndpoints(ctx context.Context, netNS string) ([]*hns.HNSEndpoint, error) { - op := "uvm::GetNamespaceEndpoints" - l := log.G(ctx).WithField("netns-id", netNS) - l.Debug(op + " - Begin") - defer func() { - l.Debug(op + " - End") - }() + log.G(ctx).WithField("netns-id", netNS).Trace("uvm::GetNamespaceEndpoints") ids, err := hns.GetNamespaceEndpoints(netNS) if err != nil { diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/vsmb.go b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/vsmb.go index 348058c7ef..a7a62b9ae5 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/vsmb.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/uvm/vsmb.go @@ -197,7 +197,7 @@ func (uvm *UtilityVM) AddVSMB(ctx context.Context, hostPath string, options *hcs if force, err := forceNoDirectMap(hostPath); err != nil { return nil, err } else if force { - log.G(ctx).WithField("path", hostPath).Info("Forcing NoDirectmap for VSMB mount") + log.G(ctx).WithField("hostPath", hostPath).Debug("Forcing NoDirectmap for VSMB mount") options.NoDirectmap = true } @@ -230,9 +230,9 @@ func (uvm *UtilityVM) AddVSMB(ctx context.Context, hostPath string, options *hcs log.G(ctx).WithFields(logrus.Fields{ "name": share.name, "path": hostPath, - "options": fmt.Sprintf("%+#v", options), + "options": options, "operation": requestType, - }).Info("Modifying VSMB share") + }).Debug("Modifying VSMB share") modification := &hcsschema.ModifySettingRequest{ RequestType: requestType, Settings: hcsschema.VirtualSmbShare{