Increase tracing within hcsshim

cmd/containerd-shim-runhcs-v1/delete.go

@@ -18,7 +18,6 @@ import (
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 	"github.com/urfave/cli"
-	"go.opencensus.io/trace"
 )
 
 // LimitedRead reads at max `readLimitBytes` bytes from the file at path `filePath`. If the file has
@@ -56,7 +55,7 @@ The delete command will be executed in the container's bundle as its cwd.
 		// task.DeleteResponse by protocol. We can write to stderr which will be
 		// logged as a warning in containerd.
 
-		ctx, span := trace.StartSpan(gcontext.Background(), "delete")
+		ctx, span := oc.StartSpan(gcontext.Background(), "delete")
 		defer span.End()
 		defer func() { oc.SetSpanStatus(span, err) }()
 

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"
@@ -39,12 +39,12 @@ func (e *eventPublisher) close() error {
 }
 
 func (e *eventPublisher) publishEvent(ctx context.Context, topic string, event interface{}) (err error) {
-	ctx, span := trace.StartSpan(ctx, "publishEvent")
+	ctx, span := oc.StartSpan(ctx, "publishEvent")
 	defer span.End()
 	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/exec_clone.go

@@ -8,9 +8,12 @@ import (
 	"github.com/Microsoft/hcsshim/internal/cmd"
 	"github.com/Microsoft/hcsshim/internal/cow"
 	"github.com/Microsoft/hcsshim/internal/log"
+	"github.com/Microsoft/hcsshim/internal/logfields"
+	"github.com/Microsoft/hcsshim/internal/oc"
 	"github.com/Microsoft/hcsshim/internal/uvm"
 	"github.com/opencontainers/runtime-spec/specs-go"
 	"github.com/sirupsen/logrus"
+	"go.opencensus.io/trace"
 )
 
 func newClonedExec(
@@ -27,7 +30,7 @@ func newClonedExec(
 		"tid":    tid,
 		"eid":    id, // Init exec ID is always same as Task ID
 		"bundle": bundle,
-	}).Debug("newClonedExec")
+	}).Trace("newClonedExec")
 
 	he := &hcsExec{
 		events:      events,
@@ -63,6 +66,12 @@ type clonedExec struct {
 }
 
 func (ce *clonedExec) Start(ctx context.Context) (err error) {
+	ctx, span := oc.StartSpan(ctx, "clonedExec::Start")
+	defer span.End()
+	defer func() { oc.SetSpanStatus(span, err) }()
+	span.AddAttributes(trace.StringAttribute(logfields.TaskID, ce.tid),
+		trace.StringAttribute(logfields.ExecID, ce.id))
+
 	// A cloned exec should never initialize the container as it should
 	// already be running.
 	return ce.startInternal(ctx, false)

cmd/containerd-shim-runhcs-v1/exec_hcs.go

@@ -20,6 +20,8 @@ import (
 	"github.com/Microsoft/hcsshim/internal/cmd"
 	"github.com/Microsoft/hcsshim/internal/cow"
 	"github.com/Microsoft/hcsshim/internal/log"
+	"github.com/Microsoft/hcsshim/internal/logfields"
+	"github.com/Microsoft/hcsshim/internal/oc"
 	"github.com/Microsoft/hcsshim/internal/protocol/guestresource"
 	"github.com/Microsoft/hcsshim/internal/signals"
 	"github.com/Microsoft/hcsshim/internal/uvm"
@@ -45,7 +47,7 @@ func newHcsExec(
 		"eid":    id, // Init exec ID is always same as Task ID
 		"bundle": bundle,
 		"wcow":   isWCOW,
-	}).Debug("newHcsExec")
+	}).Trace("newHcsExec")
 
 	he := &hcsExec{
 		events:      events,
@@ -251,12 +253,24 @@ func (he *hcsExec) startInternal(ctx context.Context, initializeContainer bool)
 }
 
 func (he *hcsExec) Start(ctx context.Context) (err error) {
+	ctx, span := oc.StartSpan(ctx, "hcsExec::Start")
+	defer span.End()
+	defer func() { oc.SetSpanStatus(span, err) }()
+	span.AddAttributes(trace.StringAttribute(logfields.TaskID, he.tid),
+		trace.StringAttribute(logfields.ExecID, he.id))
+
 	// If he.id == he.tid then this is the init exec.
 	// We need to initialize the container itself before starting this exec.
 	return he.startInternal(ctx, he.id == he.tid)
 }
 
-func (he *hcsExec) Kill(ctx context.Context, signal uint32) error {
+func (he *hcsExec) Kill(ctx context.Context, signal uint32) (err error) {
+	ctx, span := oc.StartSpan(ctx, "hcsExec::Kill")
+	defer span.End()
+	defer func() { oc.SetSpanStatus(span, err) }()
+	span.AddAttributes(trace.StringAttribute(logfields.TaskID, he.tid),
+		trace.StringAttribute(logfields.ExecID, he.id))
+
 	he.sl.Lock()
 	defer he.sl.Unlock()
 	switch he.state {
@@ -269,7 +283,6 @@ func (he *hcsExec) Kill(ctx context.Context, signal uint32) error {
 			supported = he.host == nil || he.host.SignalProcessSupported()
 		}
 		var options interface{}
-		var err error
 		if he.isWCOW {
 			var opt *guestresource.SignalProcessOptionsWCOW
 			opt, err = signals.ValidateWCOW(int(signal), supported)
@@ -309,6 +322,14 @@ func (he *hcsExec) Kill(ctx context.Context, signal uint32) error {
 }
 
 func (he *hcsExec) ResizePty(ctx context.Context, width, height uint32) error {
+	ctx, etr := log.S(ctx, logrus.Fields{
+		logfields.TaskID: he.tid,
+		logfields.ExecID: he.id,
+		"width":          width,
+		"height":         height,
+	})
+	etr.Trace("hcsExec::ResizePty")
+
 	he.sl.Lock()
 	defer he.sl.Unlock()
 	if !he.io.Terminal() {
@@ -322,6 +343,11 @@ func (he *hcsExec) ResizePty(ctx context.Context, width, height uint32) error {
 }
 
 func (he *hcsExec) CloseIO(ctx context.Context, stdin bool) error {
+	ctx, etr := log.S(ctx, logrus.Fields{
+		logfields.TaskID: he.tid,
+		logfields.ExecID: he.id,
+	})
+	etr.Trace("hcsExec::CloseIO")
 	// If we have any upstream IO we close the upstream connection. This will
 	// unblock the `io.Copy` in the `Start()` call which will signal
 	// `he.p.CloseStdin()`. If `he.io.Stdin()` is already closed this is safe to
@@ -336,6 +362,13 @@ func (he *hcsExec) Wait() *task.StateResponse {
 }
 
 func (he *hcsExec) ForceExit(ctx context.Context, status int) {
+	ctx, etr := log.S(ctx, logrus.Fields{
+		logfields.TaskID: he.tid,
+		logfields.ExecID: he.id,
+		"status":         status,
+	})
+	etr.Trace("hcsExec::ForceExit")
+
 	he.sl.Lock()
 	defer he.sl.Unlock()
 	if he.state != shimExecStateExited {
@@ -371,10 +404,15 @@ func (he *hcsExec) ForceExit(ctx context.Context, status int) {
 // We DO NOT send the async `TaskExit` event because we never would have sent
 // the `TaskStart`/`TaskExecStarted` event.
 func (he *hcsExec) exitFromCreatedL(ctx context.Context, status int) {
-	if he.state != shimExecStateExited {
-		// Avoid logging the force if we already exited gracefully
-		log.G(ctx).WithField("status", status).Debug("hcsExec::exitFromCreatedL")
+	ctx, etr := log.S(ctx, logrus.Fields{
+		logfields.TaskID: he.tid,
+		logfields.ExecID: he.id,
+		"status":         status,
+		"state":          he.state,
+	})
+	etr.Trace("hcsExec::exitFromCreatedL")
 
+	if he.state != shimExecStateExited {
 		// Unblock the container exit goroutine
 		he.processDoneOnce.Do(func() { close(he.processDone) })
 		// Transition this exec
@@ -416,13 +454,15 @@ func (he *hcsExec) exitFromCreatedL(ctx context.Context, status int) {
 //
 // 7. Finally, save the UVM and this container as a template if specified.
 func (he *hcsExec) waitForExit() {
-	ctx, span := trace.StartSpan(context.Background(), "hcsExec::waitForExit")
+	ctx, span := oc.StartSpan(context.Background(), "hcsExec::waitForExit")
+	var err error // this will only save the last error, since we dont return early on error
 	defer span.End()
+	defer func() { oc.SetSpanStatus(span, err) }()
 	span.AddAttributes(
 		trace.StringAttribute("tid", he.tid),
 		trace.StringAttribute("eid", he.id))
 
-	err := he.p.Process.Wait()
+	err = he.p.Process.Wait()
 	if err != nil {
 		log.G(ctx).WithError(err).Error("failed process Wait")
 	}
@@ -433,9 +473,11 @@ func (he *hcsExec) waitForExit() {
 
 	code, err := he.p.Process.ExitCode()
 	if err != nil {
-		log.G(ctx).WithError(err).Error("failed to get ExitCode")
+		log.G(ctx).WithError(err).WithField(logfields.ExecID, he.id).Error("failed to get hcsExec ExitCode")
 	} else {
-		log.G(ctx).WithField("exitCode", code).Debug("exited")
+		log.G(ctx).WithFields(logrus.Fields{
+			"exitCode":       code,
+			logfields.ExecID: he.id}).Debug("hcsExec exited")
 	}
 
 	he.sl.Lock()
@@ -478,7 +520,7 @@ func (he *hcsExec) waitForExit() {
 //
 // This MUST be called via a goroutine at exec create.
 func (he *hcsExec) waitForContainerExit() {
-	ctx, span := trace.StartSpan(context.Background(), "hcsExec::waitForContainerExit")
+	ctx, span := oc.StartSpan(context.Background(), "hcsExec::waitForContainerExit")
 	defer span.End()
 	span.AddAttributes(
 		trace.StringAttribute("tid", he.tid),

cmd/containerd-shim-runhcs-v1/exec_wcow_podsandbox.go

@@ -8,6 +8,7 @@ import (
 	"time"
 
 	"github.com/Microsoft/hcsshim/internal/log"
+	"github.com/Microsoft/hcsshim/internal/logfields"
 	eventstypes "github.com/containerd/containerd/api/events"
 	containerd_v1_types "github.com/containerd/containerd/api/types/task"
 	"github.com/containerd/containerd/errdefs"
@@ -22,7 +23,7 @@ func newWcowPodSandboxExec(ctx context.Context, events publisher, tid, bundle st
 		"tid":    tid,
 		"eid":    tid, // Init exec ID is always same as Task ID
 		"bundle": bundle,
-	}).Debug("newWcowPodSandboxExec")
+	}).Trace("newWcowPodSandboxExec")
 
 	wpse := &wcowPodSandboxExec{
 		events:     events,
@@ -123,6 +124,11 @@ func (wpse *wcowPodSandboxExec) Status() *task.StateResponse {
 }
 
 func (wpse *wcowPodSandboxExec) Start(ctx context.Context) error {
+	log.G(ctx).WithFields(logrus.Fields{
+		logfields.TaskID: wpse.tid,
+		logfields.ExecID: wpse.tid,
+	}).Trace("wcowPodSandboxExec::Start")
+
 	wpse.sl.Lock()
 	defer wpse.sl.Unlock()
 	if wpse.state != shimExecStateCreated {
@@ -144,6 +150,12 @@ func (wpse *wcowPodSandboxExec) Start(ctx context.Context) error {
 }
 
 func (wpse *wcowPodSandboxExec) Kill(ctx context.Context, signal uint32) error {
+	log.G(ctx).WithFields(logrus.Fields{
+		logfields.TaskID: wpse.tid,
+		logfields.ExecID: wpse.tid,
+		"signal":         signal,
+	}).Trace("wcowPodSandboxExec::Kill")
+
 	wpse.sl.Lock()
 	defer wpse.sl.Unlock()
 	switch wpse.state {
@@ -172,6 +184,12 @@ func (wpse *wcowPodSandboxExec) Kill(ctx context.Context, signal uint32) error {
 }
 
 func (wpse *wcowPodSandboxExec) ResizePty(ctx context.Context, width, height uint32) error {
+	// useless function, but trace could help track down who is calling it
+	log.G(ctx).WithFields(logrus.Fields{
+		logfields.TaskID: wpse.tid,
+		logfields.ExecID: wpse.tid,
+	}).Trace("wcowPodSandboxExec::ResizePty")
+
 	wpse.sl.Lock()
 	defer wpse.sl.Unlock()
 	// We will never have IO for a sandbox container so we wont have a tty
@@ -189,11 +207,18 @@ func (wpse *wcowPodSandboxExec) Wait() *task.StateResponse {
 }
 
 func (wpse *wcowPodSandboxExec) ForceExit(ctx context.Context, status int) {
+	ctx, etr := log.S(ctx, logrus.Fields{ //nolint:ineffassign,staticcheck
+		logfields.TaskID: wpse.tid,
+		logfields.ExecID: wpse.tid,
+		"status":         status,
+	})
+	etr.Trace("wcowPodSandboxExec::ForceExit")
+
 	wpse.sl.Lock()
 	defer wpse.sl.Unlock()
 	if wpse.state != shimExecStateExited {
 		// Avoid logging the force if we already exited gracefully
-		log.G(ctx).WithField("status", status).Debug("wcowPodSandboxExec::ForceExit")
+		etr.WithField("status", status).Debug("forcing exit")
 
 		wpse.state = shimExecStateExited
 		wpse.exitStatus = 1

cmd/containerd-shim-runhcs-v1/main.go

@@ -13,6 +13,7 @@ import (
 	"github.com/Microsoft/go-winio/pkg/etw"
 	"github.com/Microsoft/go-winio/pkg/etwlogrus"
 	"github.com/Microsoft/go-winio/pkg/guid"
+	"github.com/Microsoft/hcsshim/internal/log"
 	"github.com/Microsoft/hcsshim/internal/oc"
 	"github.com/Microsoft/hcsshim/internal/shimdiag"
 	specs "github.com/opencontainers/runtime-spec/specs-go"
@@ -64,13 +65,15 @@ func etwCallback(sourceID guid.GUID, state etw.ProviderState, level etw.Level, m
 }
 
 func main() {
+	logrus.AddHook(log.NewHook())
+
 	// Provider ID: 0b52781f-b24d-5685-ddf6-69830ed40ec3
 	// Provider and hook aren't closed explicitly, as they will exist until process exit.
 	provider, err := etw.NewProvider("Microsoft.Virtualization.RunHCS", etwCallback)
 	if err != nil {
 		logrus.Error(err)
 	} else {
-		if hook, err := etwlogrus.NewHookFromProvider(provider); err == nil {
+		if hook, err := etwlogrus.NewHookFromProvider(provider, etwlogrus.WithGetName(oc.GetSpanName)); err == nil {
 			logrus.AddHook(hook)
 		} else {
 			logrus.Error(err)
@@ -86,7 +89,7 @@ func main() {
 	)
 
 	// Register our OpenCensus logrus exporter
-	trace.ApplyConfig(trace.Config{DefaultSampler: trace.AlwaysSample()})
+	trace.ApplyConfig(trace.Config{DefaultSampler: oc.DefaultSampler})
 	trace.RegisterExporter(&oc.LogrusExporter{})
 
 	app := cli.NewApp()