Merge pull request clearcontainers#644 from jodh-intel/add-structured…

…-logging

logging: Switch to structured logging

cc-check.go

@@ -21,6 +21,7 @@ import (
 	"regexp"
 	"strings"
 
+	"github.com/Sirupsen/logrus"
 	vc "github.com/containers/virtcontainers"
 	"github.com/urfave/cli"
 )
@@ -34,10 +35,11 @@ type kernelModule struct {
 }
 
 const (
-	moduleParamDir = "parameters"
-	cpuFlagsTag    = "flags"
-	successMessage = "System is capable of running " + project
-	failMessage    = "System is not capable of running " + project
+	moduleParamDir        = "parameters"
+	cpuFlagsTag           = "flags"
+	successMessage        = "System is capable of running " + project
+	failMessage           = "System is not capable of running " + project
+	kernelPropertyCorrect = "Kernel property value correct"
 )
 
 // variables rather than consts to allow tests to modify them
@@ -146,15 +148,21 @@ func checkCPU(tag, cpuinfo string, attribs map[string]string) (count uint32, err
 	}
 
 	for attrib, desc := range attribs {
+		fields := logrus.Fields{
+			"type":        tag,
+			"name":        attrib,
+			"description": desc,
+		}
+
 		found := findAnchoredString(cpuinfo, attrib)
 		if !found {
-			ccLog.Errorf("CPU does not have required %v: %q (%s)", tag, desc, attrib)
+			ccLog.WithFields(fields).Errorf("CPU property not found")
 			count++
 			continue
 
 		}
 
-		ccLog.Infof("Found CPU %v %q (%s)", tag, desc, attrib)
+		ccLog.WithFields(fields).Infof("CPU property found")
 	}
 
 	return count, nil
@@ -178,13 +186,19 @@ func checkKernelModules(modules map[string]kernelModule) (count uint32, err erro
 	}
 
 	for module, details := range modules {
+		fields := logrus.Fields{
+			"type":        "module",
+			"name":        module,
+			"description": details.desc,
+		}
+
 		if !haveKernelModule(module) {
-			ccLog.Errorf("kernel module %q (%s) not found", module, details.desc)
+			ccLog.WithFields(fields).Error("kernel property not found")
 			count++
 			continue
 		}
 
-		ccLog.Infof("Found kernel module %q (%s)", details.desc, module)
+		ccLog.WithFields(fields).Infof("kernel property found")
 
 		for param, expected := range details.parameters {
 			path := filepath.Join(sysModuleDir, module, moduleParamDir, param)
@@ -196,25 +210,29 @@ func checkKernelModules(modules map[string]kernelModule) (count uint32, err erro
 			value = strings.TrimRight(value, "\n\r")
 
 			if value != expected {
-				msg := fmt.Sprintf("kernel module %q parameter %q has value %q (expected %q)", details.desc, param, value, expected)
+				fields["expected"] = expected
+				fields["actual"] = value
+				fields["parameter"] = param
+
+				msg := "kernel module parameter has unexpected value"
 
 				// this option is not required when
 				// already running under a hypervisor.
 				if param == "unrestricted_guest" && onVMM {
-					ccLog.Warn(msg)
+					ccLog.WithFields(fields).Warn(kernelPropertyCorrect)
 					continue
 				}
 
 				if param == "nested" {
-					ccLog.Warn(msg)
+					ccLog.WithFields(fields).Warn(msg)
 					continue
 				}
 
-				ccLog.Error(msg)
+				ccLog.WithFields(fields).Error(msg)
 				count++
 			}
 
-			ccLog.Infof("Kernel module %q parameter %q has correct value", details.desc, param)
+			ccLog.WithFields(fields).Info(kernelPropertyCorrect)
 		}
 	}
 
@@ -275,7 +293,6 @@ var ccCheckCLICommand = cli.Command{
 			return err
 		}
 
-		ccLog.Info("")
 		ccLog.Info(successMessage)
 
 		return nil

cc-check_test.go

@@ -493,13 +493,13 @@ func TestCheckCheckKernelModulesNoUnrestrictedGuest(t *testing.T) {
 	// create buffer to save logger output
 	buf := &bytes.Buffer{}
 
-	savedLogOutput := ccLog.Out
+	savedLogOutput := ccLog.Logger.Out
 
 	defer func() {
-		ccLog.Out = savedLogOutput
+		ccLog.Logger.Out = savedLogOutput
 	}()
 
-	ccLog.Out = buf
+	ccLog.Logger.Out = buf
 
 	count, err = checkKernelModules(requiredModules)
 
@@ -745,13 +745,13 @@ func TestCCCheckCLIFunction(t *testing.T) {
 	devNull, err := os.OpenFile(os.DevNull, os.O_WRONLY, 0666)
 	assert.NoError(err)
 
-	savedLogOutput := ccLog.Out
+	savedLogOutput := ccLog.Logger.Out
 
 	// discard normal output
-	ccLog.Out = devNull
+	ccLog.Logger.Out = devNull
 
 	defer func() {
-		ccLog.Out = savedLogOutput
+		ccLog.Logger.Out = savedLogOutput
 	}()
 
 	assert.False(fileExists(logfile))

config.go

@@ -23,6 +23,7 @@ import (
 	"strings"
 
 	"github.com/BurntSushi/toml"
+	"github.com/Sirupsen/logrus"
 	vc "github.com/containers/virtcontainers"
 	"github.com/containers/virtcontainers/pkg/oci"
 )
@@ -395,7 +396,11 @@ func loadConfiguration(configPath string, ignoreLogging bool) (resolvedConfigPat
 			return "", "", config, err
 		}
 
-		ccLog.Debugf("TOML configuration: %v", tomlConf)
+		ccLog.WithFields(
+			logrus.Fields{
+				"file":   logfilePath,
+				"format": "TOML",
+			}).Debugf("loaded configuration")
 	}
 
 	if err := updateRuntimeConfig(resolved, tomlConf, &config); err != nil {

create.go

@@ -21,6 +21,7 @@ import (
 	"os"
 	"path/filepath"
 
+	"github.com/Sirupsen/logrus"
 	vc "github.com/containers/virtcontainers"
 	"github.com/containers/virtcontainers/pkg/oci"
 	"github.com/urfave/cli"
@@ -133,7 +134,7 @@ func create(containerID, bundlePath, console, pidFilePath string, detach bool,
 		return err
 	}
 
-	if err := createCgroupsFiles(cgroupsPathList, process.Pid); err != nil {
+	if err := createCgroupsFiles(containerID, cgroupsPathList, process.Pid); err != nil {
 		return err
 	}
 
@@ -217,9 +218,13 @@ func createContainer(ociSpec oci.CompatOCISpec, containerID, bundlePath,
 	return c.Process(), nil
 }
 
-func createCgroupsFiles(cgroupsPathList []string, pid int) error {
+func createCgroupsFiles(containerID string, cgroupsPathList []string, pid int) error {
 	if len(cgroupsPathList) == 0 {
-		ccLog.Info("Cgroups files not created because cgroupsPath was empty")
+		fields := logrus.Fields{
+			"container": containerID,
+			"pid":       pid,
+		}
+		ccLog.WithFields(fields).Info("Cgroups files not created because cgroupsPath was empty")
 		return nil
 	}
 

create_test.go

@@ -43,7 +43,7 @@ const (
 var testStrPID = fmt.Sprintf("%d", testPID)
 
 func testCreateCgroupsFilesSuccessful(t *testing.T, cgroupsPathList []string, pid int) {
-	if err := createCgroupsFiles(cgroupsPathList, pid); err != nil {
+	if err := createCgroupsFiles("foo", cgroupsPathList, pid); err != nil {
 		t.Fatalf("This test should succeed (cgroupsPath %q, pid %d): %s", cgroupsPathList, pid, err)
 	}
 }
@@ -71,7 +71,7 @@ func TestCreateCgroupsFilesFailToWriteFile(t *testing.T) {
 
 	files := []string{file}
 
-	err = createCgroupsFiles(files, testPID)
+	err = createCgroupsFiles("foo", files, testPID)
 	assert.Error(err)
 }
 

delete.go

@@ -110,7 +110,7 @@ func delete(containerID string, force bool) error {
 		return err
 	}
 
-	return removeCgroupsPath(cgroupsPathList)
+	return removeCgroupsPath(containerID, cgroupsPathList)
 }
 
 func deletePod(podID string) error {
@@ -139,9 +139,9 @@ func deleteContainer(podID, containerID string, forceStop bool) error {
 	return nil
 }
 
-func removeCgroupsPath(cgroupsPathList []string) error {
+func removeCgroupsPath(containerID string, cgroupsPathList []string) error {
 	if len(cgroupsPathList) == 0 {
-		ccLog.Info("Cgroups files not removed because cgroupsPath was empty")
+		ccLog.WithField("container", containerID).Info("Cgroups files not removed because cgroupsPath was empty")
 		return nil
 	}
 

delete_test.go

@@ -29,7 +29,7 @@ import (
 )
 
 func testRemoveCgroupsPathSuccessful(t *testing.T, cgroupsPathList []string) {
-	if err := removeCgroupsPath(cgroupsPathList); err != nil {
+	if err := removeCgroupsPath("foo", cgroupsPathList); err != nil {
 		t.Fatalf("This test should succeed (cgroupsPathList = %v): %s", cgroupsPathList, err)
 	}
 }

logger.go

@@ -19,6 +19,7 @@ import (
 	"fmt"
 	"os"
 	"path/filepath"
+	"sort"
 	"strings"
 
 	"github.com/Sirupsen/logrus"
@@ -96,7 +97,7 @@ func handleGlobalLog(logfilePath string) error {
 		return err
 	}
 
-	ccLog.Hooks.Add(hook)
+	ccLog.Logger.Hooks.Add(hook)
 
 	return nil
 }
@@ -127,18 +128,50 @@ func (hook *GlobalLogHook) Levels() []logrus.Level {
 	return logrus.AllLevels
 }
 
+// formatFields returns a "name=value" formatted string of sorted map keys
+func formatFields(fields map[string]interface{}) string {
+	var keys []string
+
+	for key := range fields {
+		keys = append(keys, key)
+	}
+
+	sort.Sort(sort.StringSlice(keys))
+
+	var sorted []string
+
+	for _, k := range keys {
+		sorted = append(sorted, fmt.Sprintf("%s=%q", k, fields[k]))
+	}
+
+	return strings.Join(sorted, " ")
+}
+
 // Fire is called by the logrus logger when data is available for the
 // hook.
 func (hook *GlobalLogHook) Fire(entry *logrus.Entry) error {
-
 	// Ignore any formatter that has been used and log in a custom format
 	// to the global log.
-	_, err := hook.file.WriteString(fmt.Sprintf("%v:%d:%s:%s:%s\n",
+
+	fields := formatFields(entry.Data)
+
+	str := fmt.Sprintf("time=%q pid=%d name=%q level=%q",
 		entry.Time,
 		os.Getpid(),
 		name,
-		entry.Level,
-		entry.Message))
+		entry.Level)
+
+	if fields != "" {
+		str += " " + fields
+	}
+
+	if entry.Message != "" {
+		str += " " + fmt.Sprintf("msg=%q", entry.Message)
+	}
+
+	str += "\n"
+
+	_, err := hook.file.WriteString(str)
 	if err != nil {
 		return err
 	}