Configure log-format earlier, and small refactor

Some messages are logged before the logrus format was set,
therefore resulting in inconsistent log-message formatting
during startup;

Before this patch;

```
dockerd --experimental
WARN[0000] Running experimental build
INFO[2018-11-24T11:24:05.615249610Z] libcontainerd: started new containerd process  pid=132
INFO[2018-11-24T11:24:05.615348322Z] parsed scheme: "unix"                         module=grpc
...
```

With this patch applied;

```
dockerd --experimental
WARN[2018-11-24T13:41:51.199057259Z] Running experimental build
INFO[2018-11-24T13:41:51.200412645Z] libcontainerd: started new containerd process  pid=293
INFO[2018-11-24T13:41:51.200523051Z] parsed scheme: "unix"                         module=grpc
```

Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

cmd/dockerd/daemon.go

@@ -83,6 +83,11 @@ func (cli *DaemonCli) start(opts *daemonOptions) (err error) {
 	if cli.Config, err = loadDaemonCliConfig(opts); err != nil {
 		return err
 	}
+
+	if err := configureDaemonLogs(cli.Config); err != nil {
+		return err
+	}
+
 	cli.configFile = &opts.configFile
 	cli.flags = opts.flags
 
@@ -94,12 +99,6 @@ func (cli *DaemonCli) start(opts *daemonOptions) (err error) {
 		logrus.Warn("Running experimental build")
 	}
 
-	logrus.SetFormatter(&logrus.TextFormatter{
-		TimestampFormat: jsonmessage.RFC3339NanoFixed,
-		DisableColors:   cli.Config.RawLogs,
-		FullTimestamp:   true,
-	})
-
 	system.InitLCOW(cli.Config.Experimental)
 
 	if err := setDefaultUmask(); err != nil {
@@ -471,9 +470,6 @@ func loadDaemonCliConfig(opts *daemonOptions) (*config.Config, error) {
 		conf.TLS = true
 	}
 
-	// ensure that the log level is the one set after merging configurations
-	setLogLevel(conf.LogLevel)
-
 	return conf, nil
 }
 
@@ -670,3 +666,22 @@ func systemContainerdRunning() bool {
 	_, err := os.Lstat(containerddefaults.DefaultAddress)
 	return err == nil
 }
+
+// configureDaemonLogs sets the logrus logging level and formatting
+func configureDaemonLogs(conf *config.Config) error {
+	if conf.LogLevel != "" {
+		lvl, err := logrus.ParseLevel(conf.LogLevel)
+		if err != nil {
+			return fmt.Errorf("unable to parse logging level: %s", conf.LogLevel)
+		}
+		logrus.SetLevel(lvl)
+	} else {
+		logrus.SetLevel(logrus.InfoLevel)
+	}
+	logrus.SetFormatter(&logrus.TextFormatter{
+		TimestampFormat: jsonmessage.RFC3339NanoFixed,
+		DisableColors:   conf.RawLogs,
+		FullTimestamp:   true,
+	})
+	return nil
+}

cmd/dockerd/daemon_test.go

@@ -146,7 +146,6 @@ func TestLoadDaemonCliConfigWithLogLevel(t *testing.T) {
 	assert.NilError(t, err)
 	assert.Assert(t, loadedConfig != nil)
 	assert.Check(t, is.Equal("warn", loadedConfig.LogLevel))
-	assert.Check(t, is.Equal(logrus.WarnLevel, logrus.GetLevel()))
 }
 
 func TestLoadDaemonConfigWithEmbeddedOptions(t *testing.T) {
@@ -180,3 +179,22 @@ func TestLoadDaemonConfigWithRegistryOptions(t *testing.T) {
 	assert.Check(t, is.Len(loadedConfig.Mirrors, 1))
 	assert.Check(t, is.Len(loadedConfig.InsecureRegistries, 1))
 }
+
+func TestConfigureDaemonLogs(t *testing.T) {
+	conf := &config.Config{}
+	err := configureDaemonLogs(conf)
+	assert.NilError(t, err)
+	assert.Check(t, is.Equal(logrus.InfoLevel, logrus.GetLevel()))
+
+	conf.LogLevel = "warn"
+	err = configureDaemonLogs(conf)
+	assert.NilError(t, err)
+	assert.Check(t, is.Equal(logrus.WarnLevel, logrus.GetLevel()))
+
+	conf.LogLevel = "foobar"
+	err = configureDaemonLogs(conf)
+	assert.Error(t, err, "unable to parse logging level: foobar")
+
+	// log level should not be changed after a failure
+	assert.Check(t, is.Equal(logrus.WarnLevel, logrus.GetLevel()))
+}

cmd/dockerd/docker.go

@@ -8,6 +8,7 @@ import (
 	"github.com/docker/docker/cli"
 	"github.com/docker/docker/daemon/config"
 	"github.com/docker/docker/dockerversion"
+	"github.com/docker/docker/pkg/jsonmessage"
 	"github.com/docker/docker/pkg/reexec"
 	"github.com/docker/docker/pkg/term"
 	"github.com/moby/buildkit/util/apicaps"
@@ -54,6 +55,12 @@ func main() {
 		return
 	}
 
+	// initial log formatting; this setting is updated after the daemon configuration is loaded.
+	logrus.SetFormatter(&logrus.TextFormatter{
+		TimestampFormat: jsonmessage.RFC3339NanoFixed,
+		FullTimestamp:   true,
+	})
+
 	// Set terminal emulation based on platform as required.
 	_, stdout, stderr := term.StdStreams()
 

cmd/dockerd/options.go

@@ -1,7 +1,6 @@
 package main
 
 import (
-	"fmt"
 	"os"
 	"path/filepath"
 
@@ -9,7 +8,6 @@ import (
 	"github.com/docker/docker/daemon/config"
 	"github.com/docker/docker/opts"
 	"github.com/docker/go-connections/tlsconfig"
-	"github.com/sirupsen/logrus"
 	"github.com/spf13/pflag"
 )
 
@@ -106,17 +104,3 @@ func (o *daemonOptions) SetDefaultOptions(flags *pflag.FlagSet) {
 		}
 	}
 }
-
-// setLogLevel sets the logrus logging level
-func setLogLevel(logLevel string) {
-	if logLevel != "" {
-		lvl, err := logrus.ParseLevel(logLevel)
-		if err != nil {
-			fmt.Fprintf(os.Stderr, "Unable to parse logging level: %s\n", logLevel)
-			os.Exit(1)
-		}
-		logrus.SetLevel(lvl)
-	} else {
-		logrus.SetLevel(logrus.InfoLevel)
-	}
-}