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

stgraber on Github lxc-bot at linuxcontainers.org
Tue Oct 30 18:23:02 UTC 2018


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/20181030/90e109ec/attachment.bin>
-------------- next part --------------
From 992da5d46dbd3674679f09cc05f3de76ee5c771e Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?St=C3=A9phane=20Graber?= <stgraber at ubuntu.com>
Date: Tue, 30 Oct 2018 12:56:47 -0400
Subject: [PATCH 1/6] lxd/db: Send raft/dqlite logging to debug
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/cluster/gateway.go | 6 +++---
 lxd/cluster/raft.go    | 6 +++---
 2 files changed, 6 insertions(+), 6 deletions(-)

diff --git a/lxd/cluster/gateway.go b/lxd/cluster/gateway.go
index 1e93f3ba4a..543f53d2d3 100644
--- a/lxd/cluster/gateway.go
+++ b/lxd/cluster/gateway.go
@@ -294,7 +294,7 @@ func (g *Gateway) Kill() {
 
 // Shutdown this gateway, stopping the gRPC server and possibly the raft factory.
 func (g *Gateway) Shutdown() error {
-	logger.Info("Stop database gateway")
+	logger.Debugf("Stop database gateway")
 
 	if g.raft != nil {
 		err := g.raft.Shutdown()
@@ -444,7 +444,7 @@ func (g *Gateway) LeaderAddress() (string, error) {
 // Initialize the gateway, creating a new raft factory and gRPC server (if this
 // node is a database node), and a gRPC dialer.
 func (g *Gateway) init() error {
-	logger.Info("Initializing database gateway")
+	logger.Debugf("Initializing database gateway")
 	raft, err := newRaft(g.db, g.cert, g.options.latency)
 	if err != nil {
 		return errors.Wrap(err, "Failed to create raft factory")
@@ -649,7 +649,7 @@ func DqliteLog(l dqlite.LogLevel, format string, a ...interface{}) {
 	case dqlite.LogDebug:
 		logger.Debugf(format, a...)
 	case dqlite.LogInfo:
-		logger.Infof(format, a...)
+		logger.Debugf(format, a...)
 	case dqlite.LogWarn:
 		logger.Warnf(format, a...)
 	case dqlite.LogError:
diff --git a/lxd/cluster/raft.go b/lxd/cluster/raft.go
index bbb4074aa3..5ac00f4919 100644
--- a/lxd/cluster/raft.go
+++ b/lxd/cluster/raft.go
@@ -65,7 +65,7 @@ func newRaft(database *db.Node, cert *shared.CertInfo, latency float64) (*raftIn
 	if info == nil {
 		return nil, nil
 	}
-	logger.Info("Start database node", log15.Ctx{"id": info.ID, "address": info.Address})
+	logger.Debug("Start database node", log15.Ctx{"id": info.ID, "address": info.Address})
 
 	// Initialize a raft instance along with all needed dependencies.
 	instance, err := raftInstanceInit(database, info, cert, latency)
@@ -270,7 +270,7 @@ func (i *raftInstance) MembershipChanger() raftmembership.Changer {
 
 // Shutdown raft and any raft-related resource we have instantiated.
 func (i *raftInstance) Shutdown() error {
-	logger.Info("Stop raft instance")
+	logger.Debug("Stop raft instance")
 
 	// Invoke raft APIs asynchronously to allow for a timeout.
 	timeout := 10 * time.Second
@@ -461,7 +461,7 @@ func (o *raftLogWriter) Write(line []byte) (n int, err error) {
 	case "DEBUG":
 		logger.Debug(msg)
 	case "INFO":
-		logger.Info(msg)
+		logger.Debug(msg)
 	case "WARN":
 		logger.Warn(msg)
 	default:

From 5bf30cfe7c4b8f12ecc31cf27b9c5f118f5a5b72 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?St=C3=A9phane=20Graber?= <stgraber at ubuntu.com>
Date: Tue, 30 Oct 2018 12:57:04 -0400
Subject: [PATCH 2/6] lxd/daemon: Clarify early loggging
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/daemon.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lxd/daemon.go b/lxd/daemon.go
index 88c9c74db2..091e6ebe15 100644
--- a/lxd/daemon.go
+++ b/lxd/daemon.go
@@ -660,7 +660,7 @@ func (d *Daemon) init() error {
 		return err
 	}
 
-	logger.Infof("Loading configuration")
+	logger.Infof("Loading daemon configuration")
 	err = d.cluster.Transaction(func(tx *db.ClusterTx) error {
 		config, err := cluster.ConfigLoad(tx)
 		if err != nil {

From 71d0bbd4166b44610beaca20723e7829f1f66345 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?St=C3=A9phane=20Graber?= <stgraber at ubuntu.com>
Date: Tue, 30 Oct 2018 13:00:47 -0400
Subject: [PATCH 3/6] checkfeature: Don't log error on missing feature
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/main_checkfeature.go | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/lxd/main_checkfeature.go b/lxd/main_checkfeature.go
index 6380294a76..565902517a 100644
--- a/lxd/main_checkfeature.go
+++ b/lxd/main_checkfeature.go
@@ -111,9 +111,11 @@ void is_netnsid_aware(int *hostnetns_fd, int *newnetns_fd)
 	ret = setsockopt(sock_fd, SOL_NETLINK, NETLINK_DUMP_STRICT_CHK, &(int){1}, sizeof(int));
 	close(sock_fd);
 	if (ret < 0) {
-		(void)sprintf(errbuf, "%s", "Failed to set NETLINK_DUMP_STRICT_CHK socket option");
+		// NETLINK_DUMP_STRICT_CHK isn't supported
 		return;
 	}
+
+	// NETLINK_DUMP_STRICT_CHK is supported
 	netnsid_aware = true;
 }
 

From bbb527b2198888368591e5a96b29a9ee97d3966c Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?St=C3=A9phane=20Graber?= <stgraber at ubuntu.com>
Date: Tue, 30 Oct 2018 13:05:47 -0400
Subject: [PATCH 4/6] lxd/daemon: Improve logging of kernel features
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/daemon.go | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/lxd/daemon.go b/lxd/daemon.go
index 091e6ebe15..08e110621a 100644
--- a/lxd/daemon.go
+++ b/lxd/daemon.go
@@ -435,20 +435,20 @@ func (d *Daemon) init() error {
 		return err
 	}
 
-	/* Check if Netlink RTM_GET{ADDR,LINK} requests are fully netnsid aware. */
+	// Look for kernel features
+	logger.Infof("Kernel features:")
 	d.os.NetnsGetifaddrs = CanUseNetnsGetifaddrs()
 	if d.os.NetnsGetifaddrs {
-		logger.Debugf("Running kernel supports netnsid-based network retrieval")
+		logger.Infof(" - netnsid-based network retrieval: yes")
 	} else {
-		logger.Debugf("Running kernel does not support netnsid-based network retrieval")
+		logger.Infof(" - netnsid-based network retrieval: no")
 	}
 
-	/* Check if uevent injection is supported. */
 	d.os.UeventInjection = CanUseUeventInjection()
 	if d.os.UeventInjection {
-		logger.Debugf("Running kernel supports uevent injection")
+		logger.Infof(" - uevent injection: yes")
 	} else {
-		logger.Debugf("Running kernel does not support uevent injection")
+		logger.Infof(" - uevent injection: no")
 	}
 
 	/*
@@ -459,10 +459,10 @@ func (d *Daemon) init() error {
 	d.os.VFS3Fscaps = idmap.SupportsVFS3Fscaps("")
 	if d.os.VFS3Fscaps {
 		idmap.VFS3Fscaps = idmap.VFS3FscapsSupported
-		logger.Debugf("System supports unprivileged file capabilities")
+		logger.Infof(" - unprivileged file capabilities: yes")
 	} else {
 		idmap.VFS3Fscaps = idmap.VFS3FscapsUnsupported
-		logger.Debugf("System does not support unprivileged file capabilities")
+		logger.Infof(" - unprivileged file capabilities: no")
 	}
 
 	/* Initialize the database */

From a4655cdcd0018134eaee48f1fc5a90e8009731f1 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?St=C3=A9phane=20Graber?= <stgraber at ubuntu.com>
Date: Tue, 30 Oct 2018 13:54:52 -0400
Subject: [PATCH 5/6] lxd/daemon: Improve logging of inherited fds
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/endpoints/endpoints.go | 15 ++++++++++++---
 1 file changed, 12 insertions(+), 3 deletions(-)

diff --git a/lxd/endpoints/endpoints.go b/lxd/endpoints/endpoints.go
index 8770bd7f80..6b3a0db4c4 100644
--- a/lxd/endpoints/endpoints.go
+++ b/lxd/endpoints/endpoints.go
@@ -132,6 +132,7 @@ type Endpoints struct {
 	listeners map[kind]net.Listener // Activer listeners by endpoint type.
 	servers   map[kind]*http.Server // HTTP servers by endpoint type.
 	cert      *shared.CertInfo      // Keypair and CA to use for TLS.
+	inherited map[kind]bool         // Store whether the listener came through socket activation
 
 	systemdListenFDsStart int // First socket activation FD, for tests.
 }
@@ -148,16 +149,18 @@ func (e *Endpoints) up(config *Config) error {
 		pprof:   pprofCreateServer(),
 	}
 	e.cert = config.Cert
+	e.inherited = map[kind]bool{}
 
 	var err error
 
 	// Check for socket activation.
 	systemdListeners := util.GetListeners(e.systemdListenFDsStart)
 	if len(systemdListeners) > 0 {
-		logger.Infof("LXD is socket activated")
 		e.listeners = activatedListeners(systemdListeners, e.cert)
+		for kind, _ := range e.listeners {
+			e.inherited[kind] = true
+		}
 	} else {
-		logger.Infof("LXD isn't socket activated")
 		e.listeners = map[kind]net.Listener{}
 
 		e.listeners[local], err = localCreateListener(config.UnixSocket, config.LocalUnixSocketGroup)
@@ -177,6 +180,7 @@ func (e *Endpoints) up(config *Config) error {
 		if ok {
 			logger.Infof("Replacing inherited TCP socket with configured one")
 			listener.Close()
+			e.inherited[network] = false
 		}
 
 		// Errors here are not fatal and are just logged.
@@ -253,8 +257,13 @@ func (e *Endpoints) serveHTTP(kind kind) {
 		return
 	}
 
+	ctx := log.Ctx{"socket": listener.Addr()}
+	if e.inherited[kind] {
+		ctx["inherited"] = true
+	}
+
 	message := fmt.Sprintf(" - binding %s", descriptions[kind])
-	logger.Info(message, log.Ctx{"socket": listener.Addr()})
+	logger.Info(message, ctx)
 
 	server := e.servers[kind]
 

From 39847149aeaa81862eb5dc13af5afaa1c2e5ed50 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?St=C3=A9phane=20Graber?= <stgraber at ubuntu.com>
Date: Tue, 30 Oct 2018 14:22:27 -0400
Subject: [PATCH 6/6] shared/logging: Improve logfile output
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/endpoints/endpoints.go |  2 +-
 shared/logging/format.go   | 14 ++++++++++----
 shared/logging/log.go      | 17 ++++++++---------
 3 files changed, 19 insertions(+), 14 deletions(-)

diff --git a/lxd/endpoints/endpoints.go b/lxd/endpoints/endpoints.go
index 6b3a0db4c4..435af2550b 100644
--- a/lxd/endpoints/endpoints.go
+++ b/lxd/endpoints/endpoints.go
@@ -157,7 +157,7 @@ func (e *Endpoints) up(config *Config) error {
 	systemdListeners := util.GetListeners(e.systemdListenFDsStart)
 	if len(systemdListeners) > 0 {
 		e.listeners = activatedListeners(systemdListeners, e.cert)
-		for kind, _ := range e.listeners {
+		for kind := range e.listeners {
 			e.inherited[kind] = true
 		}
 	} else {
diff --git a/shared/logging/format.go b/shared/logging/format.go
index 250f4cdb7d..13bca7acf2 100644
--- a/shared/logging/format.go
+++ b/shared/logging/format.go
@@ -62,7 +62,7 @@ func TerminalFormat() log.Format {
 		}
 
 		// print the keys logfmt style
-		logfmt(b, r.Ctx, color)
+		logfmt(b, r.Ctx, color, false)
 		return b.Bytes()
 	})
 }
@@ -72,12 +72,16 @@ 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)
+
+		logfmt(buf, common, 0, false)
+		buf.Truncate(buf.Len() - 1)
+		buf.WriteByte(' ')
+		logfmt(buf, r.Ctx, 0, true)
 		return buf.Bytes()
 	})
 }
 
-func logfmt(buf *bytes.Buffer, ctx []interface{}, color int) {
+func logfmt(buf *bytes.Buffer, ctx []interface{}, color int, sorted bool) {
 	entries := []string{}
 
 	for i := 0; i < len(ctx); i += 2 {
@@ -95,7 +99,9 @@ func logfmt(buf *bytes.Buffer, ctx []interface{}, color int) {
 		}
 	}
 
-	sort.Strings(entries)
+	if sorted {
+		sort.Strings(entries)
+	}
 
 	for i, v := range entries {
 		if i != 0 {
diff --git a/shared/logging/log.go b/shared/logging/log.go
index 94dc47725e..673264bf1a 100644
--- a/shared/logging/log.go
+++ b/shared/logging/log.go
@@ -19,14 +19,8 @@ func GetLogger(syslog string, logfile string, verbose bool, debug bool, customHa
 	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, format)
+	syshandler = getSystemHandler(syslog, debug, LogfmtFormat())
 	if syshandler != nil {
 		handlers = append(handlers, syshandler)
 	}
@@ -42,15 +36,20 @@ func GetLogger(syslog string, logfile string, verbose bool, debug bool, customHa
 				handlers,
 				log.LvlFilterHandler(
 					log.LvlInfo,
-					log.Must.FileHandler(logfile, format),
+					log.Must.FileHandler(logfile, LogfmtFormat()),
 				),
 			)
 		} else {
-			handlers = append(handlers, log.Must.FileHandler(logfile, format))
+			handlers = append(handlers, log.Must.FileHandler(logfile, LogfmtFormat()))
 		}
 	}
 
 	// StderrHandler
+	format := LogfmtFormat()
+	if term.IsTty(os.Stderr.Fd()) {
+		format = TerminalFormat()
+	}
+
 	if verbose || debug {
 		if !debug {
 			handlers = append(


More information about the lxc-devel mailing list