From aadc6de7abbff3bde0c89cab75fa6d5fb2d4e0ee Mon Sep 17 00:00:00 2001 From: Hamza El-Saawy Date: Mon, 9 May 2022 13:54:39 -0400 Subject: [PATCH] Remove redundant spans Replaced redundant `cmd/containerd-shim-runhcs-v1/service.go.(Service)` `internal/gcs`, and `interna\guest\bridge` spans with `.Trace` log entries, since they include all the same (or less) information as those automatically generated by the ttrp interceptor and `(*bridge).RPC` Signed-off-by: Hamza El-Saawy --- cmd/containerd-shim-runhcs-v1/service.go | 312 ++---------------- internal/gcs/bridge.go | 3 + internal/gcs/container.go | 66 ++-- internal/gcs/guestconnection.go | 19 +- internal/gcs/process.go | 81 ++--- internal/gcs/protocol.go | 5 +- internal/guest/bridge/bridge_v2.go | 116 +++---- .../Microsoft/hcsshim/internal/gcs/bridge.go | 3 + .../hcsshim/internal/gcs/container.go | 66 ++-- .../hcsshim/internal/gcs/guestconnection.go | 19 +- .../Microsoft/hcsshim/internal/gcs/process.go | 81 ++--- .../hcsshim/internal/gcs/protocol.go | 5 +- 12 files changed, 209 insertions(+), 567 deletions(-) diff --git a/cmd/containerd-shim-runhcs-v1/service.go b/cmd/containerd-shim-runhcs-v1/service.go index 2d900ab41b..9644832449 100644 --- a/cmd/containerd-shim-runhcs-v1/service.go +++ b/cmd/containerd-shim-runhcs-v1/service.go @@ -6,18 +6,17 @@ import ( "context" "os" "runtime" - "strings" "sync" "sync/atomic" "time" "github.com/Microsoft/hcsshim/internal/extendedtask" - "github.com/Microsoft/hcsshim/internal/oc" + "github.com/Microsoft/hcsshim/internal/log" "github.com/Microsoft/hcsshim/internal/shimdiag" "github.com/containerd/containerd/errdefs" "github.com/containerd/containerd/runtime/v2/task" google_protobuf1 "github.com/gogo/protobuf/types" - "go.opencensus.io/trace" + "github.com/sirupsen/logrus" ) type ServiceOptions struct { @@ -98,389 +97,143 @@ 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 := 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())) - } - oc.SetSpanStatus(span, err) - }() - - span.AddAttributes( - trace.StringAttribute("tid", req.ID), - trace.StringAttribute("eid", req.ExecID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("State") r, e := s.stateInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Create(ctx context.Context, req *task.CreateTaskRequest) (resp *task.CreateTaskResponse, err error) { - ctx, span := oc.StartSpan(ctx, "Create") - defer span.End() - defer func() { - if resp != nil { - span.AddAttributes(trace.Int64Attribute("pid", int64(resp.Pid))) - } - oc.SetSpanStatus(span, err) - }() - - 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.BoolAttribute("terminal", req.Terminal), - trace.StringAttribute("stdin", req.Stdin), - trace.StringAttribute("stdout", req.Stdout), - trace.StringAttribute("stderr", req.Stderr), - trace.StringAttribute("checkpoint", req.Checkpoint), - trace.StringAttribute("parentcheckpoint", req.ParentCheckpoint)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Create") r, e := s.createInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Start(ctx context.Context, req *task.StartRequest) (resp *task.StartResponse, err error) { - ctx, span := oc.StartSpan(ctx, "Start") - defer span.End() - defer func() { - if resp != nil { - span.AddAttributes(trace.Int64Attribute("pid", int64(resp.Pid))) - } - oc.SetSpanStatus(span, err) - }() - - span.AddAttributes( - trace.StringAttribute("tid", req.ID), - trace.StringAttribute("eid", req.ExecID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Start") r, e := s.startInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Delete(ctx context.Context, req *task.DeleteRequest) (resp *task.DeleteResponse, err error) { - 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())) - } - oc.SetSpanStatus(span, err) - }() - - span.AddAttributes( - trace.StringAttribute("tid", req.ID), - trace.StringAttribute("eid", req.ExecID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Delete") r, e := s.deleteInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Pids(ctx context.Context, req *task.PidsRequest) (_ *task.PidsResponse, err error) { - ctx, span := oc.StartSpan(ctx, "Pids") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes(trace.StringAttribute("tid", req.ID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Pids") r, e := s.pidsInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Pause(ctx context.Context, req *task.PauseRequest) (_ *google_protobuf1.Empty, err error) { - ctx, span := oc.StartSpan(ctx, "Pause") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes(trace.StringAttribute("tid", req.ID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Pause") r, e := s.pauseInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Resume(ctx context.Context, req *task.ResumeRequest) (_ *google_protobuf1.Empty, err error) { - ctx, span := oc.StartSpan(ctx, "Resume") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes(trace.StringAttribute("tid", req.ID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Resume") r, e := s.resumeInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Checkpoint(ctx context.Context, req *task.CheckpointTaskRequest) (_ *google_protobuf1.Empty, err error) { - ctx, span := oc.StartSpan(ctx, "Checkpoint") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes( - trace.StringAttribute("tid", req.ID), - trace.StringAttribute("path", req.Path)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Checkpoint") r, e := s.checkpointInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Kill(ctx context.Context, req *task.KillRequest) (_ *google_protobuf1.Empty, err error) { - ctx, span := oc.StartSpan(ctx, "Kill") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes( - trace.StringAttribute("tid", req.ID), - trace.StringAttribute("eid", req.ExecID), - trace.Int64Attribute("signal", int64(req.Signal)), - trace.BoolAttribute("all", req.All)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Kill") r, e := s.killInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Exec(ctx context.Context, req *task.ExecProcessRequest) (_ *google_protobuf1.Empty, err error) { - ctx, span := oc.StartSpan(ctx, "Exec") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes( - trace.StringAttribute("tid", req.ID), - trace.StringAttribute("eid", req.ExecID), - trace.BoolAttribute("terminal", req.Terminal), - trace.StringAttribute("stdin", req.Stdin), - trace.StringAttribute("stdout", req.Stdout), - trace.StringAttribute("stderr", req.Stderr)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Exec") r, e := s.execInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) DiagExecInHost(ctx context.Context, req *shimdiag.ExecProcessRequest) (_ *shimdiag.ExecProcessResponse, err error) { - ctx, span := oc.StartSpan(ctx, "DiagExecInHost") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes( - trace.StringAttribute("args", strings.Join(req.Args, " ")), - trace.StringAttribute("workdir", req.Workdir), - trace.BoolAttribute("terminal", req.Terminal), - trace.StringAttribute("stdin", req.Stdin), - trace.StringAttribute("stdout", req.Stdout), - trace.StringAttribute("stderr", req.Stderr)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("DiagExecInHost") r, e := s.diagExecInHostInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) DiagShare(ctx context.Context, req *shimdiag.ShareRequest) (_ *shimdiag.ShareResponse, err error) { - ctx, span := oc.StartSpan(ctx, "DiagShare") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes( - trace.StringAttribute("hostpath", req.HostPath), - trace.StringAttribute("uvmpath", req.UvmPath), - trace.BoolAttribute("readonly", req.ReadOnly)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("DiagShare") r, e := s.diagShareInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) ResizePty(ctx context.Context, req *task.ResizePtyRequest) (_ *google_protobuf1.Empty, err error) { - ctx, span := oc.StartSpan(ctx, "ResizePty") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes( - trace.StringAttribute("tid", req.ID), - trace.StringAttribute("eid", req.ExecID), - trace.Int64Attribute("width", int64(req.Width)), - trace.Int64Attribute("height", int64(req.Height))) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("ResizePty") r, e := s.resizePtyInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) CloseIO(ctx context.Context, req *task.CloseIORequest) (_ *google_protobuf1.Empty, err error) { - ctx, span := oc.StartSpan(ctx, "CloseIO") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes( - trace.StringAttribute("tid", req.ID), - trace.StringAttribute("eid", req.ExecID), - trace.BoolAttribute("stdin", req.Stdin)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("CloseIO") r, e := s.closeIOInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Update(ctx context.Context, req *task.UpdateTaskRequest) (_ *google_protobuf1.Empty, err error) { - ctx, span := oc.StartSpan(ctx, "Update") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes(trace.StringAttribute("tid", req.ID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Update") r, e := s.updateInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Wait(ctx context.Context, req *task.WaitRequest) (resp *task.WaitResponse, err error) { - 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())) - } - oc.SetSpanStatus(span, err) - }() - - span.AddAttributes( - trace.StringAttribute("tid", req.ID), - trace.StringAttribute("eid", req.ExecID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Wait") r, e := s.waitInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Stats(ctx context.Context, req *task.StatsRequest) (_ *task.StatsResponse, err error) { - ctx, span := oc.StartSpan(ctx, "Stats") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes(trace.StringAttribute("tid", req.ID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Stats") r, e := s.statsInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Connect(ctx context.Context, req *task.ConnectRequest) (resp *task.ConnectResponse, err error) { - ctx, span := oc.StartSpan(ctx, "Connect") - defer span.End() - defer func() { - if resp != nil { - span.AddAttributes( - trace.Int64Attribute("shimPid", int64(resp.ShimPid)), - trace.Int64Attribute("taskPid", int64(resp.TaskPid)), - trace.StringAttribute("version", resp.Version)) - } - oc.SetSpanStatus(span, err) - }() - - span.AddAttributes(trace.StringAttribute("tid", req.ID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Connect") r, e := s.connectInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) Shutdown(ctx context.Context, req *task.ShutdownRequest) (_ *google_protobuf1.Empty, err error) { - ctx, span := oc.StartSpan(ctx, "Shutdown") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes(trace.StringAttribute("tid", req.ID)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } + s.logEntry(ctx).Trace("Shutdown") r, e := s.shutdownInternal(ctx, req) return r, errdefs.ToGRPC(e) } func (s *service) DiagStacks(ctx context.Context, req *shimdiag.StacksRequest) (*shimdiag.StacksResponse, error) { + s.logEntry(ctx).Trace("DiagStacks") if s == nil { return nil, nil } - ctx, span := oc.StartSpan(ctx, "DiagStacks") - defer span.End() - - span.AddAttributes(trace.StringAttribute("tid", s.tid)) - - if s.isSandbox { - span.AddAttributes(trace.StringAttribute("pod-id", s.tid)) - } buf := make([]byte, 4096) for { @@ -505,10 +258,7 @@ func (s *service) DiagPid(ctx context.Context, req *shimdiag.PidRequest) (*shimd if s == nil { return nil, nil } - ctx, span := oc.StartSpan(ctx, "DiagPid") //nolint:ineffassign,staticcheck - defer span.End() - - span.AddAttributes(trace.StringAttribute("tid", s.tid)) + s.logEntry(ctx).Trace("DiagPid") //nolint:ineffassign,staticcheck return &shimdiag.PidResponse{ Pid: int32(os.Getpid()), @@ -516,10 +266,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 := oc.StartSpan(ctx, "ComputeProcessorInfo") //nolint:ineffassign,staticcheck - defer span.End() - - span.AddAttributes(trace.StringAttribute("tid", s.tid)) + s.logEntry(ctx).Trace("ComputeProcessorInfo") r, e := s.computeProcessorInfoInternal(ctx, req) return r, errdefs.ToGRPC(e) @@ -537,3 +284,14 @@ func (s *service) IsShutdown() bool { return false } } + +func (s *service) logEntry(ctx context.Context) *logrus.Entry { + e := log.G(ctx) + if s != nil && s.isSandbox { + e = e.WithFields(logrus.Fields{ + "pod-id": s.tid, + }) + } + + return e +} diff --git a/internal/gcs/bridge.go b/internal/gcs/bridge.go index 9c404d7684..afed933e29 100644 --- a/internal/gcs/bridge.go +++ b/internal/gcs/bridge.go @@ -54,6 +54,9 @@ type rpc struct { ch chan struct{} } +// todo(helsaawy): remove bridge.log entry and log based on per-request context, not +// the context that started the bridge + // bridge represents a communcations bridge with the guest. It handles the // transport layer but (mostly) does not parse or construct the message payload. type bridge struct { diff --git a/internal/gcs/container.go b/internal/gcs/container.go index 84889a8608..074524f408 100644 --- a/internal/gcs/container.go +++ b/internal/gcs/container.go @@ -12,7 +12,9 @@ import ( "github.com/Microsoft/hcsshim/internal/hcs/schema1" 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/oc" + "github.com/sirupsen/logrus" "go.opencensus.io/trace" ) @@ -33,10 +35,9 @@ var _ cow.Container = &Container{} // CreateContainer creates a container using ID `cid` and `cfg`. The request // will likely not be cancellable even if `ctx` becomes done. func (gc *GuestConnection) CreateContainer(ctx context.Context, cid string, config interface{}) (_ *Container, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::CreateContainer", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", cid)) + log.G(ctx).WithFields(logrus.Fields{ + logfields.ContainerID: cid, + }).Trace("gcs::GuestConnection:: CreateContainer") c := &Container{ gc: gc, @@ -91,20 +92,15 @@ 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)) - }) + c.logEntry(context.Background()).Trace("gcs::Container::Close") + + c.closeOnce.Do(func() {}) return nil } // CreateProcess creates a process in the container. func (c *Container) CreateProcess(ctx context.Context, config interface{}) (_ cow.Process, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::CreateProcess", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::CreateProcess") return c.gc.exec(ctx, c.id, config) } @@ -116,10 +112,7 @@ func (c *Container) ID() string { // Modify sends a modify request to the container. func (c *Container) Modify(ctx context.Context, config interface{}) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Modify", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Modify") req := containerModifySettings{ requestBase: makeRequest(ctx, c.id), @@ -131,10 +124,7 @@ func (c *Container) Modify(ctx context.Context, config interface{}) (err error) // Properties returns the requested container properties targeting a V1 schema container. func (c *Container) Properties(ctx context.Context, types ...schema1.PropertyType) (_ *schema1.ContainerProperties, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Properties", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Properties") req := containerGetProperties{ requestBase: makeRequest(ctx, c.id), @@ -150,10 +140,7 @@ func (c *Container) Properties(ctx context.Context, types ...schema1.PropertyTyp // PropertiesV2 returns the requested container properties targeting a V2 schema container. func (c *Container) PropertiesV2(ctx context.Context, types ...hcsschema.PropertyType) (_ *hcsschema.Properties, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::PropertiesV2", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::PropertiesV2") req := containerGetPropertiesV2{ requestBase: makeRequest(ctx, c.id), @@ -169,10 +156,7 @@ func (c *Container) PropertiesV2(ctx context.Context, types ...hcsschema.Propert // Start starts the container. func (c *Container) Start(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Start", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Start") req := makeRequest(ctx, c.id) var resp responseBase @@ -190,7 +174,7 @@ func (c *Container) shutdown(ctx context.Context, proc rpcProc) error { select { case <-c.notifyCh: default: - log.G(ctx).WithError(err).Warn("ignoring missing container") + c.logEntry(ctx).WithError(err).Warn("ignoring missing container") } } return nil @@ -200,10 +184,7 @@ func (c *Container) shutdown(ctx context.Context, proc rpcProc) error { // might not be terminated by the time the request completes (and might never // terminate). func (c *Container) Shutdown(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Shutdown", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Shutdown") ctx, cancel := context.WithTimeout(ctx, 30*time.Second) defer cancel() @@ -214,10 +195,7 @@ func (c *Container) Shutdown(ctx context.Context) (err error) { // might not be terminated by the time the request completes (and might never // terminate). func (c *Container) Terminate(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Terminate", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Terminate") ctx, cancel := context.WithTimeout(ctx, 30*time.Second) defer cancel() @@ -236,11 +214,15 @@ func (c *Container) Wait() error { } func (c *Container) waitBackground() { - ctx, span := oc.StartSpan(context.Background(), "gcs::Container::waitBackground") + var err error + _, span := oc.StartSpan(context.Background(), "gcs::Container::waitBackground") defer span.End() + defer func() { oc.SetSpanStatus(span, err) }() span.AddAttributes(trace.StringAttribute("cid", c.id)) - err := c.Wait() - log.G(ctx).Debug("container exited") - oc.SetSpanStatus(span, err) + err = c.Wait() +} + +func (c *Container) logEntry(ctx context.Context) *logrus.Entry { + return log.G(ctx).WithField(logfields.ContainerID, c.id) } diff --git a/internal/gcs/guestconnection.go b/internal/gcs/guestconnection.go index a90fba15e9..8c2a47e512 100644 --- a/internal/gcs/guestconnection.go +++ b/internal/gcs/guestconnection.go @@ -167,9 +167,7 @@ func (gc *GuestConnection) connect(ctx context.Context, isColdStart bool, initGu // Modify sends a modify settings request to the null container. This is // generally used to prepare virtual hardware that has been added to the guest. func (gc *GuestConnection) Modify(ctx context.Context, settings interface{}) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::Modify", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() + log.G(ctx).Trace("gcs::GuestConnection::Modify") req := containerModifySettings{ requestBase: makeRequest(ctx, nullContainerID), @@ -180,9 +178,7 @@ func (gc *GuestConnection) Modify(ctx context.Context, settings interface{}) (er } func (gc *GuestConnection) DumpStacks(ctx context.Context) (response string, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::DumpStacks", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() + log.G(ctx).Trace("gcs::GuestConnection::DumpStacks") req := dumpStacksRequest{ requestBase: makeRequest(ctx, nullContainerID), @@ -193,10 +189,7 @@ func (gc *GuestConnection) DumpStacks(ctx context.Context) (response string, err } func (gc *GuestConnection) DeleteContainerState(ctx context.Context, cid string) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::DeleteContainerState", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", cid)) + log.G(ctx).Trace("gcs::GuestConnection::DeleteContainerState") req := deleteContainerStateRequest{ requestBase: makeRequest(ctx, cid), @@ -216,9 +209,7 @@ func (gc *GuestConnection) Close() error { // CreateProcess creates a process in the container host. func (gc *GuestConnection) CreateProcess(ctx context.Context, settings interface{}) (_ cow.Process, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::CreateProcess", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() + log.G(ctx).Trace("gcs::GuestConnection::CreateProcess") return gc.exec(ctx, nullContainerID, settings) } @@ -268,7 +259,7 @@ func (gc *GuestConnection) notify(ntf *containerNotification) error { if ch == nil { return fmt.Errorf("container %s not found", cid) } - logrus.WithField(logfields.ContainerID, cid).Info("container terminated in guest") + logrus.WithField(logfields.ContainerID, cid).Debug("container terminated in guest") close(ch) return nil } diff --git a/internal/gcs/process.go b/internal/gcs/process.go index fab6af75c7..384525b727 100644 --- a/internal/gcs/process.go +++ b/internal/gcs/process.go @@ -124,32 +124,24 @@ func (gc *GuestConnection) exec(ctx context.Context, cid string, params interfac // Close releases resources associated with the process and closes the // associated standard IO streams. func (p *Process) Close() error { - ctx, span := oc.StartSpan(context.Background(), "gcs::Process::Close") - defer span.End() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + entry := p.logEntry(context.Background()) + entry.Trace("gcs::Process::Close") if err := p.stdin.Close(); err != nil { - log.G(ctx).WithError(err).Warn("close stdin failed") + entry.WithError(err).Warn("close stdin failed") } if err := p.stdout.Close(); err != nil { - log.G(ctx).WithError(err).Warn("close stdout failed") + entry.WithError(err).Warn("close stdout failed") } if err := p.stderr.Close(); err != nil { - log.G(ctx).WithError(err).Warn("close stderr failed") + entry.WithError(err).Warn("close stderr failed") } return nil } // CloseStdin causes the process to read EOF on its stdin stream. func (p *Process) CloseStdin(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::CloseStdin") //nolint:ineffassign,staticcheck - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::CloseStdin") p.stdinCloseWriteOnce.Do(func() { p.stdinCloseWriteErr = p.stdin.CloseWrite() @@ -158,23 +150,13 @@ func (p *Process) CloseStdin(ctx context.Context) (err error) { } func (p *Process) CloseStdout(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::CloseStdout") //nolint:ineffassign,staticcheck - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::CloseStdout") return p.stdout.Close() } func (p *Process) CloseStderr(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::CloseStderr") //nolint:ineffassign,staticcheck - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::CloseStderr") return p.stderr.Close() } @@ -195,12 +177,7 @@ func (p *Process) ExitCode() (_ int, err error) { // signal was delivered. The process might not be terminated by the time this // returns. func (p *Process) Kill(ctx context.Context) (_ bool, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::Kill") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::Kill") return p.Signal(ctx, nil) } @@ -213,12 +190,7 @@ func (p *Process) Pid() int { // ResizeConsole requests that the pty associated with the process resize its // window. func (p *Process) ResizeConsole(ctx context.Context, width, height uint16) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::ResizeConsole", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::ResizeConsole") req := containerResizeConsole{ requestBase: makeRequest(ctx, p.cid), @@ -232,12 +204,7 @@ func (p *Process) ResizeConsole(ctx context.Context, width, height uint16) (err // Signal sends a signal to the process, returning whether it was delivered. func (p *Process) Signal(ctx context.Context, options interface{}) (_ bool, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::Signal", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::Signal") req := containerSignalProcess{ requestBase: makeRequest(ctx, p.cid), @@ -253,11 +220,7 @@ func (p *Process) Signal(ctx context.Context, options interface{}) (_ bool, err return false, err } if !p.waitCall.Done() { - log.G(ctx).WithFields(logrus.Fields{ - logrus.ErrorKey: err, - logfields.ContainerID: p.cid, - logfields.ProcessID: p.id, - }).Warn("ignoring missing process") + p.logEntry(ctx).WithError(err).Warn("ignoring missing process") } return false, nil } @@ -277,17 +240,23 @@ func (p *Process) Wait() error { } func (p *Process) waitBackground() { - ctx, span := oc.StartSpan(context.Background(), "gcs::Process::waitBackground") + var err error + _, span := oc.StartSpan(context.Background(), "gcs::Process::waitBackground") defer span.End() + defer func() { oc.SetSpanStatus(span, err) }() span.AddAttributes( trace.StringAttribute("cid", p.cid), trace.Int64Attribute("pid", int64(p.id))) p.waitCall.Wait() - ec, err := p.ExitCode() - if err != nil { - log.G(ctx).WithError(err).Error("failed wait") - } - log.G(ctx).WithField("exitCode", ec).Debug("process exited") - oc.SetSpanStatus(span, err) + var ec int + ec, err = p.ExitCode() + span.AddAttributes(trace.Int64Attribute("exitCode", int64(ec))) +} + +func (p *Process) logEntry(ctx context.Context) *logrus.Entry { + return log.G(ctx).WithFields(logrus.Fields{ + logfields.ContainerID: p.cid, + logfields.ProcessID: p.id, + }) } diff --git a/internal/gcs/protocol.go b/internal/gcs/protocol.go index 94e55e4c1e..31ba6bcab9 100644 --- a/internal/gcs/protocol.go +++ b/internal/gcs/protocol.go @@ -136,8 +136,11 @@ func (typ msgType) String() string { return s + ")" } +// todo: switch to "go.opentelemetry.io/otel/trace" +// todo: move this to .\internal\oc? + // ocspancontext is the internal JSON representation of the OpenCensus -// `trace.SpanContext` for fowarding to a GCS that supports it. +// `trace.SpanContext` for forwarding to a GCS that supports it. type ocspancontext struct { // TraceID is the `hex` encoded string of the OpenCensus // `SpanContext.TraceID` to propagate to the guest. diff --git a/internal/guest/bridge/bridge_v2.go b/internal/guest/bridge/bridge_v2.go index a81045bb11..a102cf46c2 100644 --- a/internal/guest/bridge/bridge_v2.go +++ b/internal/guest/bridge/bridge_v2.go @@ -10,6 +10,7 @@ import ( "time" "github.com/pkg/errors" + "github.com/sirupsen/logrus" "go.opencensus.io/trace" "golang.org/x/sys/unix" @@ -20,6 +21,7 @@ import ( "github.com/Microsoft/hcsshim/internal/guest/runtime/hcsv2" "github.com/Microsoft/hcsshim/internal/guest/stdio" "github.com/Microsoft/hcsshim/internal/log" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/Microsoft/hcsshim/internal/oc" "github.com/Microsoft/hcsshim/internal/protocol/guestrequest" ) @@ -47,10 +49,8 @@ var capabilities = prot.GcsCapabilities{ // negotiateProtocolV2 was introduced in v4 so will not be called with a minimum // lower than that. func (b *Bridge) negotiateProtocolV2(r *Request) (_ RequestResponse, err error) { - _, span := oc.StartSpan(r.Context, "opengcs::bridge::negotiateProtocolV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::createContainerV2") var request prot.NegotiateProtocol if err := commonutils.UnmarshalJSONWithHresult(r.Message, &request); err != nil { @@ -83,10 +83,8 @@ func (b *Bridge) negotiateProtocolV2(r *Request) (_ RequestResponse, err error) // // This is allowed only for protocol version 4+, schema version 2.1+ func (b *Bridge) createContainerV2(r *Request) (_ RequestResponse, err error) { - ctx, span := oc.StartSpan(r.Context, "opengcs::bridge::createContainerV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::createContainerV2") var request prot.ContainerCreate if err := commonutils.UnmarshalJSONWithHresult(r.Message, &request); err != nil { @@ -136,10 +134,8 @@ func (b *Bridge) createContainerV2(r *Request) (_ RequestResponse, err error) { // // This is allowed only for protocol version 4+, schema version 2.1+ func (b *Bridge) startContainerV2(r *Request) (_ RequestResponse, err error) { - _, span := oc.StartSpan(r.Context, "opengcs::bridge::startContainerV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::startContainerV2") // This is just a noop, but needs to be handled so that an error isn't // returned to the HCS. @@ -167,10 +163,8 @@ func (b *Bridge) startContainerV2(r *Request) (_ RequestResponse, err error) { // // This is allowed only for protocol version 4+, schema version 2.1+ func (b *Bridge) execProcessV2(r *Request) (_ RequestResponse, err error) { - ctx, span := oc.StartSpan(r.Context, "opengcs::bridge::execProcessV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::execProcessV2") var request prot.ContainerExecuteProcess if err := commonutils.UnmarshalJSONWithHresult(r.Message, &request); err != nil { @@ -211,7 +205,10 @@ func (b *Bridge) execProcessV2(r *Request) (_ RequestResponse, err error) { if err != nil { return nil, err } - log.G(ctx).WithField("pid", pid).Debug("created process pid") + log.G(ctx).WithFields(logrus.Fields{ + logfields.ContainerID: r.ContainerID, + logfields.ProcessID: pid, + }).Debug("created process pid") return &prot.ContainerExecuteProcessResponse{ ProcessID: uint32(pid), }, nil @@ -223,11 +220,10 @@ func (b *Bridge) execProcessV2(r *Request) (_ RequestResponse, err error) { // // This is allowed only for protocol version 4+, schema version 2.1+ func (b *Bridge) killContainerV2(r *Request) (RequestResponse, error) { - ctx, span := oc.StartSpan(r.Context, "opengcs::bridge::killContainerV2") - defer span.End() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::killContainerV2") - return b.signalContainerV2(ctx, span, r, unix.SIGKILL) + return b.signalContainerV2(ctx, r, unix.SIGKILL) } // shutdownContainerV2 is a user requested shutdown of the container and all @@ -236,22 +232,16 @@ func (b *Bridge) killContainerV2(r *Request) (RequestResponse, error) { // // This is allowed only for protocol version 4+, schema version 2.1+ func (b *Bridge) shutdownContainerV2(r *Request) (RequestResponse, error) { - ctx, span := oc.StartSpan(r.Context, "opengcs::bridge::shutdownContainerV2") - defer span.End() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::shutdownContainerV2") - return b.signalContainerV2(ctx, span, r, unix.SIGTERM) + return b.signalContainerV2(ctx, r, unix.SIGTERM) } // signalContainerV2 is not a handler func. This is because the actual signal is // implied based on the message type of either `killContainerV2` or // `shutdownContainerV2`. -func (b *Bridge) signalContainerV2(ctx context.Context, span *trace.Span, r *Request, signal syscall.Signal) (_ RequestResponse, err error) { - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", r.ContainerID), - trace.Int64Attribute("signal", int64(signal))) - +func (b *Bridge) signalContainerV2(ctx context.Context, r *Request, signal syscall.Signal) (_ RequestResponse, err error) { var request prot.MessageBase if err := commonutils.UnmarshalJSONWithHresult(r.Message, &request); err != nil { return nil, errors.Wrapf(err, "failed to unmarshal JSON in message \"%s\"", r.Message) @@ -272,6 +262,11 @@ func (b *Bridge) signalContainerV2(ctx context.Context, span *trace.Span, r *Req return nil, err } + log.G(ctx).WithFields(logrus.Fields{ + logfields.ContainerID: r.ContainerID, + "signal": signal, + }).Debug("signaling container") + err = c.Kill(ctx, signal) if err != nil { return nil, err @@ -282,20 +277,14 @@ func (b *Bridge) signalContainerV2(ctx context.Context, span *trace.Span, r *Req } func (b *Bridge) signalProcessV2(r *Request) (_ RequestResponse, err error) { - ctx, span := oc.StartSpan(r.Context, "opengcs::bridge::signalProcessV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::signalProcessV2") var request prot.ContainerSignalProcess if err := commonutils.UnmarshalJSONWithHresult(r.Message, &request); err != nil { return nil, errors.Wrapf(err, "failed to unmarshal JSON in message \"%s\"", r.Message) } - span.AddAttributes( - trace.Int64Attribute("pid", int64(request.ProcessID)), - trace.Int64Attribute("signal", int64(request.Options.Signal))) - c, err := b.hostState.GetCreatedContainer(request.ContainerID) if err != nil { return nil, err @@ -312,6 +301,14 @@ func (b *Bridge) signalProcessV2(r *Request) (_ RequestResponse, err error) { } else { signal = syscall.Signal(request.Options.Signal) } + + log.G(ctx).WithFields(logrus.Fields{ + logfields.ContainerID: r.ContainerID, + logfields.ProcessID: request.ProcessID, + "signal": signal, + }).Debug("signaling container") + + c, err = b.hostState.GetCreatedContainer(request.ContainerID) if err := p.Kill(ctx, signal); err != nil { return nil, err } @@ -320,10 +317,8 @@ func (b *Bridge) signalProcessV2(r *Request) (_ RequestResponse, err error) { } func (b *Bridge) getPropertiesV2(r *Request) (_ RequestResponse, err error) { - ctx, span := oc.StartSpan(r.Context, "opengcs::bridge::getPropertiesV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::getPropertiesV2") var request prot.ContainerGetProperties if err := commonutils.UnmarshalJSONWithHresult(r.Message, &request); err != nil { @@ -438,21 +433,14 @@ func (b *Bridge) waitOnProcessV2(r *Request) (_ RequestResponse, err error) { } func (b *Bridge) resizeConsoleV2(r *Request) (_ RequestResponse, err error) { - ctx, span := oc.StartSpan(r.Context, "opengcs::bridge::resizeConsoleV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).WithField(logfields.ContainerID, r.ContainerID).Trace("opengcs::bridge::resizeConsoleV2") var request prot.ContainerResizeConsole if err := commonutils.UnmarshalJSONWithHresult(r.Message, &request); err != nil { return nil, errors.Wrapf(err, "failed to unmarshal JSON in message \"%s\"", r.Message) } - span.AddAttributes( - trace.Int64Attribute("pid", int64(request.ProcessID)), - trace.Int64Attribute("height", int64(request.Height)), - trace.Int64Attribute("width", int64(request.Width))) - c, err := b.hostState.GetCreatedContainer(request.ContainerID) if err != nil { return nil, err @@ -463,6 +451,12 @@ func (b *Bridge) resizeConsoleV2(r *Request) (_ RequestResponse, err error) { return nil, err } + log.G(ctx).WithFields(logrus.Fields{ + logfields.ContainerID: r.ContainerID, + logfields.ProcessID: request.ProcessID, + "height": request.Height, + "witdth": request.Width, + }).Debug("resizing console") err = p.ResizeConsole(ctx, request.Height, request.Width) if err != nil { return nil, err @@ -472,10 +466,8 @@ func (b *Bridge) resizeConsoleV2(r *Request) (_ RequestResponse, err error) { } func (b *Bridge) modifySettingsV2(r *Request) (_ RequestResponse, err error) { - ctx, span := oc.StartSpan(r.Context, "opengcs::bridge::modifySettingsV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::modifySettingsV2") request, err := prot.UnmarshalContainerModifySettings(r.Message) if err != nil { @@ -491,9 +483,8 @@ func (b *Bridge) modifySettingsV2(r *Request) (_ RequestResponse, err error) { } func (b *Bridge) dumpStacksV2(r *Request) (_ RequestResponse, err error) { - _, span := oc.StartSpan(r.Context, "opengcs::bridge::dumpStacksV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::dumpStacksV2") stacks := debug.DumpStacks() @@ -503,11 +494,8 @@ func (b *Bridge) dumpStacksV2(r *Request) (_ RequestResponse, err error) { } func (b *Bridge) deleteContainerStateV2(r *Request) (_ RequestResponse, err error) { - ctx, span := oc.StartSpan(r.Context, "opengcs::bridge::deleteContainerStateV2") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - - span.AddAttributes(trace.StringAttribute("cid", r.ContainerID)) + ctx := r.Context + log.G(ctx).Trace("opengcs::bridge::deleteContainerStateV2") var request prot.MessageBase if err := commonutils.UnmarshalJSONWithHresult(r.Message, &request); err != nil { diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/bridge.go b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/bridge.go index 9c404d7684..afed933e29 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/bridge.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/bridge.go @@ -54,6 +54,9 @@ type rpc struct { ch chan struct{} } +// todo(helsaawy): remove bridge.log entry and log based on per-request context, not +// the context that started the bridge + // bridge represents a communcations bridge with the guest. It handles the // transport layer but (mostly) does not parse or construct the message payload. type bridge struct { 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..074524f408 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/container.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/container.go @@ -12,7 +12,9 @@ import ( "github.com/Microsoft/hcsshim/internal/hcs/schema1" 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/oc" + "github.com/sirupsen/logrus" "go.opencensus.io/trace" ) @@ -33,10 +35,9 @@ var _ cow.Container = &Container{} // CreateContainer creates a container using ID `cid` and `cfg`. The request // will likely not be cancellable even if `ctx` becomes done. func (gc *GuestConnection) CreateContainer(ctx context.Context, cid string, config interface{}) (_ *Container, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::CreateContainer", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", cid)) + log.G(ctx).WithFields(logrus.Fields{ + logfields.ContainerID: cid, + }).Trace("gcs::GuestConnection:: CreateContainer") c := &Container{ gc: gc, @@ -91,20 +92,15 @@ 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)) - }) + c.logEntry(context.Background()).Trace("gcs::Container::Close") + + c.closeOnce.Do(func() {}) return nil } // CreateProcess creates a process in the container. func (c *Container) CreateProcess(ctx context.Context, config interface{}) (_ cow.Process, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::CreateProcess", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::CreateProcess") return c.gc.exec(ctx, c.id, config) } @@ -116,10 +112,7 @@ func (c *Container) ID() string { // Modify sends a modify request to the container. func (c *Container) Modify(ctx context.Context, config interface{}) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Modify", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Modify") req := containerModifySettings{ requestBase: makeRequest(ctx, c.id), @@ -131,10 +124,7 @@ func (c *Container) Modify(ctx context.Context, config interface{}) (err error) // Properties returns the requested container properties targeting a V1 schema container. func (c *Container) Properties(ctx context.Context, types ...schema1.PropertyType) (_ *schema1.ContainerProperties, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Properties", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Properties") req := containerGetProperties{ requestBase: makeRequest(ctx, c.id), @@ -150,10 +140,7 @@ func (c *Container) Properties(ctx context.Context, types ...schema1.PropertyTyp // PropertiesV2 returns the requested container properties targeting a V2 schema container. func (c *Container) PropertiesV2(ctx context.Context, types ...hcsschema.PropertyType) (_ *hcsschema.Properties, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::PropertiesV2", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::PropertiesV2") req := containerGetPropertiesV2{ requestBase: makeRequest(ctx, c.id), @@ -169,10 +156,7 @@ func (c *Container) PropertiesV2(ctx context.Context, types ...hcsschema.Propert // Start starts the container. func (c *Container) Start(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Start", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Start") req := makeRequest(ctx, c.id) var resp responseBase @@ -190,7 +174,7 @@ func (c *Container) shutdown(ctx context.Context, proc rpcProc) error { select { case <-c.notifyCh: default: - log.G(ctx).WithError(err).Warn("ignoring missing container") + c.logEntry(ctx).WithError(err).Warn("ignoring missing container") } } return nil @@ -200,10 +184,7 @@ func (c *Container) shutdown(ctx context.Context, proc rpcProc) error { // might not be terminated by the time the request completes (and might never // terminate). func (c *Container) Shutdown(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Shutdown", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Shutdown") ctx, cancel := context.WithTimeout(ctx, 30*time.Second) defer cancel() @@ -214,10 +195,7 @@ func (c *Container) Shutdown(ctx context.Context) (err error) { // might not be terminated by the time the request completes (and might never // terminate). func (c *Container) Terminate(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Container::Terminate", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", c.id)) + c.logEntry(ctx).Trace("gcs::Container::Terminate") ctx, cancel := context.WithTimeout(ctx, 30*time.Second) defer cancel() @@ -236,11 +214,15 @@ func (c *Container) Wait() error { } func (c *Container) waitBackground() { - ctx, span := oc.StartSpan(context.Background(), "gcs::Container::waitBackground") + var err error + _, span := oc.StartSpan(context.Background(), "gcs::Container::waitBackground") defer span.End() + defer func() { oc.SetSpanStatus(span, err) }() span.AddAttributes(trace.StringAttribute("cid", c.id)) - err := c.Wait() - log.G(ctx).Debug("container exited") - oc.SetSpanStatus(span, err) + err = c.Wait() +} + +func (c *Container) logEntry(ctx context.Context) *logrus.Entry { + return log.G(ctx).WithField(logfields.ContainerID, c.id) } diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/guestconnection.go b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/guestconnection.go index a90fba15e9..8c2a47e512 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/guestconnection.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/guestconnection.go @@ -167,9 +167,7 @@ func (gc *GuestConnection) connect(ctx context.Context, isColdStart bool, initGu // Modify sends a modify settings request to the null container. This is // generally used to prepare virtual hardware that has been added to the guest. func (gc *GuestConnection) Modify(ctx context.Context, settings interface{}) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::Modify", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() + log.G(ctx).Trace("gcs::GuestConnection::Modify") req := containerModifySettings{ requestBase: makeRequest(ctx, nullContainerID), @@ -180,9 +178,7 @@ func (gc *GuestConnection) Modify(ctx context.Context, settings interface{}) (er } func (gc *GuestConnection) DumpStacks(ctx context.Context) (response string, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::DumpStacks", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() + log.G(ctx).Trace("gcs::GuestConnection::DumpStacks") req := dumpStacksRequest{ requestBase: makeRequest(ctx, nullContainerID), @@ -193,10 +189,7 @@ func (gc *GuestConnection) DumpStacks(ctx context.Context) (response string, err } func (gc *GuestConnection) DeleteContainerState(ctx context.Context, cid string) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::DeleteContainerState", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes(trace.StringAttribute("cid", cid)) + log.G(ctx).Trace("gcs::GuestConnection::DeleteContainerState") req := deleteContainerStateRequest{ requestBase: makeRequest(ctx, cid), @@ -216,9 +209,7 @@ func (gc *GuestConnection) Close() error { // CreateProcess creates a process in the container host. func (gc *GuestConnection) CreateProcess(ctx context.Context, settings interface{}) (_ cow.Process, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::CreateProcess", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() + log.G(ctx).Trace("gcs::GuestConnection::CreateProcess") return gc.exec(ctx, nullContainerID, settings) } @@ -268,7 +259,7 @@ func (gc *GuestConnection) notify(ntf *containerNotification) error { if ch == nil { return fmt.Errorf("container %s not found", cid) } - logrus.WithField(logfields.ContainerID, cid).Info("container terminated in guest") + logrus.WithField(logfields.ContainerID, cid).Debug("container terminated in guest") close(ch) return nil } diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/process.go b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/process.go index fab6af75c7..384525b727 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/process.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/process.go @@ -124,32 +124,24 @@ func (gc *GuestConnection) exec(ctx context.Context, cid string, params interfac // Close releases resources associated with the process and closes the // associated standard IO streams. func (p *Process) Close() error { - ctx, span := oc.StartSpan(context.Background(), "gcs::Process::Close") - defer span.End() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + entry := p.logEntry(context.Background()) + entry.Trace("gcs::Process::Close") if err := p.stdin.Close(); err != nil { - log.G(ctx).WithError(err).Warn("close stdin failed") + entry.WithError(err).Warn("close stdin failed") } if err := p.stdout.Close(); err != nil { - log.G(ctx).WithError(err).Warn("close stdout failed") + entry.WithError(err).Warn("close stdout failed") } if err := p.stderr.Close(); err != nil { - log.G(ctx).WithError(err).Warn("close stderr failed") + entry.WithError(err).Warn("close stderr failed") } return nil } // CloseStdin causes the process to read EOF on its stdin stream. func (p *Process) CloseStdin(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::CloseStdin") //nolint:ineffassign,staticcheck - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::CloseStdin") p.stdinCloseWriteOnce.Do(func() { p.stdinCloseWriteErr = p.stdin.CloseWrite() @@ -158,23 +150,13 @@ func (p *Process) CloseStdin(ctx context.Context) (err error) { } func (p *Process) CloseStdout(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::CloseStdout") //nolint:ineffassign,staticcheck - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::CloseStdout") return p.stdout.Close() } func (p *Process) CloseStderr(ctx context.Context) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::CloseStderr") //nolint:ineffassign,staticcheck - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::CloseStderr") return p.stderr.Close() } @@ -195,12 +177,7 @@ func (p *Process) ExitCode() (_ int, err error) { // signal was delivered. The process might not be terminated by the time this // returns. func (p *Process) Kill(ctx context.Context) (_ bool, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::Kill") - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::Kill") return p.Signal(ctx, nil) } @@ -213,12 +190,7 @@ func (p *Process) Pid() int { // ResizeConsole requests that the pty associated with the process resize its // window. func (p *Process) ResizeConsole(ctx context.Context, width, height uint16) (err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::ResizeConsole", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::ResizeConsole") req := containerResizeConsole{ requestBase: makeRequest(ctx, p.cid), @@ -232,12 +204,7 @@ func (p *Process) ResizeConsole(ctx context.Context, width, height uint16) (err // Signal sends a signal to the process, returning whether it was delivered. func (p *Process) Signal(ctx context.Context, options interface{}) (_ bool, err error) { - ctx, span := oc.StartSpan(ctx, "gcs::Process::Signal", oc.WithClientSpanKind) - defer span.End() - defer func() { oc.SetSpanStatus(span, err) }() - span.AddAttributes( - trace.StringAttribute("cid", p.cid), - trace.Int64Attribute("pid", int64(p.id))) + p.logEntry(ctx).Trace("gcs::Process::Signal") req := containerSignalProcess{ requestBase: makeRequest(ctx, p.cid), @@ -253,11 +220,7 @@ func (p *Process) Signal(ctx context.Context, options interface{}) (_ bool, err return false, err } if !p.waitCall.Done() { - log.G(ctx).WithFields(logrus.Fields{ - logrus.ErrorKey: err, - logfields.ContainerID: p.cid, - logfields.ProcessID: p.id, - }).Warn("ignoring missing process") + p.logEntry(ctx).WithError(err).Warn("ignoring missing process") } return false, nil } @@ -277,17 +240,23 @@ func (p *Process) Wait() error { } func (p *Process) waitBackground() { - ctx, span := oc.StartSpan(context.Background(), "gcs::Process::waitBackground") + var err error + _, span := oc.StartSpan(context.Background(), "gcs::Process::waitBackground") defer span.End() + defer func() { oc.SetSpanStatus(span, err) }() span.AddAttributes( trace.StringAttribute("cid", p.cid), trace.Int64Attribute("pid", int64(p.id))) p.waitCall.Wait() - ec, err := p.ExitCode() - if err != nil { - log.G(ctx).WithError(err).Error("failed wait") - } - log.G(ctx).WithField("exitCode", ec).Debug("process exited") - oc.SetSpanStatus(span, err) + var ec int + ec, err = p.ExitCode() + span.AddAttributes(trace.Int64Attribute("exitCode", int64(ec))) +} + +func (p *Process) logEntry(ctx context.Context) *logrus.Entry { + return log.G(ctx).WithFields(logrus.Fields{ + logfields.ContainerID: p.cid, + logfields.ProcessID: p.id, + }) } diff --git a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/protocol.go b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/protocol.go index 94e55e4c1e..31ba6bcab9 100644 --- a/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/protocol.go +++ b/test/vendor/github.com/Microsoft/hcsshim/internal/gcs/protocol.go @@ -136,8 +136,11 @@ func (typ msgType) String() string { return s + ")" } +// todo: switch to "go.opentelemetry.io/otel/trace" +// todo: move this to .\internal\oc? + // ocspancontext is the internal JSON representation of the OpenCensus -// `trace.SpanContext` for fowarding to a GCS that supports it. +// `trace.SpanContext` for forwarding to a GCS that supports it. type ocspancontext struct { // TraceID is the `hex` encoded string of the OpenCensus // `SpanContext.TraceID` to propagate to the guest.