Merge pull request #8238 from vbatts/vbatts-daemon_timestamps

daemon logging: unifying output and timestamps

docker/client.go

@@ -3,7 +3,7 @@
 package main
 
 import (
-	"log"
+	"github.com/docker/docker/pkg/log"
 )
 
 const CanDaemon = false

docker/daemon.go

@@ -3,8 +3,6 @@
 package main
 
 import (
-	"log"
-
 	"github.com/docker/docker/builder"
 	"github.com/docker/docker/builtins"
 	"github.com/docker/docker/daemon"
@@ -12,6 +10,7 @@ import (
 	_ "github.com/docker/docker/daemon/execdriver/native"
 	"github.com/docker/docker/dockerversion"
 	"github.com/docker/docker/engine"
+	"github.com/docker/docker/pkg/log"
 	flag "github.com/docker/docker/pkg/mflag"
 	"github.com/docker/docker/pkg/signal"
 )
@@ -60,7 +59,7 @@ func mainDaemon() {
 		}
 	}()
 	// TODO actually have a resolved graphdriver to show?
-	log.Printf("docker daemon: %s %s; execdriver: %s; graphdriver: %s",
+	log.Infof("docker daemon: %s %s; execdriver: %s; graphdriver: %s",
 		dockerversion.VERSION,
 		dockerversion.GITCOMMIT,
 		daemonCfg.ExecDriver,

docker/docker.go

@@ -5,13 +5,13 @@ import (
 	"crypto/x509"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"os"
 	"strings"
 
 	"github.com/docker/docker/api"
 	"github.com/docker/docker/api/client"
 	"github.com/docker/docker/dockerversion"
+	"github.com/docker/docker/pkg/log"
 	flag "github.com/docker/docker/pkg/mflag"
 	"github.com/docker/docker/reexec"
 	"github.com/docker/docker/utils"
@@ -104,7 +104,7 @@ func main() {
 	if err := cli.Cmd(flag.Args()...); err != nil {
 		if sterr, ok := err.(*utils.StatusError); ok {
 			if sterr.Status != "" {
-				log.Println(sterr.Status)
+				log.Infof("%s", sterr.Status)
 			}
 			os.Exit(sterr.StatusCode)
 		}

engine/engine.go

@@ -11,6 +11,7 @@ import (
 	"time"
 
 	"github.com/docker/docker/pkg/ioutils"
+	"github.com/docker/docker/pkg/timeutils"
 	"github.com/docker/docker/utils"
 )
 
@@ -255,6 +256,6 @@ func (eng *Engine) Logf(format string, args ...interface{}) (n int, err error) {
 	if !eng.Logging {
 		return 0, nil
 	}
-	prefixedFormat := fmt.Sprintf("[%s] %s\n", eng, strings.TrimRight(format, "\n"))
+	prefixedFormat := fmt.Sprintf("[%s] [%s] %s\n", time.Now().Format(timeutils.RFC3339NanoFixed), eng, strings.TrimRight(format, "\n"))
 	return fmt.Fprintf(eng.Stderr, prefixedFormat, args...)
 }

pkg/iptables/iptables.go

@@ -4,11 +4,12 @@ import (
 	"errors"
 	"fmt"
 	"net"
-	"os"
 	"os/exec"
 	"regexp"
 	"strconv"
 	"strings"
+
+	"github.com/docker/docker/pkg/log"
 )
 
 type Action string
@@ -175,9 +176,7 @@ func Raw(args ...string) ([]byte, error) {
 		args = append([]string{"--wait"}, args...)
 	}
 
-	if os.Getenv("DEBUG") != "" {
-		fmt.Fprintf(os.Stderr, fmt.Sprintf("[debug] %s, %v\n", path, args))
-	}
+	log.Debugf("%s, %v", path, args)
 
 	output, err := exec.Command(path, args...).CombinedOutput()
 	if err != nil {

pkg/log/log.go

@@ -6,18 +6,21 @@ import (
 	"os"
 	"runtime"
 	"strings"
+	"time"
+
+	"github.com/docker/docker/pkg/timeutils"
 )
 
 type priority int
 
 const (
-	errorFormat = "[%s] %s:%d %s\n"
-	logFormat   = "[%s] %s\n"
+	errorFormat = "[%s] [%s] %s:%d %s\n"
+	logFormat   = "[%s] [%s] %s\n"
 
-	fatal priority = iota
-	error
-	info
-	debug
+	fatalPriority priority = iota
+	errorPriority
+	infoPriority
+	debugPriority
 )
 
 // A common interface to access the Fatal method of
@@ -28,44 +31,72 @@ type Fataler interface {
 
 func (p priority) String() string {
 	switch p {
-	case fatal:
+	case fatalPriority:
 		return "fatal"
-	case error:
+	case errorPriority:
 		return "error"
-	case info:
+	case infoPriority:
 		return "info"
-	case debug:
+	case debugPriority:
 		return "debug"
 	}
 
 	return ""
 }
 
+var DefaultLogger = Logger{Out: os.Stdout, Err: os.Stderr}
+
 // Debug function, if the debug flag is set, then display. Do nothing otherwise
 // If Docker is in damon mode, also send the debug info on the socket
-func Debugf(format string, a ...interface{}) {
-	if os.Getenv("DEBUG") != "" {
-		logf(os.Stderr, debug, format, a...)
-	}
+func Debugf(format string, a ...interface{}) (int, error) {
+	return DefaultLogger.Debugf(format, a...)
 }
 
-func Infof(format string, a ...interface{}) {
-	logf(os.Stdout, info, format, a...)
+func Infof(format string, a ...interface{}) (int, error) {
+	return DefaultLogger.Infof(format, a...)
 }
 
-func Errorf(format string, a ...interface{}) {
-	logf(os.Stderr, error, format, a...)
+func Errorf(format string, a ...interface{}) (int, error) {
+	return DefaultLogger.Errorf(format, a...)
+}
+
+func Fatal(a ...interface{}) {
+	DefaultLogger.Fatalf("%s", a...)
 }
 
 func Fatalf(format string, a ...interface{}) {
-	logf(os.Stderr, fatal, format, a...)
+	DefaultLogger.Fatalf(format, a...)
+}
+
+type Logger struct {
+	Err io.Writer
+	Out io.Writer
+}
+
+func (l Logger) Debugf(format string, a ...interface{}) (int, error) {
+	if os.Getenv("DEBUG") != "" {
+		return l.logf(l.Err, debugPriority, format, a...)
+	}
+	return 0, nil
+}
+
+func (l Logger) Infof(format string, a ...interface{}) (int, error) {
+	return l.logf(l.Out, infoPriority, format, a...)
+}
+
+func (l Logger) Errorf(format string, a ...interface{}) (int, error) {
+	return l.logf(l.Err, errorPriority, format, a...)
+}
+
+func (l Logger) Fatalf(format string, a ...interface{}) {
+	l.logf(l.Err, fatalPriority, format, a...)
 	os.Exit(1)
 }
 
-func logf(stream io.Writer, level priority, format string, a ...interface{}) {
+func (l Logger) logf(stream io.Writer, level priority, format string, a ...interface{}) (int, error) {
 	var prefix string
 
-	if level <= error || level == debug {
+	if level <= errorPriority || level == debugPriority {
 		// Retrieve the stack infos
 		_, file, line, ok := runtime.Caller(2)
 		if !ok {
@@ -74,10 +105,10 @@ func logf(stream io.Writer, level priority, format string, a ...interface{}) {
 		} else {
 			file = file[strings.LastIndex(file, "/")+1:]
 		}
-		prefix = fmt.Sprintf(errorFormat, level.String(), file, line, format)
+		prefix = fmt.Sprintf(errorFormat, time.Now().Format(timeutils.RFC3339NanoFixed), level.String(), file, line, format)
 	} else {
-		prefix = fmt.Sprintf(logFormat, level.String(), format)
+		prefix = fmt.Sprintf(logFormat, time.Now().Format(timeutils.RFC3339NanoFixed), level.String(), format)
 	}
 
-	fmt.Fprintf(stream, prefix, a...)
+	return fmt.Fprintf(stream, prefix, a...)
 }

pkg/log/log_test.go

@@ -7,6 +7,8 @@ import (
 	"testing"
 )
 
+var reRFC3339NanoFixed = "[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}.[0-9]{9}.([0-9]{2}:[0-9]{2})?"
+
 func TestLogFatalf(t *testing.T) {
 	var output *bytes.Buffer
 
@@ -16,15 +18,15 @@ func TestLogFatalf(t *testing.T) {
 		Values          []interface{}
 		ExpectedPattern string
 	}{
-		{fatal, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[fatal\\] testing.go:\\d+ 1 \\+ 1 = 2"},
-		{error, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[error\\] testing.go:\\d+ 1 \\+ 1 = 2"},
-		{info, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[info\\] 1 \\+ 1 = 2"},
-		{debug, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[debug\\] testing.go:\\d+ 1 \\+ 1 = 2"},
+		{fatalPriority, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[" + reRFC3339NanoFixed + "\\] \\[fatal\\] testing.go:\\d+ 1 \\+ 1 = 2"},
+		{errorPriority, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[" + reRFC3339NanoFixed + "\\] \\[error\\] testing.go:\\d+ 1 \\+ 1 = 2"},
+		{infoPriority, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[" + reRFC3339NanoFixed + "\\] \\[info\\] 1 \\+ 1 = 2"},
+		{debugPriority, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[" + reRFC3339NanoFixed + "\\] \\[debug\\] testing.go:\\d+ 1 \\+ 1 = 2"},
 	}
 
 	for i, test := range tests {
 		output = &bytes.Buffer{}
-		logf(output, test.Level, test.Format, test.Values...)
+		DefaultLogger.logf(output, test.Level, test.Format, test.Values...)
 
 		expected := regexp.MustCompile(test.ExpectedPattern)
 		if !expected.MatchString(output.String()) {

pkg/signal/trap.go

@@ -1,11 +1,12 @@
 package signal
 
 import (
-	"log"
 	"os"
 	gosignal "os/signal"
 	"sync/atomic"
 	"syscall"
+
+	"github.com/docker/docker/pkg/log"
 )
 
 // Trap sets up a simplified signal "trap", appropriate for common
@@ -28,7 +29,7 @@ func Trap(cleanup func()) {
 		interruptCount := uint32(0)
 		for sig := range c {
 			go func(sig os.Signal) {
-				log.Printf("Received signal '%v', starting shutdown of docker...\n", sig)
+				log.Infof("Received signal '%v', starting shutdown of docker...", sig)
 				switch sig {
 				case os.Interrupt, syscall.SIGTERM:
 					// If the user really wants to interrupt, let him do so.
@@ -43,7 +44,7 @@ func Trap(cleanup func()) {
 							return
 						}
 					} else {
-						log.Printf("Force shutdown of docker, interrupting cleanup\n")
+						log.Infof("Force shutdown of docker, interrupting cleanup")
 					}
 				case syscall.SIGQUIT:
 				}