Skip to content

Commit

Permalink
Log context integration changes (microsoft#1382)
Browse files Browse the repository at this point in the history
Log integration changes

Changed `internal\log` functions interacts with context.
`log.G` no longer adds trace/span IDs to entry.

Added logrus hook to add trace/span ID to entry when exporting log
entry.

Added `log.S()` to set the log entry stored in the context with
provided fields. `log.G()` now checks the context for a stored
context.

Added `log.Copy()` to add log entry and trace span from source context
to destination, allowing for duplicating contexts but not cancellation.

Added `log.U()` to update the context an entry (in the context) points
to, allowing it to reference the latest span and other information.

Added `oc.StartSpan[WithRemoteParent]` to set the context for log entries
to reference the newly created context.

Switch to oc.StartSpan to update log context

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>
  • Loading branch information
helsaawy authored May 9, 2022
1 parent d51e522 commit 63c9743
Show file tree
Hide file tree
Showing 52 changed files with 372 additions and 175 deletions.
13 changes: 11 additions & 2 deletions cmd/cmd.go
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@ import (

"github.com/Microsoft/hcsshim/internal/cow"
hcsschema "github.com/Microsoft/hcsshim/internal/hcs/schema2"
"github.com/Microsoft/hcsshim/internal/log"
specs "github.com/opencontainers/runtime-spec/specs-go"
"github.com/sirupsen/logrus"
"golang.org/x/sync/errgroup"
Expand Down Expand Up @@ -111,7 +112,7 @@ func Command(host cow.ProcessHost, name string, arg ...string) *Cmd {
Spec: &specs.Process{
Args: append([]string{name}, arg...),
},
Log: logrus.NewEntry(logrus.StandardLogger()),
Log: log.L.Dup(),
ExitState: &ExitState{},
}
if host.OS() == "windows" {
Expand All @@ -128,6 +129,7 @@ func Command(host cow.ProcessHost, name string, arg ...string) *Cmd {
func CommandContext(ctx context.Context, host cow.ProcessHost, name string, arg ...string) *Cmd {
cmd := Command(host, name, arg...)
cmd.Context = ctx
cmd.Log = log.G(ctx)
return cmd
}

Expand Down Expand Up @@ -239,7 +241,14 @@ func (c *Cmd) Start() error {
go func() {
select {
case <-c.Context.Done():
_, _ = c.Process.Kill(context.TODO())
// Process.Kill (via Process.Signal) will not send an RPC if the
// provided context in is cancelled (bridge.AsyncRPC will end early)
ctx := c.Context
if ctx == nil {
ctx = context.Background()
}
kctx := log.Copy(context.Background(), ctx)
_, _ = c.Process.Kill(kctx)
case <-c.allDoneCh:
}
}()
Expand Down
2 changes: 1 addition & 1 deletion copyfile/copyfile.go
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,7 @@ var (
// CopyFile is a utility for copying a file using CopyFileW win32 API for
// performance.
func CopyFile(ctx context.Context, srcFile, destFile string, overwrite bool) (err error) {
ctx, span := trace.StartSpan(ctx, "copyfile::CopyFile") //nolint:ineffassign,staticcheck
ctx, span := oc.StartSpan(ctx, "copyfile::CopyFile") //nolint:ineffassign,staticcheck
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()
span.AddAttributes(
Expand Down
4 changes: 2 additions & 2 deletions gcs/bridge.go
Original file line number Diff line number Diff line change
Expand Up @@ -311,7 +311,7 @@ func (brdg *bridge) recvLoop() error {
}
brdg.log.WithFields(logrus.Fields{
"payload": string(b),
"type": typ,
"type": typ.String(),
"message-id": id}).Debug("bridge receive")
switch typ & msgTypeMask {
case msgTypeResponse:
Expand Down Expand Up @@ -412,7 +412,7 @@ func (brdg *bridge) writeMessage(buf *bytes.Buffer, enc *json.Encoder, typ msgTy
}
brdg.log.WithFields(logrus.Fields{
"payload": string(b),
"type": typ,
"type": typ.String(),
"message-id": id}).Debug("bridge send")
}

Expand Down
20 changes: 10 additions & 10 deletions gcs/container.go
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ 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 := trace.StartSpan(ctx, "gcs::GuestConnection::CreateContainer")
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))
Expand Down Expand Up @@ -92,7 +92,7 @@ func (c *Container) IsOCI() bool {
// Close releases associated with the container.
func (c *Container) Close() error {
c.closeOnce.Do(func() {
_, span := trace.StartSpan(context.Background(), "gcs::Container::Close")
_, span := oc.StartSpan(context.Background(), "gcs::Container::Close")
defer span.End()
span.AddAttributes(trace.StringAttribute("cid", c.id))
})
Expand All @@ -101,7 +101,7 @@ func (c *Container) Close() error {

// CreateProcess creates a process in the container.
func (c *Container) CreateProcess(ctx context.Context, config interface{}) (_ cow.Process, err error) {
ctx, span := trace.StartSpan(ctx, "gcs::Container::CreateProcess")
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))
Expand All @@ -116,7 +116,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 := trace.StartSpan(ctx, "gcs::Container::Modify")
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))
Expand All @@ -131,7 +131,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 := trace.StartSpan(ctx, "gcs::Container::Properties")
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))
Expand All @@ -150,7 +150,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 := trace.StartSpan(ctx, "gcs::Container::PropertiesV2")
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))
Expand All @@ -169,7 +169,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 := trace.StartSpan(ctx, "gcs::Container::Start")
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))
Expand Down Expand Up @@ -200,7 +200,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 := trace.StartSpan(ctx, "gcs::Container::Shutdown")
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))
Expand All @@ -214,7 +214,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 := trace.StartSpan(ctx, "gcs::Container::Terminate")
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))
Expand All @@ -236,7 +236,7 @@ func (c *Container) Wait() error {
}

func (c *Container) waitBackground() {
ctx, span := trace.StartSpan(context.Background(), "gcs::Container::waitBackground")
ctx, span := oc.StartSpan(context.Background(), "gcs::Container::waitBackground")
defer span.End()
span.AddAttributes(trace.StringAttribute("cid", c.id))

Expand Down
10 changes: 5 additions & 5 deletions gcs/guestconnection.go
Original file line number Diff line number Diff line change
Expand Up @@ -68,7 +68,7 @@ type GuestConnectionConfig struct {

// Connect establishes a GCS connection. `gcc.Conn` will be closed by this function.
func (gcc *GuestConnectionConfig) Connect(ctx context.Context, isColdStart bool) (_ *GuestConnection, err error) {
ctx, span := trace.StartSpan(ctx, "gcs::GuestConnectionConfig::Connect")
ctx, span := oc.StartSpan(ctx, "gcs::GuestConnectionConfig::Connect", oc.WithClientSpanKind)
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()

Expand Down Expand Up @@ -167,7 +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 := trace.StartSpan(ctx, "gcs::GuestConnection::Modify")
ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::Modify", oc.WithClientSpanKind)
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()

Expand All @@ -180,7 +180,7 @@ func (gc *GuestConnection) Modify(ctx context.Context, settings interface{}) (er
}

func (gc *GuestConnection) DumpStacks(ctx context.Context) (response string, err error) {
ctx, span := trace.StartSpan(ctx, "gcs::GuestConnection::DumpStacks")
ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::DumpStacks", oc.WithClientSpanKind)
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()

Expand All @@ -193,7 +193,7 @@ func (gc *GuestConnection) DumpStacks(ctx context.Context) (response string, err
}

func (gc *GuestConnection) DeleteContainerState(ctx context.Context, cid string) (err error) {
ctx, span := trace.StartSpan(ctx, "gcs::GuestConnection::DeleteContainerState")
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))
Expand All @@ -216,7 +216,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 := trace.StartSpan(ctx, "gcs::GuestConnection::CreateProcess")
ctx, span := oc.StartSpan(ctx, "gcs::GuestConnection::CreateProcess", oc.WithClientSpanKind)
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()

Expand Down
4 changes: 3 additions & 1 deletion gcs/guestconnection_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,8 @@ import (
"github.com/sirupsen/logrus"
"go.opencensus.io/trace"
"go.opencensus.io/trace/tracestate"

"github.com/Microsoft/hcsshim/internal/oc"
)

const pipePortFmt = `\\.\pipe\gctest-port-%d`
Expand Down Expand Up @@ -273,7 +275,7 @@ func Test_makeRequestNoSpan(t *testing.T) {
}

func Test_makeRequestWithSpan(t *testing.T) {
ctx, span := trace.StartSpan(context.Background(), t.Name())
ctx, span := oc.StartSpan(context.Background(), t.Name())
defer span.End()
r := makeRequest(ctx, t.Name())

Expand Down
16 changes: 8 additions & 8 deletions gcs/process.go
Original file line number Diff line number Diff line change
Expand Up @@ -124,7 +124,7 @@ 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 := trace.StartSpan(context.Background(), "gcs::Process::Close")
ctx, span := oc.StartSpan(context.Background(), "gcs::Process::Close")
defer span.End()
span.AddAttributes(
trace.StringAttribute("cid", p.cid),
Expand All @@ -144,7 +144,7 @@ func (p *Process) Close() error {

// CloseStdin causes the process to read EOF on its stdin stream.
func (p *Process) CloseStdin(ctx context.Context) (err error) {
ctx, span := trace.StartSpan(ctx, "gcs::Process::CloseStdin") //nolint:ineffassign,staticcheck
ctx, span := oc.StartSpan(ctx, "gcs::Process::CloseStdin") //nolint:ineffassign,staticcheck
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()
span.AddAttributes(
Expand All @@ -158,7 +158,7 @@ func (p *Process) CloseStdin(ctx context.Context) (err error) {
}

func (p *Process) CloseStdout(ctx context.Context) (err error) {
ctx, span := trace.StartSpan(ctx, "gcs::Process::CloseStdout") //nolint:ineffassign,staticcheck
ctx, span := oc.StartSpan(ctx, "gcs::Process::CloseStdout") //nolint:ineffassign,staticcheck
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()
span.AddAttributes(
Expand All @@ -169,7 +169,7 @@ func (p *Process) CloseStdout(ctx context.Context) (err error) {
}

func (p *Process) CloseStderr(ctx context.Context) (err error) {
ctx, span := trace.StartSpan(ctx, "gcs::Process::CloseStderr") //nolint:ineffassign,staticcheck
ctx, span := oc.StartSpan(ctx, "gcs::Process::CloseStderr") //nolint:ineffassign,staticcheck
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()
span.AddAttributes(
Expand All @@ -195,7 +195,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 := trace.StartSpan(ctx, "gcs::Process::Kill")
ctx, span := oc.StartSpan(ctx, "gcs::Process::Kill")
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()
span.AddAttributes(
Expand All @@ -213,7 +213,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 := trace.StartSpan(ctx, "gcs::Process::ResizeConsole")
ctx, span := oc.StartSpan(ctx, "gcs::Process::ResizeConsole", oc.WithClientSpanKind)
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()
span.AddAttributes(
Expand All @@ -232,7 +232,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 := trace.StartSpan(ctx, "gcs::Process::Signal")
ctx, span := oc.StartSpan(ctx, "gcs::Process::Signal", oc.WithClientSpanKind)
defer span.End()
defer func() { oc.SetSpanStatus(span, err) }()
span.AddAttributes(
Expand Down Expand Up @@ -277,7 +277,7 @@ func (p *Process) Wait() error {
}

func (p *Process) waitBackground() {
ctx, span := trace.StartSpan(context.Background(), "gcs::Process::waitBackground")
ctx, span := oc.StartSpan(context.Background(), "gcs::Process::waitBackground")
defer span.End()
span.AddAttributes(
trace.StringAttribute("cid", p.cid),
Expand Down
30 changes: 21 additions & 9 deletions guest/bridge/bridge.go
Original file line number Diff line number Diff line change
Expand Up @@ -17,15 +17,16 @@ import (
"sync/atomic"
"time"

"github.com/pkg/errors"
"github.com/sirupsen/logrus"
"go.opencensus.io/trace"
"go.opencensus.io/trace/tracestate"

"github.com/Microsoft/hcsshim/internal/guest/gcserr"
"github.com/Microsoft/hcsshim/internal/guest/prot"
"github.com/Microsoft/hcsshim/internal/guest/runtime/hcsv2"
"github.com/Microsoft/hcsshim/internal/log"
"github.com/Microsoft/hcsshim/internal/oc"
"github.com/pkg/errors"
"github.com/sirupsen/logrus"
"go.opencensus.io/trace"
"go.opencensus.io/trace/tracestate"
)

// UnknownMessage represents the default handler logic for an unmatched request
Expand Down Expand Up @@ -131,7 +132,7 @@ func (mux *Mux) ServeMsg(r *Request) (RequestResponse, error) {
type Request struct {
// Context is the request context received from the bridge.
Context context.Context
// Header is the wire format message header that preceeded the message for
// Header is the wire format message header that preceded the message for
// this request.
Header *prot.MessageHeader
// ContainerID is the id of the container that this message corresponds to.
Expand Down Expand Up @@ -164,7 +165,7 @@ type bridgeResponse struct {
// It has two fundamentally different dispatch options:
//
// 1. Request/Response where using the `Handler` a request
// of a given type will be dispatched to the apprpriate handler
// of a given type will be dispatched to the appropriate handler
// and an appropriate response will respond to exactly that request that
// caused the dispatch.
//
Expand Down Expand Up @@ -288,9 +289,18 @@ func (b *Bridge) ListenAndServe(bridgeIn io.ReadCloser, bridgeOut io.WriteCloser
}
}
}
ctx, span = trace.StartSpanWithRemoteParent(context.Background(), "opengcs::bridge::request", sc)
ctx, span = oc.StartSpanWithRemoteParent(
context.Background(),
"opengcs::bridge::request",
sc,
oc.WithServerSpanKind,
)
} else {
ctx, span = trace.StartSpan(context.Background(), "opengcs::bridge::request")
ctx, span = oc.StartSpan(
context.Background(),
"opengcs::bridge::request",
oc.WithServerSpanKind,
)
}

span.AddAttributes(
Expand Down Expand Up @@ -410,7 +420,9 @@ func (b *Bridge) ListenAndServe(bridgeIn io.ReadCloser, bridgeOut io.WriteCloser

// PublishNotification writes a specific notification to the bridge.
func (b *Bridge) PublishNotification(n *prot.ContainerNotification) {
ctx, span := trace.StartSpan(context.Background(), "opengcs::bridge::PublishNotification")
ctx, span := oc.StartSpan(context.Background(),
"opengcs::bridge::PublishNotification",
oc.WithClientSpanKind)
span.AddAttributes(trace.StringAttribute("notification", fmt.Sprintf("%+v", n)))
// DONT defer span.End() here. Publish is odd because bridgeResponse calls
// `End` on the `ctx` after the response is sent.
Expand Down
Loading

0 comments on commit 63c9743

Please sign in to comment.