Changing logging to use logrus.WithFields

cmd/runhcs/container.go

@@ -15,6 +15,7 @@ import (
 	"github.com/Microsoft/hcsshim/internal/guid"
 	"github.com/Microsoft/hcsshim/internal/hcs"
 	"github.com/Microsoft/hcsshim/internal/hcsoci"
+	"github.com/Microsoft/hcsshim/internal/logfields"
 	"github.com/Microsoft/hcsshim/internal/regstate"
 	"github.com/Microsoft/hcsshim/internal/runhcs"
 	"github.com/Microsoft/hcsshim/internal/uvm"
@@ -235,7 +236,11 @@ func parseAnnotationsBool(a map[string]string, key string) *bool {
 		case "false":
 			return &no
 		default:
-			logrus.Warningf("annotation: '%s', with value: '%s', could not be parsed into boolean", key, v)
+			logrus.WithFields(logrus.Fields{
+				logfields.OCIAnnotation: key,
+				logfields.Value:         v,
+				logfields.ExpectedType:  logfields.Bool,
+			}).Warning("annotation could not be parsed")
 		}
 	}
 	return nil
@@ -270,7 +275,12 @@ func parseAnnotationsUint32(a map[string]string, key string) *uint32 {
 			v := uint32(countu)
 			return &v
 		}
-		logrus.Warningf("annotation: '%s', with value: '%s', could not be parsed into uint32: %s", key, v, err)
+		logrus.WithFields(logrus.Fields{
+			logfields.OCIAnnotation: key,
+			logfields.Value:         v,
+			logfields.ExpectedType:  logfields.Uint32,
+			logrus.ErrorKey:         err,
+		}).Warning("annotation could not be parsed")
 	}
 	return nil
 }
@@ -283,7 +293,12 @@ func parseAnnotationsUint64(a map[string]string, key string) *uint64 {
 		if err == nil {
 			return &countu
 		}
-		logrus.Warningf("annotation: '%s', with value: '%s', could not be parsed into uint64: %s", key, v, err)
+		logrus.WithFields(logrus.Fields{
+			logfields.OCIAnnotation: key,
+			logfields.Value:         v,
+			logfields.ExpectedType:  logfields.Uint64,
+			logrus.ErrorKey:         err,
+		}).Warning("annotation could not be parsed")
 	}
 	return nil
 }
@@ -589,7 +604,11 @@ func (c *container) Unmount(all bool) error {
 		err := c.issueVMRequest(op)
 		if err != nil {
 			if _, ok := err.(*noVMError); ok {
-				logrus.Warnf("did not unmount resources for container %s because VM shim for %s could not be contacted", c.ID, c.HostID)
+				logrus.WithFields(logrus.Fields{
+					logfields.ContainerID: c.ID,
+					logfields.UVMID:       c.HostID,
+					logrus.ErrorKey:       errors.New("failed to unmount container resources"),
+				}).Warning("VM shim could not be contacted")
 			} else {
 				return err
 			}
@@ -617,7 +636,10 @@ func createContainerInHost(c *container, vm *uvm.UtilityVM) (err error) {
 	if vm != nil {
 		vmid = vm.ID()
 	}
-	logrus.Infof("creating container %s (VM: '%s')", c.ID, vmid)
+	logrus.WithFields(logrus.Fields{
+		logfields.ContainerID: c.ID,
+		logfields.UVMID:       vmid,
+	}).Info("creating container in UVM")
 	hc, resources, err := hcsoci.CreateContainer(opts)
 	if err != nil {
 		return err

cmd/runhcs/vm.go

@@ -10,6 +10,7 @@ import (
 
 	winio "github.com/Microsoft/go-winio"
 	"github.com/Microsoft/hcsshim/internal/appargs"
+	"github.com/Microsoft/hcsshim/internal/logfields"
 	"github.com/Microsoft/hcsshim/internal/runhcs"
 	"github.com/Microsoft/hcsshim/internal/uvm"
 	"github.com/pkg/errors"
@@ -112,7 +113,8 @@ var vmshimCommand = cli.Command{
 						ioutil.ReadAll(pipe)
 					}
 				} else {
-					logrus.Error("failed creating container in VM: ", err)
+					logrus.WithError(err).
+						Error("failed creating container in VM")
 					fmt.Fprintf(pipe, "%v", err)
 				}
 				pipe.Close()
@@ -140,7 +142,10 @@ func processRequest(vm *uvm.UtilityVM, pipe net.Conn) error {
 	if err != nil {
 		return err
 	}
-	logrus.Debug("received operation ", req.Op, " for ", req.ID)
+	logrus.WithFields(logrus.Fields{
+		logfields.ContainerID:     req.ID,
+		logfields.VMShimOperation: req.Op,
+	}).Debug("process request")
 	c, err := getContainer(req.ID, false)
 	if err != nil {
 		return err

internal/copywithtimeout/copywithtimeout.go

@@ -31,11 +31,11 @@ func init() {
 
 // Copy is a wrapper for io.Copy using a timeout duration
 func Copy(dst io.Writer, src io.Reader, size int64, context string, timeout time.Duration) (int64, error) {
-	log := "to EOF"
-	if size > 0 {
-		log = fmt.Sprintf("%d bytes", size)
-	}
-	logrus.Debugf(fmt.Sprintf("hcsshim::copywithtimeout (%s) %s", context, log))
+	logrus.WithFields(logrus.Fields{
+		"stdval":  context,
+		"size":    size,
+		"timeout": timeout,
+	}).Debug("hcsshim::copywithtimeout - Begin")
 
 	type resultType struct {
 		err   error
@@ -62,7 +62,7 @@ func Copy(dst io.Writer, src io.Reader, size int64, context string, timeout time
 				if size > 0 {
 					bytes := make([]byte, size)
 					if _, err := buf.Read(bytes); err == nil {
-						logrus.Debugf(fmt.Sprintf("hcsshim: copyWithTimeout\n%s", hex.Dump(bytes)))
+						logrus.Debugf("hcsshim::copyWithTimeout - Read bytes\n%s", hex.Dump(bytes))
 					}
 				}
 			}
@@ -85,13 +85,19 @@ func Copy(dst io.Writer, src io.Reader, size int64, context string, timeout time
 					errBrokenPipe = syscall.Errno(109)
 				)
 				if se == errNoData || se == errBrokenPipe {
-					logrus.Debugf("hcsshim::copyWithTimeout: hit NoData or BrokenPipe: %d: %s", se, context)
+					logrus.WithFields(logrus.Fields{
+						"stdval":        context,
+						logrus.ErrorKey: se,
+					}).Debug("hcsshim::copywithtimeout - End")
 					return result.bytes, nil
 				}
 			}
 			return 0, fmt.Errorf("hcsshim::copyWithTimeout: error reading: '%s' after %d bytes (%s)", result.err, result.bytes, context)
 		}
 	}
-	logrus.Debugf("hcsshim::copyWithTimeout: success - copied %d bytes (%s)", result.bytes, context)
+	logrus.WithFields(logrus.Fields{
+		"stdval":       context,
+		"copied-bytes": result.bytes,
+	}).Debug("hcsshim::copywithtimeout - Completed Successfully")
 	return result.bytes, nil
 }

internal/hcs/errors.go

@@ -7,6 +7,7 @@ import (
 	"syscall"
 
 	"github.com/Microsoft/hcsshim/internal/interop"
+	"github.com/Microsoft/hcsshim/internal/logfields"
 	"github.com/sirupsen/logrus"
 )
 
@@ -116,10 +117,14 @@ func (ev *ErrorEvent) String() string {
 func processHcsResult(resultp *uint16) []ErrorEvent {
 	if resultp != nil {
 		resultj := interop.ConvertAndFreeCoTaskMemString(resultp)
-		logrus.Debugf("Result: %s", resultj)
+		logrus.WithField(logfields.JSON, resultj).
+			Debug("HCS Result")
 		result := &hcsResult{}
 		if err := json.Unmarshal([]byte(resultj), result); err != nil {
-			logrus.Warnf("Could not unmarshal HCS result %s: %s", resultj, err)
+			logrus.WithFields(logrus.Fields{
+				logfields.JSON:  resultj,
+				logrus.ErrorKey: err,
+			}).Warning("Could not unmarshal HCS result")
 			return nil
 		}
 		return result.ErrorEvents

internal/hcs/log.go

@@ -0,0 +1,15 @@
+package hcs
+
+import "github.com/sirupsen/logrus"
+
+func logOperationBegin(ctx logrus.Fields, msg string) {
+	logrus.WithFields(ctx).Debug(msg)
+}
+
+func logOperationEnd(ctx logrus.Fields, msg string, err error) {
+	if err == nil {
+		logrus.WithFields(ctx).Debug(msg)
+	} else {
+		logrus.WithFields(ctx).WithError(err).Error(msg)
+	}
+}