From a0be57f64fff7bd49ecd459f4aa1577ad4db7e3d Mon Sep 17 00:00:00 2001 From: "James O. D. Hunt" Date: Thu, 26 Jul 2018 14:14:17 +0100 Subject: [PATCH 1/9] network: Always call network logger function Rather than using the virtcontainers logger, always call the network logger function. Signed-off-by: James O. D. Hunt --- virtcontainers/network.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/virtcontainers/network.go b/virtcontainers/network.go index 15401af655..7adde3c6f9 100644 --- a/virtcontainers/network.go +++ b/virtcontainers/network.go @@ -489,7 +489,7 @@ func (n *NetworkNamespace) UnmarshalJSON(b []byte) error { } endpoints = append(endpoints, &endpoint) - virtLog.Infof("Physical endpoint unmarshalled [%v]", endpoint) + networkLogger().Infof("Physical endpoint unmarshalled [%v]", endpoint) case VirtualEndpointType: var endpoint VirtualEndpoint @@ -499,7 +499,7 @@ func (n *NetworkNamespace) UnmarshalJSON(b []byte) error { } endpoints = append(endpoints, &endpoint) - virtLog.Infof("Virtual endpoint unmarshalled [%v]", endpoint) + networkLogger().Infof("Virtual endpoint unmarshalled [%v]", endpoint) case VhostUserEndpointType: var endpoint VhostUserEndpoint @@ -509,10 +509,10 @@ func (n *NetworkNamespace) UnmarshalJSON(b []byte) error { } endpoints = append(endpoints, &endpoint) - virtLog.Infof("VhostUser endpoint unmarshalled [%v]", endpoint) + networkLogger().Infof("VhostUser endpoint unmarshalled [%v]", endpoint) default: - virtLog.Errorf("Unknown endpoint type received %s\n", e.Type) + networkLogger().Errorf("Unknown endpoint type received %s\n", e.Type) } } @@ -1010,7 +1010,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().Warnf("Could not get veth interface %s: %s", netPair.VirtIface.Name, err) } else { if err := netHandle.LinkSetDown(vethLink); err != nil { return fmt.Errorf("Could not disable veth %s: %s", netPair.VirtIface.Name, err) @@ -1062,7 +1062,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) From c59394d3edbefdcc59a144e2161ed3f2a2477dae Mon Sep 17 00:00:00 2001 From: "James O. D. Hunt" Date: Thu, 26 Jul 2018 15:24:07 +0100 Subject: [PATCH 2/9] network: Make better use of log fields Add key log information as log fields rather than free-format text. Signed-off-by: James O. D. Hunt --- virtcontainers/network.go | 34 ++++++++++++++++++++++------------ 1 file changed, 22 insertions(+), 12 deletions(-) diff --git a/virtcontainers/network.go b/virtcontainers/network.go index 7adde3c6f9..07d0a3ca2a 100644 --- a/virtcontainers/network.go +++ b/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) - networkLogger().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) - networkLogger().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) - networkLogger().Infof("VhostUser endpoint unmarshalled [%v]", endpoint) + networkLogger().WithFields(logrus.Fields{ + "endpoint": endpoint, + "endpoint-type": "vhostuser", + }).Info("endpoint unmarshalled") default: - networkLogger().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 - networkLogger().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) From acdd0b8e688a9f91e1772d8a1e6216cfd8d69349 Mon Sep 17 00:00:00 2001 From: "James O. D. Hunt" Date: Thu, 26 Jul 2018 14:08:08 +0100 Subject: [PATCH 3/9] logging: Split logging source into two fields Don't use slash-delimited values in log fields - create two separate log fields (`source` and `subsystem`) for clarity. Signed-off-by: James O. D. Hunt --- virtcontainers/pkg/hyperstart/hyperstart.go | 5 ++++- virtcontainers/pkg/oci/utils.go | 5 ++++- 2 files changed, 8 insertions(+), 2 deletions(-) diff --git a/virtcontainers/pkg/hyperstart/hyperstart.go b/virtcontainers/pkg/hyperstart/hyperstart.go index 36474566ef..44548bd4c6 100644 --- a/virtcontainers/pkg/hyperstart/hyperstart.go +++ b/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. diff --git a/virtcontainers/pkg/oci/utils.go b/virtcontainers/pkg/oci/utils.go index 680354b1d7..0fb67ad5d4 100644 --- a/virtcontainers/pkg/oci/utils.go +++ b/virtcontainers/pkg/oci/utils.go @@ -132,7 +132,10 @@ var ociLog = logrus.FieldLogger(logrus.New()) // SetLogger sets the logger for oci package. func SetLogger(logger logrus.FieldLogger) { - ociLog = logger.WithField("source", "virtcontainers/oci") + ociLog = logger.WithFields(logrus.Fields{ + "source": "virtcontainers", + "subsystem": "oci", + }) } func cmdEnvs(spec CompatOCISpec, envs []vc.EnvVar) []vc.EnvVar { From dfb758a82d4f86de6a675d67f52b3cf7df1bf9e6 Mon Sep 17 00:00:00 2001 From: "James O. D. Hunt" Date: Thu, 26 Jul 2018 14:00:31 +0100 Subject: [PATCH 4/9] logging: Remove duplicate arch field in vc As of #521, the runtime now adds the `arch` log field so `virtcontainers` doesn't need to set it too. Signed-off-by: James O. D. Hunt --- virtcontainers/api.go | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/virtcontainers/api.go b/virtcontainers/api.go index 21d05a6c66..f9ab7b9d73 100644 --- a/virtcontainers/api.go +++ b/virtcontainers/api.go @@ -23,12 +23,7 @@ var virtLog = logrus.FieldLogger(logrus.New()) // SetLogger sets the logger for virtcontainers package. func SetLogger(logger logrus.FieldLogger) { - fields := logrus.Fields{ - "source": "virtcontainers", - "arch": runtime.GOARCH, - } - - virtLog = logger.WithFields(fields) + virtLog = logger.WithField("source", "virtcontainers") deviceApi.SetLogger(virtLog) } From 029e7ca680053f94f59d6d8475dd04c72714d738 Mon Sep 17 00:00:00 2001 From: "James O. D. Hunt" Date: Thu, 26 Jul 2018 14:38:26 +0100 Subject: [PATCH 5/9] api: Change logger functions to accept a log entry Rather than accepting a `logrus.FieldLogger` interface type, change all the `SetLogger()` functions to accept a `logrus.Entry`. Signed-off-by: James O. D. Hunt --- virtcontainers/api.go | 5 +++-- virtcontainers/device/api/interface.go | 4 ++-- virtcontainers/hack/virtc/main.go | 6 +++--- virtcontainers/implementation.go | 2 +- virtcontainers/interfaces.go | 2 +- virtcontainers/pkg/oci/utils.go | 2 +- virtcontainers/pkg/vcmock/mock.go | 2 +- virtcontainers/pkg/vcmock/mock_test.go | 2 +- virtcontainers/virtcontainers_test.go | 6 +++--- 9 files changed, 16 insertions(+), 15 deletions(-) diff --git a/virtcontainers/api.go b/virtcontainers/api.go index f9ab7b9d73..781e1eb314 100644 --- a/virtcontainers/api.go +++ b/virtcontainers/api.go @@ -19,11 +19,12 @@ func init() { runtime.LockOSThread() } -var virtLog = logrus.FieldLogger(logrus.New()) +var virtLog *logrus.Entry // SetLogger sets the logger for virtcontainers package. -func SetLogger(logger logrus.FieldLogger) { +func SetLogger(logger *logrus.Entry) { virtLog = logger.WithField("source", "virtcontainers") + deviceApi.SetLogger(virtLog) } diff --git a/virtcontainers/device/api/interface.go b/virtcontainers/device/api/interface.go index d6a4072d33..ab079598c9 100644 --- a/virtcontainers/device/api/interface.go +++ b/virtcontainers/device/api/interface.go @@ -12,10 +12,10 @@ import ( "github.com/kata-containers/runtime/virtcontainers/device/config" ) -var devLogger = logrus.FieldLogger(logrus.New()) +var devLogger *logrus.Entry // SetLogger sets the logger for device api package. -func SetLogger(logger logrus.FieldLogger) { +func SetLogger(logger *logrus.Entry) { devLogger = logger } diff --git a/virtcontainers/hack/virtc/main.go b/virtcontainers/hack/virtc/main.go index cf6457f9f8..ec36019db9 100644 --- a/virtcontainers/hack/virtc/main.go +++ b/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")) } diff --git a/virtcontainers/implementation.go b/virtcontainers/implementation.go index 8e5f8fa039..b3a4b961ad 100644 --- a/virtcontainers/implementation.go +++ b/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) } diff --git a/virtcontainers/interfaces.go b/virtcontainers/interfaces.go index fc74b97992..ec0d2b5bd3 100644 --- a/virtcontainers/interfaces.go +++ b/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) diff --git a/virtcontainers/pkg/oci/utils.go b/virtcontainers/pkg/oci/utils.go index 0fb67ad5d4..5028fc6577 100644 --- a/virtcontainers/pkg/oci/utils.go +++ b/virtcontainers/pkg/oci/utils.go @@ -131,7 +131,7 @@ func (config *RuntimeConfig) AddKernelParam(p vc.Param) error { var ociLog = logrus.FieldLogger(logrus.New()) // SetLogger sets the logger for oci package. -func SetLogger(logger logrus.FieldLogger) { +func SetLogger(logger *logrus.Entry) { ociLog = logger.WithFields(logrus.Fields{ "source": "virtcontainers", "subsystem": "oci", diff --git a/virtcontainers/pkg/vcmock/mock.go b/virtcontainers/pkg/vcmock/mock.go index c0413591b8..ea895c26a5 100644 --- a/virtcontainers/pkg/vcmock/mock.go +++ b/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) } diff --git a/virtcontainers/pkg/vcmock/mock_test.go b/virtcontainers/pkg/vcmock/mock_test.go index 67c7bfe644..411bc05541 100644 --- a/virtcontainers/pkg/vcmock/mock_test.go +++ b/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) diff --git a/virtcontainers/virtcontainers_test.go b/virtcontainers/virtcontainers_test.go index 86432b6dac..c85a422560 100644 --- a/virtcontainers/virtcontainers_test.go +++ b/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) From 58448bbcb8513eef0242a5e05d54331c70e259d9 Mon Sep 17 00:00:00 2001 From: "James O. D. Hunt" Date: Thu, 26 Jul 2018 14:47:42 +0100 Subject: [PATCH 6/9] logging: Allow SetLogger to be called multiple times Now that the `SetLogger()` functions accept a `logrus.Entry`, they can access the fields that have already been set for the logger and re-apply them if `SetLogger()` is called multiple times. This fixes a bug whereby the logger functions -- which are necessarily called multiple times [1] -- previously ended up applying any new fields the specified logger contained, but erroneously removing any additional fields added since `SetLogger()` was last called. Partially fixes #519. -- [1] - https://github.com/kata-containers/runtime/pull/468 Signed-off-by: James O. D. Hunt --- virtcontainers/api.go | 5 +++-- virtcontainers/device/api/interface.go | 7 ++++--- virtcontainers/pkg/oci/utils.go | 11 ++++++----- 3 files changed, 13 insertions(+), 10 deletions(-) diff --git a/virtcontainers/api.go b/virtcontainers/api.go index 781e1eb314..340a2bf71a 100644 --- a/virtcontainers/api.go +++ b/virtcontainers/api.go @@ -19,11 +19,12 @@ func init() { runtime.LockOSThread() } -var virtLog *logrus.Entry +var virtLog = logrus.WithField("source", "virtcontainers") // SetLogger sets the logger for virtcontainers package. func SetLogger(logger *logrus.Entry) { - virtLog = logger.WithField("source", "virtcontainers") + fields := virtLog.Data + virtLog = logger.WithFields(fields) deviceApi.SetLogger(virtLog) } diff --git a/virtcontainers/device/api/interface.go b/virtcontainers/device/api/interface.go index ab079598c9..2bb2af6542 100644 --- a/virtcontainers/device/api/interface.go +++ b/virtcontainers/device/api/interface.go @@ -12,16 +12,17 @@ import ( "github.com/kata-containers/runtime/virtcontainers/device/config" ) -var devLogger *logrus.Entry +var devLogger = logrus.WithField("subsystem", "device") // SetLogger sets the logger for device api package. func SetLogger(logger *logrus.Entry) { - devLogger = logger + 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 diff --git a/virtcontainers/pkg/oci/utils.go b/virtcontainers/pkg/oci/utils.go index 5028fc6577..a94a3797c7 100644 --- a/virtcontainers/pkg/oci/utils.go +++ b/virtcontainers/pkg/oci/utils.go @@ -128,14 +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.Entry) { - ociLog = logger.WithFields(logrus.Fields{ - "source": "virtcontainers", - "subsystem": "oci", - }) + fields := ociLog.Data + ociLog = logger.WithFields(fields) } func cmdEnvs(spec CompatOCISpec, envs []vc.EnvVar) []vc.EnvVar { From 3d5ed6669c000b806039081192ed5e661800458f Mon Sep 17 00:00:00 2001 From: "James O. D. Hunt" Date: Fri, 27 Jul 2018 14:45:21 +0100 Subject: [PATCH 7/9] logging: Improve cid+sid logging Refine the changes made on #468 by adding the containerID log field as soon as possible (before *any* virtcontainers calls). This requires that `setExternalLoggers()` be called more times, but it's essential to ensure the correct log fields are available as early as possible. Partially fixes #519. Signed-off-by: James O. D. Hunt --- cli/delete.go | 7 +++++-- cli/events.go | 5 +++++ cli/exec.go | 15 +++++++++------ cli/kill.go | 4 ++++ cli/pause.go | 3 +++ cli/ps.go | 3 +++ cli/start.go | 7 +++++-- 7 files changed, 34 insertions(+), 10 deletions(-) diff --git a/cli/delete.go b/cli/delete.go index 31ee87227f..6a89e40f79 100644 --- a/cli/delete.go +++ b/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 diff --git a/cli/events.go b/cli/events.go index 67dfc56aac..588ca17738 100644 --- a/cli/events.go +++ b/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, diff --git a/cli/exec.go b/cli/exec.go index 2d5d1f28ad..40a2d09ce1 100644 --- a/cli/exec.go +++ b/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 && diff --git a/cli/kill.go b/cli/kill.go index f66de9be72..2c7d3bdef2 100644 --- a/cli/kill.go +++ b/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 } diff --git a/cli/pause.go b/cli/pause.go index 2cec0beaec..c9b357105c 100644 --- a/cli/pause.go +++ b/cli/pause.go @@ -42,6 +42,9 @@ Where "" 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 { diff --git a/cli/ps.go b/cli/ps.go index 2d0817270c..85a33777c3 100644 --- a/cli/ps.go +++ b/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 { diff --git a/cli/start.go b/cli/start.go index 24723209a4..71cb7d11e5 100644 --- a/cli/start.go +++ b/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 From 3323c087c583e62663aac985b7a44a80d0d25f1f Mon Sep 17 00:00:00 2001 From: "James O. D. Hunt" Date: Fri, 27 Jul 2018 14:46:43 +0100 Subject: [PATCH 8/9] logging: Add cid logging to update command PR #468 neglected to update the `update` command. Fixes #519. Signed-off-by: James O. D. Hunt --- cli/update.go | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/cli/update.go b/cli/update.go index fbb718f623..71b2dfbdd8 100644 --- a/cli/update.go +++ b/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) From 763a1b6265a24699cae8d5e1e2f1b94b4b291a1d Mon Sep 17 00:00:00 2001 From: "James O. D. Hunt" Date: Fri, 27 Jul 2018 14:55:55 +0100 Subject: [PATCH 9/9] logging: Remove unnecessary fields and use standard names Ensure the entire codebase uses `"sandbox"` and `"container"` log fields for the sandboxID and containerID respectively. Simplify code where fields can be dropped. Signed-off-by: James O. D. Hunt --- virtcontainers/container.go | 5 ++--- virtcontainers/kata_agent.go | 8 ++++---- virtcontainers/sandbox.go | 6 +++--- 3 files changed, 9 insertions(+), 10 deletions(-) diff --git a/virtcontainers/container.go b/virtcontainers/container.go index 941b7d3968..50b1094e86 100644 --- a/virtcontainers/container.go +++ b/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, }) } diff --git a/virtcontainers/kata_agent.go b/virtcontainers/kata_agent.go index f442aabc1d..64e6aa4d5a 100644 --- a/virtcontainers/kata_agent.go +++ b/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 diff --git a/virtcontainers/sandbox.go b/virtcontainers/sandbox.go index b3339d252f..f0abcb7bfe 100644 --- a/virtcontainers/sandbox.go +++ b/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 }