[lxc-devel] [lxd/master] Improve logging

stgraber on Github lxc-bot at linuxcontainers.org
Sun Nov 27 01:09:23 UTC 2016


A non-text attachment was scrubbed...
Name: not available
Type: text/x-mailbox
Size: 301 bytes
Desc: not available
URL: <http://lists.linuxcontainers.org/pipermail/lxc-devel/attachments/20161127/b7431e09/attachment.bin>
-------------- next part --------------
From 335763775cf4a25492ed5a59070e2f9ce22f5233 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?St=C3=A9phane=20Graber?= <stgraber at ubuntu.com>
Date: Sat, 26 Nov 2016 18:48:09 -0500
Subject: [PATCH 1/2] Add basic logging to container creation
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Signed-off-by: Stéphane Graber <stgraber at ubuntu.com>
---
 lxd/container_lxc.go | 17 +++++++++++++++++
 1 file changed, 17 insertions(+)

diff --git a/lxd/container_lxc.go b/lxd/container_lxc.go
index a5bf86b..fe416be 100644
--- a/lxd/container_lxc.go
+++ b/lxd/container_lxc.go
@@ -180,6 +180,11 @@ func containerLXCCreate(d *Daemon, args containerArgs) (container, error) {
 		localDevices: args.Devices,
 	}
 
+	ctxMap := log.Ctx{"name": c.name,
+		"ephemeral": c.ephemeral}
+
+	shared.LogInfo("Creating container", ctxMap)
+
 	// No need to detect storage here, its a new container.
 	c.storage = d.Storage
 
@@ -187,6 +192,7 @@ func containerLXCCreate(d *Daemon, args containerArgs) (container, error) {
 	err := c.init()
 	if err != nil {
 		c.Delete()
+		shared.LogError("Failed creating container", ctxMap)
 		return nil, err
 	}
 
@@ -223,6 +229,7 @@ func containerLXCCreate(d *Daemon, args containerArgs) (container, error) {
 		err = c.Update(updateArgs, false)
 		if err != nil {
 			c.Delete()
+			shared.LogError("Failed creating container", ctxMap)
 			return nil, err
 		}
 	}
@@ -231,12 +238,14 @@ func containerLXCCreate(d *Daemon, args containerArgs) (container, error) {
 	err = containerValidConfig(d, c.expandedConfig, false, true)
 	if err != nil {
 		c.Delete()
+		shared.LogError("Failed creating container", ctxMap)
 		return nil, err
 	}
 
 	err = containerValidDevices(c.expandedDevices, false, true)
 	if err != nil {
 		c.Delete()
+		shared.LogError("Failed creating container", ctxMap)
 		return nil, err
 	}
 
@@ -254,6 +263,7 @@ func containerLXCCreate(d *Daemon, args containerArgs) (container, error) {
 
 		if err != nil {
 			c.Delete()
+			shared.LogError("Failed creating container", ctxMap)
 			return nil, err
 		}
 	}
@@ -263,6 +273,7 @@ func containerLXCCreate(d *Daemon, args containerArgs) (container, error) {
 		idmapBytes, err := json.Marshal(idmap.Idmap)
 		if err != nil {
 			c.Delete()
+			shared.LogError("Failed creating container", ctxMap)
 			return nil, err
 		}
 		jsonIdmap = string(idmapBytes)
@@ -273,12 +284,14 @@ func containerLXCCreate(d *Daemon, args containerArgs) (container, error) {
 	err = c.ConfigKeySet("volatile.idmap.next", jsonIdmap)
 	if err != nil {
 		c.Delete()
+		shared.LogError("Failed creating container", ctxMap)
 		return nil, err
 	}
 
 	err = c.ConfigKeySet("volatile.idmap.base", fmt.Sprintf("%v", base))
 	if err != nil {
 		c.Delete()
+		shared.LogError("Failed creating container", ctxMap)
 		return nil, err
 	}
 
@@ -287,6 +300,7 @@ func containerLXCCreate(d *Daemon, args containerArgs) (container, error) {
 		err = c.ConfigKeySet("volatile.last_state.idmap", jsonIdmap)
 		if err != nil {
 			c.Delete()
+			shared.LogError("Failed creating container", ctxMap)
 			return nil, err
 		}
 	}
@@ -295,12 +309,15 @@ func containerLXCCreate(d *Daemon, args containerArgs) (container, error) {
 	err = c.init()
 	if err != nil {
 		c.Delete()
+		shared.LogError("Failed creating container", ctxMap)
 		return nil, err
 	}
 
 	// Update lease files
 	networkUpdateStatic(d)
 
+	shared.LogInfo("Created container", ctxMap)
+
 	return c, nil
 }
 

From a9fd2a7448ccebfd97e1c943ec1550ee383f73a1 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?St=C3=A9phane=20Graber?= <stgraber at ubuntu.com>
Date: Sat, 26 Nov 2016 19:59:39 -0500
Subject: [PATCH 2/2] logging: Introduce our own formatter
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

This allows us to sort the context keys.

Signed-off-by: Stéphane Graber <stgraber at ubuntu.com>
---
 shared/logging/format.go      | 191 ++++++++++++++++++++++++++++++++++++++++++
 shared/logging/log.go         |  20 +++--
 shared/logging/log_posix.go   |   6 +-
 shared/logging/log_windows.go |   2 +-
 4 files changed, 208 insertions(+), 11 deletions(-)
 create mode 100644 shared/logging/format.go

diff --git a/shared/logging/format.go b/shared/logging/format.go
new file mode 100644
index 0000000..083d40e
--- /dev/null
+++ b/shared/logging/format.go
@@ -0,0 +1,191 @@
+package logging
+
+import (
+	"bytes"
+	"fmt"
+	"reflect"
+	"sort"
+	"strconv"
+	"strings"
+	"time"
+
+	log "gopkg.in/inconshreveable/log15.v2"
+)
+
+const (
+	timeFormat     = "2006-01-02T15:04:05-0700"
+	floatFormat    = 'f'
+	errorKey       = "LOG15_ERROR"
+	termTimeFormat = "01-02|15:04:05"
+	termMsgJust    = 40
+)
+
+// Imported from the log15 project
+
+// TerminalFormat formats log records optimized for human readability on
+// a terminal with color-coded level output and terser human friendly timestamp.
+// This format should only be used for interactive programs or while developing.
+//
+//     [TIME] [LEVEL] MESAGE key=value key=value ...
+//
+// Example:
+//
+//     [May 16 20:58:45] [DBUG] remove route ns=haproxy addr=127.0.0.1:50002
+//
+func TerminalFormat() log.Format {
+	return log.FormatFunc(func(r *log.Record) []byte {
+		var color = 0
+		switch r.Lvl {
+		case log.LvlCrit:
+			color = 35
+		case log.LvlError:
+			color = 31
+		case log.LvlWarn:
+			color = 33
+		case log.LvlInfo:
+			color = 32
+		case log.LvlDebug:
+			color = 36
+		}
+
+		b := &bytes.Buffer{}
+		lvl := strings.ToUpper(r.Lvl.String())
+		if color > 0 {
+			fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %s ", color, lvl, r.Time.Format(termTimeFormat), r.Msg)
+		} else {
+			fmt.Fprintf(b, "[%s] [%s] %s ", lvl, r.Time.Format(termTimeFormat), r.Msg)
+		}
+
+		// try to justify the log output for short messages
+		if len(r.Ctx) > 0 && len(r.Msg) < termMsgJust {
+			b.Write(bytes.Repeat([]byte{' '}, termMsgJust-len(r.Msg)))
+		}
+
+		// print the keys logfmt style
+		logfmt(b, r.Ctx, color)
+		return b.Bytes()
+	})
+}
+
+func LogfmtFormat() log.Format {
+	return log.FormatFunc(func(r *log.Record) []byte {
+		common := []interface{}{r.KeyNames.Time, r.Time, r.KeyNames.Lvl, r.Lvl, r.KeyNames.Msg, r.Msg}
+		buf := &bytes.Buffer{}
+		logfmt(buf, append(common, r.Ctx...), 0)
+		return buf.Bytes()
+	})
+}
+
+func logfmt(buf *bytes.Buffer, ctx []interface{}, color int) {
+	entries := []string{}
+
+	for i := 0; i < len(ctx); i += 2 {
+		k, ok := ctx[i].(string)
+		v := formatLogfmtValue(ctx[i+1])
+		if !ok {
+			k, v = errorKey, formatLogfmtValue(k)
+		}
+
+		// XXX: we should probably check that all of your key bytes aren't invalid
+		if color > 0 {
+			entries = append(entries, fmt.Sprintf("\x1b[%dm%s\x1b[0m=%s", color, k, v))
+		} else {
+			entries = append(entries, fmt.Sprintf("%s=%s", k, v))
+		}
+	}
+
+	sort.Strings(entries)
+
+	for i, v := range entries {
+		if i != 0 {
+			buf.WriteByte(' ')
+		}
+
+		fmt.Fprint(buf, v)
+	}
+
+	buf.WriteByte('\n')
+}
+
+func formatShared(value interface{}) (result interface{}) {
+	defer func() {
+		if err := recover(); err != nil {
+			if v := reflect.ValueOf(value); v.Kind() == reflect.Ptr && v.IsNil() {
+				result = "nil"
+			} else {
+				panic(err)
+			}
+		}
+	}()
+
+	switch v := value.(type) {
+	case time.Time:
+		return v.Format(timeFormat)
+
+	case error:
+		return v.Error()
+
+	case fmt.Stringer:
+		return v.String()
+
+	default:
+		return v
+	}
+}
+
+// formatValue formats a value for serialization
+func formatLogfmtValue(value interface{}) string {
+	if value == nil {
+		return "nil"
+	}
+
+	value = formatShared(value)
+	switch v := value.(type) {
+	case bool:
+		return strconv.FormatBool(v)
+	case float32:
+		return strconv.FormatFloat(float64(v), floatFormat, 3, 64)
+	case float64:
+		return strconv.FormatFloat(v, floatFormat, 3, 64)
+	case int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64:
+		return fmt.Sprintf("%d", value)
+	case string:
+		return escapeString(v)
+	default:
+		return escapeString(fmt.Sprintf("%+v", value))
+	}
+}
+
+func escapeString(s string) string {
+	needQuotes := false
+	e := bytes.Buffer{}
+	e.WriteByte('"')
+	for _, r := range s {
+		if r <= ' ' || r == '=' || r == '"' {
+			needQuotes = true
+		}
+
+		switch r {
+		case '\\', '"':
+			e.WriteByte('\\')
+			e.WriteByte(byte(r))
+		case '\n':
+			e.WriteByte('\\')
+			e.WriteByte('n')
+		case '\r':
+			e.WriteByte('\\')
+			e.WriteByte('r')
+		case '\t':
+			e.WriteByte('\\')
+			e.WriteByte('t')
+		default:
+			e.WriteRune(r)
+		}
+	}
+	e.WriteByte('"')
+	start, stop := 0, e.Len()
+	if !needQuotes {
+		start, stop = 1, stop-1
+	}
+	return string(e.Bytes()[start:stop])
+}
diff --git a/shared/logging/log.go b/shared/logging/log.go
index 53e2d6a..f073028 100644
--- a/shared/logging/log.go
+++ b/shared/logging/log.go
@@ -6,6 +6,7 @@ import (
 	"path/filepath"
 
 	"github.com/lxc/lxd/shared"
+	"gopkg.in/inconshreveable/log15.v2/term"
 
 	log "gopkg.in/inconshreveable/log15.v2"
 )
@@ -15,11 +16,16 @@ func GetLogger(syslog string, logfile string, verbose bool, debug bool, customHa
 	Log := log.New()
 
 	var handlers []log.Handler
-
 	var syshandler log.Handler
 
+	// Format handler
+	format := LogfmtFormat()
+	if term.IsTty(os.Stderr.Fd()) {
+		format = TerminalFormat()
+	}
+
 	// System specific handler
-	syshandler = getSystemHandler(syslog, debug)
+	syshandler = getSystemHandler(syslog, debug, format)
 	if syshandler != nil {
 		handlers = append(handlers, syshandler)
 	}
@@ -35,11 +41,11 @@ func GetLogger(syslog string, logfile string, verbose bool, debug bool, customHa
 				handlers,
 				log.LvlFilterHandler(
 					log.LvlInfo,
-					log.Must.FileHandler(logfile, log.LogfmtFormat()),
+					log.Must.FileHandler(logfile, format),
 				),
 			)
 		} else {
-			handlers = append(handlers, log.Must.FileHandler(logfile, log.LogfmtFormat()))
+			handlers = append(handlers, log.Must.FileHandler(logfile, format))
 		}
 	}
 
@@ -50,18 +56,18 @@ func GetLogger(syslog string, logfile string, verbose bool, debug bool, customHa
 				handlers,
 				log.LvlFilterHandler(
 					log.LvlInfo,
-					log.StderrHandler,
+					log.StreamHandler(os.Stderr, format),
 				),
 			)
 		} else {
-			handlers = append(handlers, log.StderrHandler)
+			handlers = append(handlers, log.StreamHandler(os.Stderr, format))
 		}
 	} else {
 		handlers = append(
 			handlers,
 			log.LvlFilterHandler(
 				log.LvlWarn,
-				log.StderrHandler,
+				log.StreamHandler(os.Stderr, format),
 			),
 		)
 	}
diff --git a/shared/logging/log_posix.go b/shared/logging/log_posix.go
index 28e0dd1..7cdbfd9 100644
--- a/shared/logging/log_posix.go
+++ b/shared/logging/log_posix.go
@@ -7,16 +7,16 @@ import (
 )
 
 // getSystemHandler on Linux writes messages to syslog.
-func getSystemHandler(syslog string, debug bool) log.Handler {
+func getSystemHandler(syslog string, debug bool, format log.Format) log.Handler {
 	// SyslogHandler
 	if syslog != "" {
 		if !debug {
 			return log.LvlFilterHandler(
 				log.LvlInfo,
-				log.Must.SyslogHandler(syslog, log.LogfmtFormat()),
+				log.Must.SyslogHandler(syslog, format),
 			)
 		} else {
-			return log.Must.SyslogHandler(syslog, log.LogfmtFormat())
+			return log.Must.SyslogHandler(syslog, format)
 		}
 	}
 
diff --git a/shared/logging/log_windows.go b/shared/logging/log_windows.go
index ff8b24e..009326e 100644
--- a/shared/logging/log_windows.go
+++ b/shared/logging/log_windows.go
@@ -7,6 +7,6 @@ import (
 )
 
 // getSystemHandler on Windows does nothing.
-func getSystemHandler(syslog string, debug bool) log.Handler {
+func getSystemHandler(syslog string, debug bool, format log.Format) log.Handler {
 	return nil
 }


More information about the lxc-devel mailing list