Add spans and drop large size high volume trace logs

Signed-off-by: Kirtana Ashok <kiashok@microsoft.com>
(cherry picked from commit c91d82d)
Signed-off-by: Kirtana Ashok <kiashok@microsoft.com>

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,

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.

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()
 			}
 		}