Replacing trace.StartSpan with oc.StartSpan

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

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)
 	}()

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()

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
 }

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
 }
 

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()
+}

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.
 

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,32 +322,33 @@ 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")
 			return nil, r, err
 		}
 		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 {

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
 	}
 

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 {

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 {