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 <hamzaelsaawy@microsoft.com>
microsoft · Apr 21, 2022 · e5c4b57 · e5c4b57
1 parent 566a18b
commit e5c4b57
Show file tree

Hide file tree

Showing 138 changed files with 1,100 additions and 515 deletions.
diff --git a/cmd/containerd-shim-runhcs-v1/delete.go b/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) }()
 

diff --git 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"
@@ -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

diff --git a/cmd/containerd-shim-runhcs-v1/exec_hcs.go b/cmd/containerd-shim-runhcs-v1/exec_hcs.go
@@ -20,6 +20,7 @@ import (
  "github.com/Microsoft/hcsshim/internal/cmd"
  "github.com/Microsoft/hcsshim/internal/cow"
  "github.com/Microsoft/hcsshim/internal/log"
+ "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"
@@ -416,13 +417,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")
+ var err error // this will only save the last error, since we dont return early on error
+ ctx, span := oc.StartSpan(context.Background(), "hcsExec::waitForExit")
  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")
  }
@@ -478,7 +481,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),

diff --git a/cmd/containerd-shim-runhcs-v1/main.go b/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,6 +65,8 @@ 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)
@@ -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()

diff --git 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"
@@ -98,14 +99,14 @@ func NewService(o ...ServiceOption) (svc *service, err error) {
 }
 
 func (s *service) State(ctx context.Context, req *task.StateRequest) (resp *task.StateResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "State")
+ ctx, span := oc.StartSpan(ctx, "State")
  defer span.End()
  defer func() {
  if resp != nil {
  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)
  }()
@@ -123,7 +124,7 @@ func (s *service) State(ctx context.Context, req *task.StateRequest) (resp *task
 }
 
 func (s *service) Create(ctx context.Context, req *task.CreateTaskRequest) (resp *task.CreateTaskResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "Create")
+ ctx, span := oc.StartSpan(ctx, "Create")
  defer span.End()
  defer func() {
  if resp != nil {
@@ -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),
@@ -153,7 +153,7 @@ func (s *service) Create(ctx context.Context, req *task.CreateTaskRequest) (resp
 }
 
 func (s *service) Start(ctx context.Context, req *task.StartRequest) (resp *task.StartResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "Start")
+ ctx, span := oc.StartSpan(ctx, "Start")
  defer span.End()
  defer func() {
  if resp != nil {
@@ -175,14 +175,14 @@ func (s *service) Start(ctx context.Context, req *task.StartRequest) (resp *task
 }
 
 func (s *service) Delete(ctx context.Context, req *task.DeleteRequest) (resp *task.DeleteResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "Delete")
+ ctx, span := oc.StartSpan(ctx, "Delete")
  defer span.End()
  defer func() {
  if resp != nil {
  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)
  }()
@@ -200,7 +200,7 @@ func (s *service) Delete(ctx context.Context, req *task.DeleteRequest) (resp *ta
 }
 
 func (s *service) Pids(ctx context.Context, req *task.PidsRequest) (_ *task.PidsResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "Pids")
+ ctx, span := oc.StartSpan(ctx, "Pids")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -215,7 +215,7 @@ func (s *service) Pids(ctx context.Context, req *task.PidsRequest) (_ *task.Pids
 }
 
 func (s *service) Pause(ctx context.Context, req *task.PauseRequest) (_ *google_protobuf1.Empty, err error) {
- ctx, span := trace.StartSpan(ctx, "Pause")
+ ctx, span := oc.StartSpan(ctx, "Pause")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -230,7 +230,7 @@ func (s *service) Pause(ctx context.Context, req *task.PauseRequest) (_ *google_
 }
 
 func (s *service) Resume(ctx context.Context, req *task.ResumeRequest) (_ *google_protobuf1.Empty, err error) {
- ctx, span := trace.StartSpan(ctx, "Resume")
+ ctx, span := oc.StartSpan(ctx, "Resume")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -245,7 +245,7 @@ func (s *service) Resume(ctx context.Context, req *task.ResumeRequest) (_ *googl
 }
 
 func (s *service) Checkpoint(ctx context.Context, req *task.CheckpointTaskRequest) (_ *google_protobuf1.Empty, err error) {
- ctx, span := trace.StartSpan(ctx, "Checkpoint")
+ ctx, span := oc.StartSpan(ctx, "Checkpoint")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -262,7 +262,7 @@ func (s *service) Checkpoint(ctx context.Context, req *task.CheckpointTaskReques
 }
 
 func (s *service) Kill(ctx context.Context, req *task.KillRequest) (_ *google_protobuf1.Empty, err error) {
- ctx, span := trace.StartSpan(ctx, "Kill")
+ ctx, span := oc.StartSpan(ctx, "Kill")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -281,7 +281,7 @@ func (s *service) Kill(ctx context.Context, req *task.KillRequest) (_ *google_pr
 }
 
 func (s *service) Exec(ctx context.Context, req *task.ExecProcessRequest) (_ *google_protobuf1.Empty, err error) {
- ctx, span := trace.StartSpan(ctx, "Exec")
+ ctx, span := oc.StartSpan(ctx, "Exec")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -302,7 +302,7 @@ func (s *service) Exec(ctx context.Context, req *task.ExecProcessRequest) (_ *go
 }
 
 func (s *service) DiagExecInHost(ctx context.Context, req *shimdiag.ExecProcessRequest) (_ *shimdiag.ExecProcessResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "DiagExecInHost")
+ ctx, span := oc.StartSpan(ctx, "DiagExecInHost")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -323,7 +323,7 @@ func (s *service) DiagExecInHost(ctx context.Context, req *shimdiag.ExecProcessR
 }
 
 func (s *service) DiagShare(ctx context.Context, req *shimdiag.ShareRequest) (_ *shimdiag.ShareResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "DiagShare")
+ ctx, span := oc.StartSpan(ctx, "DiagShare")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -341,7 +341,7 @@ func (s *service) DiagShare(ctx context.Context, req *shimdiag.ShareRequest) (_
 }
 
 func (s *service) ResizePty(ctx context.Context, req *task.ResizePtyRequest) (_ *google_protobuf1.Empty, err error) {
- ctx, span := trace.StartSpan(ctx, "ResizePty")
+ ctx, span := oc.StartSpan(ctx, "ResizePty")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -360,7 +360,7 @@ func (s *service) ResizePty(ctx context.Context, req *task.ResizePtyRequest) (_
 }
 
 func (s *service) CloseIO(ctx context.Context, req *task.CloseIORequest) (_ *google_protobuf1.Empty, err error) {
- ctx, span := trace.StartSpan(ctx, "CloseIO")
+ ctx, span := oc.StartSpan(ctx, "CloseIO")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -378,7 +378,7 @@ func (s *service) CloseIO(ctx context.Context, req *task.CloseIORequest) (_ *goo
 }
 
 func (s *service) Update(ctx context.Context, req *task.UpdateTaskRequest) (_ *google_protobuf1.Empty, err error) {
- ctx, span := trace.StartSpan(ctx, "Update")
+ ctx, span := oc.StartSpan(ctx, "Update")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -393,13 +393,13 @@ func (s *service) Update(ctx context.Context, req *task.UpdateTaskRequest) (_ *g
 }
 
 func (s *service) Wait(ctx context.Context, req *task.WaitRequest) (resp *task.WaitResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "Wait")
+ ctx, span := oc.StartSpan(ctx, "Wait")
  defer span.End()
  defer func() {
  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)
  }()
@@ -417,7 +417,7 @@ func (s *service) Wait(ctx context.Context, req *task.WaitRequest) (resp *task.W
 }
 
 func (s *service) Stats(ctx context.Context, req *task.StatsRequest) (_ *task.StatsResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "Stats")
+ ctx, span := oc.StartSpan(ctx, "Stats")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -432,7 +432,7 @@ func (s *service) Stats(ctx context.Context, req *task.StatsRequest) (_ *task.St
 }
 
 func (s *service) Connect(ctx context.Context, req *task.ConnectRequest) (resp *task.ConnectResponse, err error) {
- ctx, span := trace.StartSpan(ctx, "Connect")
+ ctx, span := oc.StartSpan(ctx, "Connect")
  defer span.End()
  defer func() {
  if resp != nil {
@@ -455,7 +455,7 @@ func (s *service) Connect(ctx context.Context, req *task.ConnectRequest) (resp *
 }
 
 func (s *service) Shutdown(ctx context.Context, req *task.ShutdownRequest) (_ *google_protobuf1.Empty, err error) {
- ctx, span := trace.StartSpan(ctx, "Shutdown")
+ ctx, span := oc.StartSpan(ctx, "Shutdown")
  defer span.End()
  defer func() { oc.SetSpanStatus(span, err) }()
 
@@ -473,7 +473,7 @@ func (s *service) DiagStacks(ctx context.Context, req *shimdiag.StacksRequest) (
  if s == nil {
  return nil, nil
  }
- ctx, span := trace.StartSpan(ctx, "DiagStacks")
+ ctx, span := oc.StartSpan(ctx, "DiagStacks")
  defer span.End()
 
  span.AddAttributes(trace.StringAttribute("tid", s.tid))
@@ -505,7 +505,7 @@ func (s *service) DiagPid(ctx context.Context, req *shimdiag.PidRequest) (*shimd
  if s == nil {
  return nil, nil
  }
- ctx, span := trace.StartSpan(ctx, "DiagPid") //nolint:ineffassign,staticcheck
+ ctx, span := oc.StartSpan(ctx, "DiagPid") //nolint:ineffassign,staticcheck
  defer span.End()
 
  span.AddAttributes(trace.StringAttribute("tid", s.tid))
@@ -516,7 +516,7 @@ func (s *service) DiagPid(ctx context.Context, req *shimdiag.PidRequest) (*shimd
 }
 
 func (s *service) ComputeProcessorInfo(ctx context.Context, req *extendedtask.ComputeProcessorInfoRequest) (*extendedtask.ComputeProcessorInfoResponse, error) {
- ctx, span := trace.StartSpan(ctx, "ComputeProcessorInfo") //nolint:ineffassign,staticcheck
+ ctx, span := oc.StartSpan(ctx, "ComputeProcessorInfo") //nolint:ineffassign,staticcheck
  defer span.End()
 
  span.AddAttributes(trace.StringAttribute("tid", s.tid))

diff --git a/cmd/containerd-shim-runhcs-v1/task_hcs.go b/cmd/containerd-shim-runhcs-v1/task_hcs.go
@@ -32,6 +32,7 @@ import (
  "github.com/Microsoft/hcsshim/internal/jobcontainers"
  "github.com/Microsoft/hcsshim/internal/log"
  "github.com/Microsoft/hcsshim/internal/memory"
+ "github.com/Microsoft/hcsshim/internal/oc"
  "github.com/Microsoft/hcsshim/internal/oci"
  "github.com/Microsoft/hcsshim/internal/processorinfo"
  "github.com/Microsoft/hcsshim/internal/protocol/guestrequest"
@@ -692,9 +693,10 @@ func (ht *hcsTask) Wait() *task.StateResponse {
 }
 
 func (ht *hcsTask) waitInitExit(destroyContainer bool) {
- ctx, span := trace.StartSpan(context.Background(), "hcsTask::waitInitExit")
+ 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()
@@ -723,7 +725,7 @@ func (ht *hcsTask) waitInitExit(destroyContainer bool) {
 // Note: For Windows process isolated containers there is no host virtual
 // machine so this should not be called.
 func (ht *hcsTask) waitForHostExit() {
- ctx, span := trace.StartSpan(context.Background(), "hcsTask::waitForHostExit")
+ ctx, span := oc.StartSpan(context.Background(), "hcsTask::waitForHostExit")
  defer span.End()
  span.AddAttributes(trace.StringAttribute("tid", ht.id))
 

diff --git a/cmd/containerd-shim-runhcs-v1/task_wcow_podsandbox.go b/cmd/containerd-shim-runhcs-v1/task_wcow_podsandbox.go
@@ -12,6 +12,7 @@ import (
  "github.com/Microsoft/hcsshim/internal/clone"
  "github.com/Microsoft/hcsshim/internal/cmd"
  "github.com/Microsoft/hcsshim/internal/log"
+ "github.com/Microsoft/hcsshim/internal/oc"
  "github.com/Microsoft/hcsshim/internal/shimdiag"
  "github.com/Microsoft/hcsshim/internal/uvm"
  eventstypes "github.com/containerd/containerd/api/events"
@@ -212,7 +213,7 @@ func (wpst *wcowPodSandboxTask) close(ctx context.Context) {
 }
 
 func (wpst *wcowPodSandboxTask) waitInitExit() {
- ctx, span := trace.StartSpan(context.Background(), "wcowPodSandboxTask::waitInitExit")
+ ctx, span := oc.StartSpan(context.Background(), "wcowPodSandboxTask::waitInitExit")
  defer span.End()
  span.AddAttributes(trace.StringAttribute("tid", wpst.id))
 
@@ -224,7 +225,7 @@ func (wpst *wcowPodSandboxTask) waitInitExit() {
 }
 
 func (wpst *wcowPodSandboxTask) waitParentExit() {
- ctx, span := trace.StartSpan(context.Background(), "wcowPodSandboxTask::waitParentExit")
+ ctx, span := oc.StartSpan(context.Background(), "wcowPodSandboxTask::waitParentExit")
  defer span.End()
  span.AddAttributes(trace.StringAttribute("tid", wpst.id))