From 202f90ae87bc9026d3e75b2e2b1344ad3a775075 Mon Sep 17 00:00:00 2001 From: Kirtana Ashok Date: Tue, 13 Feb 2024 19:46:01 -0800 Subject: [PATCH] Add spans and drop large size high volume trace logs Signed-off-by: Kirtana Ashok (cherry picked from commit c91d82d2e8c5cad1034f17712391e0c76281e5aa) Signed-off-by: Kirtana Ashok --- cmd/containerd-shim-runhcs-v1/exec_hcs.go | 2 +- internal/gcs/bridge.go | 26 +++++++++++++++++++---- internal/guest/bridge/bridge.go | 7 +++--- 3 files changed, 27 insertions(+), 8 deletions(-) diff --git a/cmd/containerd-shim-runhcs-v1/exec_hcs.go b/cmd/containerd-shim-runhcs-v1/exec_hcs.go index 9395f35724..84cdb38d24 100644 --- a/cmd/containerd-shim-runhcs-v1/exec_hcs.go +++ b/cmd/containerd-shim-runhcs-v1/exec_hcs.go @@ -48,7 +48,7 @@ func newHcsExec( "eid": id, // Init exec ID is always same as Task ID "bundle": bundle, "wcow": isWCOW, - }).Debug("newHcsExec") + }).Trace("newHcsExec") he := &hcsExec{ events: events, diff --git a/internal/gcs/bridge.go b/internal/gcs/bridge.go index 6f8a6b0558..0aa9d54536 100644 --- a/internal/gcs/bridge.go +++ b/internal/gcs/bridge.go @@ -16,9 +16,11 @@ import ( "time" "github.com/sirupsen/logrus" + "go.opencensus.io/trace" "golang.org/x/sys/windows" "github.com/Microsoft/hcsshim/internal/log" + "github.com/Microsoft/hcsshim/internal/oc" ) const ( @@ -258,6 +260,9 @@ func (brdg *bridge) recvLoopRoutine() { } func readMessage(r io.Reader) (int64, msgType, []byte, error) { + _, span := oc.StartSpan(context.Background(), "bridge receive read message", oc.WithClientSpanKind) + defer span.End() + var h [hdrSize]byte _, err := io.ReadFull(r, h[:]) if err != nil { @@ -266,6 +271,10 @@ func readMessage(r io.Reader) (int64, msgType, []byte, error) { typ := msgType(binary.LittleEndian.Uint32(h[hdrOffType:])) n := binary.LittleEndian.Uint32(h[hdrOffSize:]) id := int64(binary.LittleEndian.Uint64(h[hdrOffID:])) + span.AddAttributes( + trace.StringAttribute("type", typ.String()), + trace.Int64Attribute("message-id", id)) + if n < hdrSize || n > maxMsgSize { return 0, 0, nil, fmt.Errorf("invalid message size %d", n) } @@ -298,7 +307,8 @@ func (brdg *bridge) recvLoop() error { brdg.log.WithFields(logrus.Fields{ "payload": string(b), "type": typ.String(), - "message-id": id}).Debug("bridge receive") + "message-id": id}).Trace("bridge receive") + switch typ & msgTypeMask { case msgTypeResponse: // Find the request associated with this response. @@ -372,19 +382,27 @@ func (brdg *bridge) sendLoop() { } func (brdg *bridge) writeMessage(buf *bytes.Buffer, enc *json.Encoder, typ msgType, id int64, req interface{}) error { + var err error + _, span := oc.StartSpan(context.Background(), "bridge send", oc.WithClientSpanKind) + defer span.End() + defer func() { oc.SetSpanStatus(span, err) }() + span.AddAttributes( + trace.StringAttribute("type", typ.String()), + trace.Int64Attribute("message-id", id)) + // Prepare the buffer with the message. var h [hdrSize]byte binary.LittleEndian.PutUint32(h[hdrOffType:], uint32(typ)) binary.LittleEndian.PutUint64(h[hdrOffID:], uint64(id)) buf.Write(h[:]) - err := enc.Encode(req) + err = enc.Encode(req) if err != nil { return fmt.Errorf("bridge encode: %w", err) } // Update the message header with the size. binary.LittleEndian.PutUint32(buf.Bytes()[hdrOffSize:], uint32(buf.Len())) - if brdg.log.Logger.GetLevel() >= logrus.DebugLevel { + if brdg.log.Logger.GetLevel() > logrus.DebugLevel { b := buf.Bytes()[hdrSize:] switch typ { // container environment vars are in rpCreate for linux; rpcExecuteProcess for windows @@ -399,7 +417,7 @@ func (brdg *bridge) writeMessage(buf *bytes.Buffer, enc *json.Encoder, typ msgTy brdg.log.WithFields(logrus.Fields{ "payload": string(b), "type": typ.String(), - "message-id": id}).Debug("bridge send") + "message-id": id}).Trace("bridge send") } // Write the message. diff --git a/internal/guest/bridge/bridge.go b/internal/guest/bridge/bridge.go index f17cb2ce4d..d56eb51760 100644 --- a/internal/guest/bridge/bridge.go +++ b/internal/guest/bridge/bridge.go @@ -310,7 +310,7 @@ func (b *Bridge) ListenAndServe(bridgeIn io.ReadCloser, bridgeOut io.WriteCloser trace.StringAttribute("cid", base.ContainerID)) entry := log.G(ctx) - if entry.Logger.GetLevel() >= logrus.DebugLevel { + if entry.Logger.GetLevel() > logrus.DebugLevel { s := string(message) switch header.Type { case prot.ComputeSystemCreateV1: @@ -320,7 +320,7 @@ func (b *Bridge) ListenAndServe(bridgeIn io.ReadCloser, bridgeOut io.WriteCloser entry.WithError(err).Warning("could not scrub bridge payload") } } - entry.WithField("message", s).Debug("request read message") + entry.WithField("message", s).Trace("request read message") } requestChan <- &Request{ Context: ctx, @@ -384,7 +384,8 @@ func (b *Bridge) ListenAndServe(bridgeIn io.ReadCloser, bridgeOut io.WriteCloser s := trace.FromContext(resp.ctx) if s != nil { - log.G(resp.ctx).WithField("message", string(responseBytes)).Debug("request write response") + log.G(resp.ctx).WithField("message", string(responseBytes)).Trace("request write response") + s.AddAttributes(trace.StringAttribute("response-message-type", resp.header.Type.String())) s.End() } }