[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