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/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/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/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 "" + } +} 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{