runtime: change un-structured log to structured log

Change some logger from directly calling logrus to use a
logrus instance to use structured log.

Fixes: #458

Signed-off-by: bin liu <bin@hyper.sh>

src/runtime/containerd-shim-v2/create.go

@@ -19,7 +19,6 @@ import (
 	"github.com/containerd/typeurl"
 	"github.com/opencontainers/runtime-spec/specs-go"
 	"github.com/pkg/errors"
-	"github.com/sirupsen/logrus"
 
 	// only register the proto type
 	_ "github.com/containerd/containerd/runtime/linux/runctypes"
@@ -72,7 +71,7 @@ func create(ctx context.Context, s *service, r *taskAPI.CreateTaskRequest) (*con
 		defer func() {
 			if err != nil && rootFs.Mounted {
 				if err2 := mount.UnmountAll(rootfs, 0); err2 != nil {
-					logrus.WithError(err2).Warn("failed to cleanup rootfs mount")
+					shimLog.WithField("container-type", containerType).WithError(err2).Warn("failed to cleanup rootfs mount")
 				}
 			}
 		}()
@@ -102,7 +101,7 @@ func create(ctx context.Context, s *service, r *taskAPI.CreateTaskRequest) (*con
 		defer func() {
 			if err != nil && rootFs.Mounted {
 				if err2 := mount.UnmountAll(rootfs, 0); err2 != nil {
-					logrus.WithError(err2).Warn("failed to cleanup rootfs mount")
+					shimLog.WithField("container-type", containerType).WithError(err2).Warn("failed to cleanup rootfs mount")
 				}
 			}
 		}()

src/runtime/containerd-shim-v2/delete.go

@@ -12,8 +12,6 @@ import (
 	"github.com/containerd/containerd/mount"
 	"github.com/kata-containers/kata-containers/src/runtime/pkg/katautils"
 	"github.com/kata-containers/kata-containers/src/runtime/virtcontainers/types"
-
-	"github.com/sirupsen/logrus"
 )
 
 func deleteContainer(ctx context.Context, s *service, c *container) error {
@@ -42,7 +40,7 @@ func deleteContainer(ctx context.Context, s *service, c *container) error {
 	if c.mounted {
 		rootfs := path.Join(c.bundle, "rootfs")
 		if err := mount.UnmountAll(rootfs, 0); err != nil {
-			logrus.WithError(err).Warn("failed to cleanup rootfs mount")
+			shimLog.WithError(err).Warn("failed to cleanup rootfs mount")
 		}
 	}
 

src/runtime/containerd-shim-v2/service.go

@@ -58,9 +58,15 @@ var (
 // concrete virtcontainer implementation
 var vci vc.VC = &vc.VCImpl{}
 
+// shimLog is logger for shim package
+var shimLog = logrus.WithField("source", "containerd-kata-shim-v2")
+
 // New returns a new shim service that can be used via GRPC
 func New(ctx context.Context, id string, publisher events.Publisher) (cdshim.Shim, error) {
-	logger := logrus.WithField("ID", id)
+	shimLog = shimLog.WithFields(logrus.Fields{
+		"sandbox": id,
+		"pid":     os.Getpid(),
+	})
 	// Discard the log before shim init its log output. Otherwise
 	// it will output into stdio, from which containerd would like
 	// to get the shim's socket address.
@@ -69,8 +75,8 @@ func New(ctx context.Context, id string, publisher events.Publisher) (cdshim.Shi
 	if !opts.Debug {
 		logrus.SetLevel(logrus.WarnLevel)
 	}
-	vci.SetLogger(ctx, logger)
+	vci.SetLogger(ctx, shimLog)
-	katautils.SetLogger(ctx, logger, logger.Logger.Level)
+	katautils.SetLogger(ctx, shimLog, shimLog.Logger.Level)
 
 	ctx, cancel := context.WithCancel(ctx)
 
@@ -226,7 +232,7 @@ func (s *service) forward(publisher events.Publisher) {
 		err := publisher.Publish(ctx, getTopic(e), e)
 		cancel()
 		if err != nil {
-			logrus.WithError(err).Error("post event")
+			shimLog.WithError(err).Error("post event")
 		}
 	}
 }
@@ -269,7 +275,7 @@ func getTopic(e interface{}) string {
 	case *eventstypes.TaskCheckpointed:
 		return cdruntime.TaskCheckpointedEventTopic
 	default:
-		logrus.Warnf("no topic for type %#v", e)
+		shimLog.WithField("event-type", e).Warn("no topic for event type")
 	}
 	return cdruntime.TaskUnknownTopic
 }
@@ -684,7 +690,7 @@ func (s *service) Kill(ctx context.Context, r *taskAPI.KillRequest) (_ *ptypes.E
 	// and return directly.
 	if signum == syscall.SIGKILL || signum == syscall.SIGTERM {
 		if c.status == task.StatusStopped {
-			logrus.WithField("sandbox", s.sandbox.ID()).WithField("Container", c.id).Debug("Container has already been stopped")
+			shimLog.WithField("sandbox", s.sandbox.ID()).WithField("container", c.id).Debug("Container has already been stopped")
 			return empty, nil
 		}
 	}
@@ -697,10 +703,10 @@ func (s *service) Kill(ctx context.Context, r *taskAPI.KillRequest) (_ *ptypes.E
 		}
 		processID = execs.id
 		if processID == "" {
-			logrus.WithFields(logrus.Fields{
+			shimLog.WithFields(logrus.Fields{
 				"sandbox":   s.sandbox.ID(),
-				"Container": c.id,
+				"container": c.id,
-				"ExecID":    r.ExecID,
+				"exec-id":   r.ExecID,
 			}).Debug("Id of exec process to be signalled is empty")
 			return empty, errors.New("The exec process does not exist")
 		}

src/runtime/containerd-shim-v2/shim_management.go

@@ -24,8 +24,6 @@ import (
 	dto "github.com/prometheus/client_model/go"
 	"github.com/prometheus/common/expfmt"
 
-	"github.com/sirupsen/logrus"
-
 	"google.golang.org/grpc/codes"
 
 	mutils "github.com/kata-containers/kata-containers/src/runtime/pkg/utils"
@@ -33,6 +31,7 @@ import (
 
 var (
 	ifSupportAgentMetricsAPI = true
+	shimMgtLog               = shimLog.WithField("subsystem", "shim-management")
 )
 
 // serveMetrics handle /metrics requests
@@ -65,9 +64,9 @@ func (s *service) serveMetrics(w http.ResponseWriter, r *http.Request) {
 	// get metrics from agent
 	agentMetrics, err := s.sandbox.GetAgentMetrics()
 	if err != nil {
-		logrus.WithError(err).Error("failed GetAgentMetrics")
+		shimMgtLog.WithError(err).Error("failed GetAgentMetrics")
 		if isGRPCErrorCode(codes.NotFound, err) {
-			logrus.Warn("metrics API not supportted by this agent.")
+			shimMgtLog.Warn("metrics API not supportted by this agent.")
 			ifSupportAgentMetricsAPI = false
 			return
 		}
@@ -119,23 +118,23 @@ func (s *service) startManagementServer(ctx context.Context, ociSpec *specs.Spec
 	// metrics socket will under sandbox's bundle path
 	metricsAddress, err := socketAddress(ctx, s.id)
 	if err != nil {
-		logrus.Errorf("failed to create socket address: %s", err.Error())
+		shimMgtLog.WithError(err).Error("failed to create socket address")
 		return
 	}
 
 	listener, err := cdshim.NewSocket(metricsAddress)
 	if err != nil {
-		logrus.Errorf("failed to create listener: %s", err.Error())
+		shimMgtLog.WithError(err).Error("failed to create listener")
 		return
 	}
 
 	// write metrics address to filesystem
 	if err := cdshim.WriteAddress("monitor_address", metricsAddress); err != nil {
-		logrus.Errorf("failed to write metrics address: %s", err.Error())
+		shimMgtLog.WithError(err).Errorf("failed to write metrics address")
 		return
 	}
 
-	logrus.Info("kata monitor inited")
+	shimMgtLog.Info("kata management inited")
 
 	// bind hanlder
 	m := http.NewServeMux()

src/runtime/containerd-shim-v2/utils.go

@@ -19,7 +19,6 @@ import (
 	vc "github.com/kata-containers/kata-containers/src/runtime/virtcontainers"
 	"github.com/kata-containers/kata-containers/src/runtime/virtcontainers/pkg/compatoci"
 	"github.com/kata-containers/kata-containers/src/runtime/virtcontainers/pkg/oci"
-	"github.com/sirupsen/logrus"
 )
 
 func cReap(s *service, status int, id, execid string, exitat time.Time) {
@@ -33,18 +32,18 @@ func cReap(s *service, status int, id, execid string, exitat time.Time) {
 }
 
 func cleanupContainer(ctx context.Context, sid, cid, bundlePath string) error {
-	logrus.WithField("Service", "Cleanup").WithField("container", cid).Info("Cleanup container")
+	shimLog.WithField("service", "cleanup").WithField("container", cid).Info("Cleanup container")
 
 	err := vci.CleanupContainer(ctx, sid, cid, true)
 	if err != nil {
-		logrus.WithError(err).WithField("container", cid).Warn("failed to cleanup container")
+		shimLog.WithError(err).WithField("container", cid).Warn("failed to cleanup container")
 		return err
 	}
 
 	rootfs := filepath.Join(bundlePath, "rootfs")
 
 	if err := mount.UnmountAll(rootfs, 0); err != nil {
-		logrus.WithError(err).WithField("container", cid).Warn("failed to cleanup container rootfs")
+		shimLog.WithError(err).WithField("container", cid).Warn("failed to cleanup container rootfs")
 		return err
 	}
 

src/runtime/containerd-shim-v2/wait.go

@@ -40,7 +40,7 @@ func wait(s *service, c *container, execID string) (int32, error) {
 
 	ret, err := s.sandbox.WaitProcess(c.id, processID)
 	if err != nil {
-		logrus.WithError(err).WithFields(logrus.Fields{
+		shimLog.WithError(err).WithFields(logrus.Fields{
 			"container": c.id,
 			"pid":       processID,
 		}).Error("Wait for process failed")
@@ -61,15 +61,15 @@ func wait(s *service, c *container, execID string) (int32, error) {
 				s.monitor <- nil
 			}
 			if err = s.sandbox.Stop(true); err != nil {
-				logrus.WithField("sandbox", s.sandbox.ID()).Error("failed to stop sandbox")
+				shimLog.WithField("sandbox", s.sandbox.ID()).Error("failed to stop sandbox")
 			}
 
 			if err = s.sandbox.Delete(); err != nil {
-				logrus.WithField("sandbox", s.sandbox.ID()).Error("failed to delete sandbox")
+				shimLog.WithField("sandbox", s.sandbox.ID()).Error("failed to delete sandbox")
 			}
 		} else {
 			if _, err = s.sandbox.StopContainer(c.id, false); err != nil {
-				logrus.WithError(err).WithField("container", c.id).Warn("stop container failed")
+				shimLog.WithError(err).WithField("container", c.id).Warn("stop container failed")
 			}
 		}
 		c.status = task.StatusStopped
@@ -105,14 +105,14 @@ func watchSandbox(s *service) {
 	s.mu.Lock()
 	defer s.mu.Unlock()
 	// sandbox malfunctioning, cleanup as much as we can
-	logrus.WithError(err).Warn("sandbox stopped unexpectedly")
+	shimLog.WithError(err).Warn("sandbox stopped unexpectedly")
 	err = s.sandbox.Stop(true)
 	if err != nil {
-		logrus.WithError(err).Warn("stop sandbox failed")
+		shimLog.WithError(err).Warn("stop sandbox failed")
 	}
 	err = s.sandbox.Delete()
 	if err != nil {
-		logrus.WithError(err).Warn("delete sandbox failed")
+		shimLog.WithError(err).Warn("delete sandbox failed")
 	}
 
 	for _, c := range s.containers {
@@ -120,9 +120,9 @@ func watchSandbox(s *service) {
 			continue
 		}
 		rootfs := path.Join(c.bundle, "rootfs")
-		logrus.WithField("rootfs", rootfs).WithField("id", c.id).Debug("container umount rootfs")
+		shimLog.WithField("rootfs", rootfs).WithField("container", c.id).Debug("container umount rootfs")
 		if err := mount.UnmountAll(rootfs, 0); err != nil {
-			logrus.WithError(err).Warn("failed to cleanup rootfs mount")
+			shimLog.WithError(err).Warn("failed to cleanup rootfs mount")
 		}
 	}
 
@@ -142,7 +142,7 @@ func watchOOMEvents(ctx context.Context, s *service) {
 		default:
 			containerID, err := s.sandbox.GetOOMEvent()
 			if err != nil {
-				logrus.WithField("sandbox", s.sandbox.ID()).WithError(err).Warn("failed to get OOM event from sandbox")
+				shimLog.WithError(err).Warn("failed to get OOM event from sandbox")
 				// If the GetOOMEvent call is not implemented, then the agent is most likely an older version,
 				// stop attempting to get OOM events.
 				// for rust agent, the response code is not found

src/runtime/virtcontainers/mount.go

@@ -30,6 +30,10 @@ var rootfsDir = "rootfs"
 
 var systemMountPrefixes = []string{"/proc", "/sys"}
 
+func mountLogger() *logrus.Entry {
+	return virtLog.WithField("subsystem", "mount")
+}
+
 var propagationTypes = map[string]uintptr{
 	"shared":  syscall.MS_SHARED,
 	"private": syscall.MS_PRIVATE,
@@ -321,17 +325,17 @@ func bindUnmountContainerRootfs(ctx context.Context, sharedDir, cID string) erro
 
 	rootfsDest := filepath.Join(sharedDir, cID, rootfsDir)
 	if isSymlink(filepath.Join(sharedDir, cID)) || isSymlink(rootfsDest) {
-		logrus.Warnf("container dir %s is a symlink, malicious guest?", cID)
+		mountLogger().WithField("container", cID).Warnf("container dir is a symlink, malicious guest?")
 		return nil
 	}
 
 	err := syscall.Unmount(rootfsDest, syscall.MNT_DETACH|UmountNoFollow)
 	if err == syscall.ENOENT {
-		logrus.Warnf("%s: %s", err, rootfsDest)
+		mountLogger().WithError(err).WithField("rootfs-dir", rootfsDest).Warn()
 		return nil
 	}
 	if err := syscall.Rmdir(rootfsDest); err != nil {
-		logrus.WithError(err).WithField("rootfs-dir", rootfsDest).Warn("Could not remove container rootfs dir")
+		mountLogger().WithError(err).WithField("rootfs-dir", rootfsDest).Warn("Could not remove container rootfs dir")
 	}
 
 	return err
@@ -344,7 +348,7 @@ func bindUnmountAllRootfs(ctx context.Context, sharedDir string, sandbox *Sandbo
 	var errors *merr.Error
 	for _, c := range sandbox.containers {
 		if isSymlink(filepath.Join(sharedDir, c.id)) {
-			logrus.Warnf("container dir %s is a symlink, malicious guest?", c.id)
+			mountLogger().WithField("container", c.id).Warnf("container dir is a symlink, malicious guest?")
 			continue
 		}
 		c.unmountHostMounts()