Skip to content

Commit

Permalink
Remove redundant spans
Browse files Browse the repository at this point in the history 
Replaced redundant `cmd/containerd-shim-runhcs-v1/service.go.(Service)`
and `internal/gcs` 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 <hamzaelsaawy@microsoft.com>
  • Loading branch information
@helsaawy
helsaawy committed May 9, 2022
1 parent 5fe9129 commit 668fd6e
Show file tree
Hide file tree
Showing 11 changed files with 157 additions and 503 deletions.
312 changes: 35 additions & 277 deletions cmd/containerd-shim-runhcs-v1/service.go
View file

Large diffs are not rendered by default.

3 changes: 3 additions & 0 deletions internal/gcs/bridge.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
66 changes: 24 additions & 42 deletions internal/gcs/container.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)

Expand All @@ -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,
Expand Down Expand Up @@ -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)
}
Expand All @@ -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),
Expand All @@ -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),
Expand All @@ -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),
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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()
Expand All @@ -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()
Expand All @@ -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)
}
19 changes: 5 additions & 14 deletions internal/gcs/guestconnection.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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),
Expand All @@ -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),
Expand All @@ -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),
Expand All @@ -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)
}
Expand Down Expand Up @@ -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
}
Expand Down
81 changes: 25 additions & 56 deletions internal/gcs/process.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand All @@ -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()
}
Expand All @@ -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)
}
Expand All @@ -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),
Expand All @@ -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),
Expand All @@ -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
}
Expand All @@ -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,
})
}
5 changes: 4 additions & 1 deletion internal/gcs/protocol.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
3 changes: 3 additions & 0 deletions test/vendor/github.com/Microsoft/hcsshim/internal/gcs/bridge.go
View file

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

Loading

0 comments on commit 668fd6e

Please sign in to comment.