Merge pull request #528 from jodh-intel/fix-log-fields

Ensure containerID and sandboxID fields logged as early as possible

cli/delete.go

@@ -53,12 +53,17 @@ EXAMPLE:
 }
 
 func delete(containerID string, force bool) error {
+	kataLog = kataLog.WithField("container", containerID)
+	setExternalLoggers(kataLog)
+
 	// Checks the MUST and MUST NOT from OCI runtime specification
 	status, sandboxID, err := getExistingContainerInfo(containerID)
 	if err != nil {
 		return err
 	}
 
+	containerID = status.ID
+
 	kataLog = kataLog.WithFields(logrus.Fields{
 		"container": containerID,
 		"sandbox":   sandboxID,
@@ -66,8 +71,6 @@ func delete(containerID string, force bool) error {
 
 	setExternalLoggers(kataLog)
 
-	containerID = status.ID
-
 	containerType, err := oci.GetContainerType(status.Annotations)
 	if err != nil {
 		return err

cli/events.go

@@ -141,6 +141,9 @@ information is displayed once every 5 seconds.`,
 			return fmt.Errorf("container id cannot be empty")
 		}
 
+		kataLog = kataLog.WithField("container", containerID)
+		setExternalLoggers(kataLog)
+
 		duration := context.Duration("interval")
 		if duration <= 0 {
 			return fmt.Errorf("duration interval must be greater than 0")
@@ -151,6 +154,8 @@ information is displayed once every 5 seconds.`,
 			return err
 		}
 
+		containerID = status.ID
+
 		kataLog = kataLog.WithFields(logrus.Fields{
 			"container": containerID,
 			"sandbox":   sandboxID,

cli/exec.go

@@ -16,7 +16,6 @@ import (
 	vc "github.com/kata-containers/runtime/virtcontainers"
 	"github.com/kata-containers/runtime/virtcontainers/pkg/oci"
 	specs "github.com/opencontainers/runtime-spec/specs-go"
-	"github.com/sirupsen/logrus"
 	"github.com/urfave/cli"
 )
 
@@ -184,16 +183,16 @@ func generateExecParams(context *cli.Context, specProcess *oci.CompatOCIProcess)
 
 func execute(context *cli.Context) error {
 	containerID := context.Args().First()
+
+	kataLog = kataLog.WithField("container", containerID)
+	setExternalLoggers(kataLog)
+
 	status, sandboxID, err := getExistingContainerInfo(containerID)
 	if err != nil {
 		return err
 	}
 
-	kataLog = kataLog.WithFields(logrus.Fields{
-		"container": containerID,
-		"sandbox":   sandboxID,
-	})
-
+	kataLog = kataLog.WithField("sandbox", sandboxID)
 	setExternalLoggers(kataLog)
 
 	// Retrieve OCI spec configuration.
@@ -208,6 +207,10 @@ func execute(context *cli.Context) error {
 	}
 
 	params.cID = status.ID
+	containerID = params.cID
+
+	kataLog = kataLog.WithField("container", containerID)
+	setExternalLoggers(kataLog)
 
 	// container MUST be ready or running.
 	if status.State.State != vc.StateReady &&

cli/kill.go

@@ -91,8 +91,12 @@ var signals = map[string]syscall.Signal{
 }
 
 func kill(containerID, signal string, all bool) error {
+	kataLog = kataLog.WithField("container", containerID)
+	setExternalLoggers(kataLog)
+
 	// Checks the MUST and MUST NOT from OCI runtime specification
 	status, sandboxID, err := getExistingContainerInfo(containerID)
+
 	if err != nil {
 		return err
 	}

cli/pause.go

@@ -42,6 +42,9 @@ Where "<container-id>" is the container name to be resumed.`,
 }
 
 func toggleContainerPause(containerID string, pause bool) (err error) {
+	kataLog = kataLog.WithField("container", containerID)
+	setExternalLoggers(kataLog)
+
 	// Checks the MUST and MUST NOT from OCI runtime specification
 	status, sandboxID, err := getExistingContainerInfo(containerID)
 	if err != nil {

cli/ps.go

@@ -48,6 +48,9 @@ func ps(containerID, format string, args []string) error {
 		return fmt.Errorf("Missing container ID")
 	}
 
+	kataLog = kataLog.WithField("container", containerID)
+	setExternalLoggers(kataLog)
+
 	// Checks the MUST and MUST NOT from OCI runtime specification
 	status, sandboxID, err := getExistingContainerInfo(containerID)
 	if err != nil {

cli/start.go

@@ -41,12 +41,17 @@ var startCLICommand = cli.Command{
 }
 
 func start(containerID string) (vc.VCSandbox, error) {
+	kataLog = kataLog.WithField("container", containerID)
+	setExternalLoggers(kataLog)
+
 	// Checks the MUST and MUST NOT from OCI runtime specification
 	status, sandboxID, err := getExistingContainerInfo(containerID)
 	if err != nil {
 		return nil, err
 	}
 
+	containerID = status.ID
+
 	kataLog = kataLog.WithFields(logrus.Fields{
 		"container": containerID,
 		"sandbox":   sandboxID,
@@ -54,8 +59,6 @@ func start(containerID string) (vc.VCSandbox, error) {
 
 	setExternalLoggers(kataLog)
 
-	containerID = status.ID
-
 	containerType, err := oci.GetContainerType(status.Annotations)
 	if err != nil {
 		return nil, err

cli/update.go

@@ -132,6 +132,10 @@ other options are ignored.
 		}
 
 		containerID := context.Args().First()
+
+		kataLog = kataLog.WithField("container", containerID)
+		setExternalLoggers(kataLog)
+
 		status, sandboxID, err := getExistingContainerInfo(containerID)
 		if err != nil {
 			return err
@@ -144,6 +148,8 @@ other options are ignored.
 			"sandbox":   sandboxID,
 		})
 
+		setExternalLoggers(kataLog)
+
 		// container MUST be running
 		if status.State.State != vc.StateRunning {
 			return fmt.Errorf("Container %s is not running", containerID)

virtcontainers/api.go

@@ -19,16 +19,13 @@ func init() {
 	runtime.LockOSThread()
 }
 
-var virtLog = logrus.FieldLogger(logrus.New())
+var virtLog = logrus.WithField("source", "virtcontainers")
 
 // SetLogger sets the logger for virtcontainers package.
-func SetLogger(logger logrus.FieldLogger) {
-	fields := logrus.Fields{
-		"source": "virtcontainers",
-		"arch":   runtime.GOARCH,
-	}
-
+func SetLogger(logger *logrus.Entry) {
+	fields := virtLog.Data
 	virtLog = logger.WithFields(fields)
+
 	deviceApi.SetLogger(virtLog)
 }
 

virtcontainers/container.go

@@ -264,9 +264,8 @@ func (c *Container) ID() string {
 // Logger returns a logrus logger appropriate for logging Container messages
 func (c *Container) Logger() *logrus.Entry {
 	return virtLog.WithFields(logrus.Fields{
-		"subsystem":    "container",
-		"container-id": c.id,
-		"sandbox-id":   c.sandboxID,
+		"subsystem": "container",
+		"sandbox":   c.sandboxID,
 	})
 }
 

virtcontainers/device/api/interface.go

@@ -12,16 +12,17 @@ import (
 	"github.com/kata-containers/runtime/virtcontainers/device/config"
 )
 
-var devLogger = logrus.FieldLogger(logrus.New())
+var devLogger = logrus.WithField("subsystem", "device")
 
 // SetLogger sets the logger for device api package.
-func SetLogger(logger logrus.FieldLogger) {
-	devLogger = logger
+func SetLogger(logger *logrus.Entry) {
+	fields := devLogger.Data
+	devLogger = logger.WithFields(fields)
 }
 
 // DeviceLogger returns logger for device management
 func DeviceLogger() *logrus.Entry {
-	return devLogger.WithField("subsystem", "device")
+	return devLogger
 }
 
 // DeviceReceiver is an interface used for accepting devices

virtcontainers/hack/virtc/main.go

@@ -19,7 +19,7 @@ import (
 	vc "github.com/kata-containers/runtime/virtcontainers"
 )
 
-var virtcLog = logrus.New()
+var virtcLog *logrus.Entry
 
 var listFormat = "%s\t%s\t%s\t%s\n"
 var statusFormat = "%s\t%s\n"
@@ -915,14 +915,14 @@ func main() {
 			if err != nil {
 				return err
 			}
-			virtcLog.Out = f
+			virtcLog.Logger.Out = f
 		}
 
 		switch context.GlobalString("log-format") {
 		case "text":
 			// retain logrus's default.
 		case "json":
-			virtcLog.Formatter = new(logrus.JSONFormatter)
+			virtcLog.Logger.Formatter = new(logrus.JSONFormatter)
 		default:
 			return fmt.Errorf("unknown log-format %q", context.GlobalString("log-format"))
 		}

virtcontainers/implementation.go

@@ -22,7 +22,7 @@ type VCImpl struct {
 }
 
 // SetLogger implements the VC function of the same name.
-func (impl *VCImpl) SetLogger(logger logrus.FieldLogger) {
+func (impl *VCImpl) SetLogger(logger *logrus.Entry) {
 	SetLogger(logger)
 }
 

virtcontainers/interfaces.go

@@ -15,7 +15,7 @@ import (
 
 // VC is the Virtcontainers interface
 type VC interface {
-	SetLogger(logger logrus.FieldLogger)
+	SetLogger(logger *logrus.Entry)
 	SetFactory(Factory)
 
 	CreateSandbox(sandboxConfig SandboxConfig) (VCSandbox, error)

virtcontainers/kata_agent.go

@@ -469,7 +469,7 @@ func (k *kataAgent) startProxy(sandbox *Sandbox) error {
 
 	proxyParams := proxyParams{
 		agentURL: agentURL,
-		logger:   k.Logger().WithField("sandbox-id", sandbox.id),
+		logger:   k.Logger().WithField("sandbox", sandbox.id),
 	}
 
 	// Start the proxy here
@@ -494,9 +494,9 @@ func (k *kataAgent) startProxy(sandbox *Sandbox) error {
 	}
 
 	k.Logger().WithFields(logrus.Fields{
-		"sandbox-id": sandbox.id,
-		"proxy-pid":  pid,
-		"proxy-url":  uri,
+		"sandbox":   sandbox.id,
+		"proxy-pid": pid,
+		"proxy-url": uri,
 	}).Info("proxy started")
 
 	return nil

virtcontainers/network.go

@@ -219,9 +219,10 @@ func networkLogger() *logrus.Entry {
 // Attach for virtual endpoint bridges the network pair and adds the
 // tap interface of the network pair to the hypervisor.
 func (endpoint *VirtualEndpoint) Attach(h hypervisor) error {
-	networkLogger().Info("Attaching virtual endpoint")
+	networkLogger().WithField("endpoint-type", "virtual").Info("Attaching endpoint")
+
 	if err := xconnectVMNetwork(&(endpoint.NetPair), true); err != nil {
-		networkLogger().WithError(err).Error("Error bridging virtual ep")
+		networkLogger().WithError(err).Error("Error bridging virtual endpoint")
 		return err
 	}
 
@@ -237,7 +238,7 @@ func (endpoint *VirtualEndpoint) Detach(netNsCreated bool, netNsPath string) err
 		return nil
 	}
 
-	networkLogger().Info("Detaching virtual endpoint")
+	networkLogger().WithField("endpoint-type", "virtual").Info("Detaching endpoint")
 
 	return doNetNS(netNsPath, func(_ ns.NetNS) error {
 		return xconnectVMNetwork(&(endpoint.NetPair), false)
@@ -271,7 +272,7 @@ func (endpoint *VhostUserEndpoint) SetProperties(properties NetworkInfo) {
 
 // Attach for vhostuser endpoint
 func (endpoint *VhostUserEndpoint) Attach(h hypervisor) error {
-	networkLogger().Info("Attaching vhostuser based endpoint")
+	networkLogger().WithField("endpoint-type", "vhostuser").Info("Attaching endpoint")
 
 	// Generate a unique ID to be used for hypervisor commandline fields
 	randBytes, err := utils.GenerateRandomBytes(8)
@@ -291,7 +292,7 @@ func (endpoint *VhostUserEndpoint) Attach(h hypervisor) error {
 
 // Detach for vhostuser endpoint
 func (endpoint *VhostUserEndpoint) Detach(netNsCreated bool, netNsPath string) error {
-	networkLogger().Info("Detaching vhostuser based endpoint")
+	networkLogger().WithField("endpoint-type", "vhostuser").Info("Detaching endpoint")
 	return nil
 }
 
@@ -335,7 +336,7 @@ func (endpoint *PhysicalEndpoint) SetProperties(properties NetworkInfo) {
 // Attach for physical endpoint binds the physical network interface to
 // vfio-pci and adds device to the hypervisor with vfio-passthrough.
 func (endpoint *PhysicalEndpoint) Attach(h hypervisor) error {
-	networkLogger().Info("Attaching physical endpoint")
+	networkLogger().WithField("endpoint-type", "physical").Info("Attaching endpoint")
 
 	// Unbind physical interface from host driver and bind to vfio
 	// so that it can be passed to qemu.
@@ -356,7 +357,7 @@ func (endpoint *PhysicalEndpoint) Detach(netNsCreated bool, netNsPath string) er
 	// Bind back the physical network interface to host.
 	// We need to do this even if a new network namespace has not
 	// been created by virtcontainers.
-	networkLogger().Info("Detaching physical endpoint")
+	networkLogger().WithField("endpoint-type", "physical").Info("Detaching endpoint")
 
 	// We do not need to enter the network namespace to bind back the
 	// physical interface to host driver.
@@ -489,7 +490,10 @@ func (n *NetworkNamespace) UnmarshalJSON(b []byte) error {
 			}
 
 			endpoints = append(endpoints, &endpoint)
-			virtLog.Infof("Physical endpoint unmarshalled [%v]", endpoint)
+			networkLogger().WithFields(logrus.Fields{
+				"endpoint":      endpoint,
+				"endpoint-type": "physical",
+			}).Info("endpoint unmarshalled")
 
 		case VirtualEndpointType:
 			var endpoint VirtualEndpoint
@@ -499,7 +503,10 @@ func (n *NetworkNamespace) UnmarshalJSON(b []byte) error {
 			}
 
 			endpoints = append(endpoints, &endpoint)
-			virtLog.Infof("Virtual endpoint unmarshalled [%v]", endpoint)
+			networkLogger().WithFields(logrus.Fields{
+				"endpoint":      endpoint,
+				"endpoint-type": "virtual",
+			}).Info("endpoint unmarshalled")
 
 		case VhostUserEndpointType:
 			var endpoint VhostUserEndpoint
@@ -509,10 +516,13 @@ func (n *NetworkNamespace) UnmarshalJSON(b []byte) error {
 			}
 
 			endpoints = append(endpoints, &endpoint)
-			virtLog.Infof("VhostUser endpoint unmarshalled [%v]", endpoint)
+			networkLogger().WithFields(logrus.Fields{
+				"endpoint":      endpoint,
+				"endpoint-type": "vhostuser",
+			}).Info("endpoint unmarshalled")
 
 		default:
-			virtLog.Errorf("Unknown endpoint type received %s\n", e.Type)
+			networkLogger().WithField("endpoint-type", e.Type).Error("Ignoring unknown endpoint type")
 		}
 	}
 
@@ -1010,7 +1020,7 @@ func untapNetworkPair(netPair NetworkInterfacePair) error {
 	vethLink, err := getLinkByName(netHandle, netPair.VirtIface.Name, &netlink.Veth{})
 	if err != nil {
 		// The veth pair is not totally managed by virtcontainers
-		virtLog.Warnf("Could not get veth interface %s: %s", netPair.VirtIface.Name, err)
+		networkLogger().WithError(err).WithField("veth-name", netPair.VirtIface.Name).Warn("Could not get veth interface")
 	} else {
 		if err := netHandle.LinkSetDown(vethLink); err != nil {
 			return fmt.Errorf("Could not disable veth %s: %s", netPair.VirtIface.Name, err)
@@ -1062,7 +1072,7 @@ func unBridgeNetworkPair(netPair NetworkInterfacePair) error {
 	vethLink, err := getLinkByName(netHandle, netPair.VirtIface.Name, &netlink.Veth{})
 	if err != nil {
 		// The veth pair is not totally managed by virtcontainers
-		virtLog.WithError(err).Warn("Could not get veth interface")
+		networkLogger().WithError(err).Warn("Could not get veth interface")
 	} else {
 		if err := netHandle.LinkSetDown(vethLink); err != nil {
 			return fmt.Errorf("Could not disable veth %s: %s", netPair.VirtIface.Name, err)

virtcontainers/pkg/hyperstart/hyperstart.go

@@ -124,7 +124,10 @@ var hyperLog = logrus.FieldLogger(logrus.New())
 
 // SetLogger sets the logger for hyperstart package.
 func SetLogger(logger logrus.FieldLogger) {
-	hyperLog = logger.WithField("source", "virtcontainers/hyperstart")
+	hyperLog = logger.WithFields(logrus.Fields{
+		"source":    "virtcontainers",
+		"subsystem": "hyperstart",
+	})
 }
 
 // NewHyperstart returns a new hyperstart structure.

virtcontainers/pkg/oci/utils.go

@@ -128,11 +128,15 @@ func (config *RuntimeConfig) AddKernelParam(p vc.Param) error {
 	return config.HypervisorConfig.AddKernelParam(p)
 }
 
-var ociLog = logrus.FieldLogger(logrus.New())
+var ociLog = logrus.WithFields(logrus.Fields{
+	"source":    "virtcontainers",
+	"subsystem": "oci",
+})
 
 // SetLogger sets the logger for oci package.
-func SetLogger(logger logrus.FieldLogger) {
-	ociLog = logger.WithField("source", "virtcontainers/oci")
+func SetLogger(logger *logrus.Entry) {
+	fields := ociLog.Data
+	ociLog = logger.WithFields(fields)
 }
 
 func cmdEnvs(spec CompatOCISpec, envs []vc.EnvVar) []vc.EnvVar {

virtcontainers/pkg/vcmock/mock.go

@@ -29,7 +29,7 @@ import (
 const mockErrorPrefix = "vcmock forced failure"
 
 // SetLogger implements the VC function of the same name.
-func (m *VCMock) SetLogger(logger logrus.FieldLogger) {
+func (m *VCMock) SetLogger(logger *logrus.Entry) {
 	if m.SetLoggerFunc != nil {
 		m.SetLoggerFunc(logger)
 	}

virtcontainers/pkg/vcmock/mock_test.go

@@ -98,7 +98,7 @@ func TestVCMockSetLogger(t *testing.T) {
 	m := &VCMock{}
 	assert.Nil(m.SetLoggerFunc)
 
-	logger := logrus.New()
+	logger := logrus.NewEntry(logrus.New())
 
 	assert.Equal(loggerTriggered, 0)
 	m.SetLogger(logger)

virtcontainers/sandbox.go

@@ -483,8 +483,8 @@ func (s *Sandbox) ID() string {
 // Logger returns a logrus logger appropriate for logging Sandbox messages
 func (s *Sandbox) Logger() *logrus.Entry {
 	return virtLog.WithFields(logrus.Fields{
-		"subsystem":  "sandbox",
-		"sandbox-id": s.id,
+		"subsystem": "sandbox",
+		"sandbox":   s.id,
 	})
 }
 
@@ -827,7 +827,7 @@ func (s *Sandbox) storeSandbox() error {
 
 // fetchSandbox fetches a sandbox config from a sandbox ID and returns a sandbox.
 func fetchSandbox(sandboxID string) (sandbox *Sandbox, err error) {
-	virtLog.WithField("sandbox-id", sandboxID).Info("fetch sandbox")
+	virtLog.Info("fetch sandbox")
 	if sandboxID == "" {
 		return nil, errNeedSandboxID
 	}

virtcontainers/virtcontainers_test.go

@@ -66,11 +66,11 @@ func TestMain(m *testing.M) {
 
 	flag.Parse()
 
-	logger := logrus.New()
-	logger.Level = logrus.ErrorLevel
+	logger := logrus.NewEntry(logrus.New())
+	logger.Logger.Level = logrus.ErrorLevel
 	for _, arg := range flag.Args() {
 		if arg == "debug-logs" {
-			logger.Level = logrus.DebugLevel
+			logger.Logger.Level = logrus.DebugLevel
 		}
 	}
 	SetLogger(logger)