Browse code

daemon logging: unifying output and timestamps

A little refactor of the ./pkg/log so engine can have a logger instance

Signed-off-by: Vincent Batts <vbatts@redhat.com>

Vincent Batts authored on 2014/09/26 01:55:53
Showing 8 changed files
... ...
@@ -3,7 +3,7 @@
3 3
 package main
4 4
 
5 5
 import (
6
-	"log"
6
+	"github.com/docker/docker/pkg/log"
7 7
 )
8 8
 
9 9
 const CanDaemon = false
... ...
@@ -3,8 +3,6 @@
3 3
 package main
4 4
 
5 5
 import (
6
-	"log"
7
-
8 6
 	"github.com/docker/docker/builder"
9 7
 	"github.com/docker/docker/builtins"
10 8
 	"github.com/docker/docker/daemon"
... ...
@@ -12,6 +10,7 @@ import (
12 12
 	_ "github.com/docker/docker/daemon/execdriver/native"
13 13
 	"github.com/docker/docker/dockerversion"
14 14
 	"github.com/docker/docker/engine"
15
+	"github.com/docker/docker/pkg/log"
15 16
 	flag "github.com/docker/docker/pkg/mflag"
16 17
 	"github.com/docker/docker/pkg/signal"
17 18
 )
... ...
@@ -60,7 +59,7 @@ func mainDaemon() {
60 60
 		}
61 61
 	}()
62 62
 	// TODO actually have a resolved graphdriver to show?
63
-	log.Printf("docker daemon: %s %s; execdriver: %s; graphdriver: %s",
63
+	log.Infof("docker daemon: %s %s; execdriver: %s; graphdriver: %s",
64 64
 		dockerversion.VERSION,
65 65
 		dockerversion.GITCOMMIT,
66 66
 		daemonCfg.ExecDriver,
... ...
@@ -5,13 +5,13 @@ import (
5 5
 	"crypto/x509"
6 6
 	"fmt"
7 7
 	"io/ioutil"
8
-	"log"
9 8
 	"os"
10 9
 	"strings"
11 10
 
12 11
 	"github.com/docker/docker/api"
13 12
 	"github.com/docker/docker/api/client"
14 13
 	"github.com/docker/docker/dockerversion"
14
+	"github.com/docker/docker/pkg/log"
15 15
 	flag "github.com/docker/docker/pkg/mflag"
16 16
 	"github.com/docker/docker/reexec"
17 17
 	"github.com/docker/docker/utils"
... ...
@@ -103,7 +103,7 @@ func main() {
103 103
 	if err := cli.Cmd(flag.Args()...); err != nil {
104 104
 		if sterr, ok := err.(*utils.StatusError); ok {
105 105
 			if sterr.Status != "" {
106
-				log.Println(sterr.Status)
106
+				log.Infof("%s", sterr.Status)
107 107
 			}
108 108
 			os.Exit(sterr.StatusCode)
109 109
 		}
... ...
@@ -11,6 +11,7 @@ import (
11 11
 	"time"
12 12
 
13 13
 	"github.com/docker/docker/pkg/ioutils"
14
+	"github.com/docker/docker/pkg/timeutils"
14 15
 	"github.com/docker/docker/utils"
15 16
 )
16 17
 
... ...
@@ -255,6 +256,6 @@ func (eng *Engine) Logf(format string, args ...interface{}) (n int, err error) {
255 255
 	if !eng.Logging {
256 256
 		return 0, nil
257 257
 	}
258
-	prefixedFormat := fmt.Sprintf("[%s] %s\n", eng, strings.TrimRight(format, "\n"))
258
+	prefixedFormat := fmt.Sprintf("[%s] [%s] %s\n", time.Now().Format(timeutils.RFC3339NanoFixed), eng, strings.TrimRight(format, "\n"))
259 259
 	return fmt.Fprintf(eng.Stderr, prefixedFormat, args...)
260 260
 }
... ...
@@ -4,11 +4,12 @@ import (
4 4
 	"errors"
5 5
 	"fmt"
6 6
 	"net"
7
-	"os"
8 7
 	"os/exec"
9 8
 	"regexp"
10 9
 	"strconv"
11 10
 	"strings"
11
+
12
+	"github.com/docker/docker/pkg/log"
12 13
 )
13 14
 
14 15
 type Action string
... ...
@@ -175,9 +176,7 @@ func Raw(args ...string) ([]byte, error) {
175 175
 		args = append([]string{"--wait"}, args...)
176 176
 	}
177 177
 
178
-	if os.Getenv("DEBUG") != "" {
179
-		fmt.Fprintf(os.Stderr, fmt.Sprintf("[debug] %s, %v\n", path, args))
180
-	}
178
+	log.Debugf("%s, %v", path, args)
181 179
 
182 180
 	output, err := exec.Command(path, args...).CombinedOutput()
183 181
 	if err != nil {
... ...
@@ -6,18 +6,21 @@ import (
6 6
 	"os"
7 7
 	"runtime"
8 8
 	"strings"
9
+	"time"
10
+
11
+	"github.com/docker/docker/pkg/timeutils"
9 12
 )
10 13
 
11 14
 type priority int
12 15
 
13 16
 const (
14
-	errorFormat = "[%s] %s:%d %s\n"
15
-	logFormat   = "[%s] %s\n"
17
+	errorFormat = "[%s] [%s] %s:%d %s\n"
18
+	logFormat   = "[%s] [%s] %s\n"
16 19
 
17
-	fatal priority = iota
18
-	error
19
-	info
20
-	debug
20
+	fatalPriority priority = iota
21
+	errorPriority
22
+	infoPriority
23
+	debugPriority
21 24
 )
22 25
 
23 26
 // A common interface to access the Fatal method of
... ...
@@ -28,44 +31,72 @@ type Fataler interface {
28 28
 
29 29
 func (p priority) String() string {
30 30
 	switch p {
31
-	case fatal:
31
+	case fatalPriority:
32 32
 		return "fatal"
33
-	case error:
33
+	case errorPriority:
34 34
 		return "error"
35
-	case info:
35
+	case infoPriority:
36 36
 		return "info"
37
-	case debug:
37
+	case debugPriority:
38 38
 		return "debug"
39 39
 	}
40 40
 
41 41
 	return ""
42 42
 }
43 43
 
44
+var DefaultLogger = Logger{Out: os.Stdout, Err: os.Stderr}
45
+
44 46
 // Debug function, if the debug flag is set, then display. Do nothing otherwise
45 47
 // If Docker is in damon mode, also send the debug info on the socket
46
-func Debugf(format string, a ...interface{}) {
48
+func Debugf(format string, a ...interface{}) (int, error) {
49
+	return DefaultLogger.Debugf(format, a...)
50
+}
51
+
52
+func Infof(format string, a ...interface{}) (int, error) {
53
+	return DefaultLogger.Infof(format, a...)
54
+}
55
+
56
+func Errorf(format string, a ...interface{}) (int, error) {
57
+	return DefaultLogger.Errorf(format, a...)
58
+}
59
+
60
+func Fatal(a ...interface{}) {
61
+	DefaultLogger.Fatalf("%s", a...)
62
+}
63
+
64
+func Fatalf(format string, a ...interface{}) {
65
+	DefaultLogger.Fatalf(format, a...)
66
+}
67
+
68
+type Logger struct {
69
+	Err io.Writer
70
+	Out io.Writer
71
+}
72
+
73
+func (l Logger) Debugf(format string, a ...interface{}) (int, error) {
47 74
 	if os.Getenv("DEBUG") != "" {
48
-		logf(os.Stderr, debug, format, a...)
75
+		return l.logf(l.Err, debugPriority, format, a...)
49 76
 	}
77
+	return 0, nil
50 78
 }
51 79
 
52
-func Infof(format string, a ...interface{}) {
53
-	logf(os.Stdout, info, format, a...)
80
+func (l Logger) Infof(format string, a ...interface{}) (int, error) {
81
+	return l.logf(l.Out, infoPriority, format, a...)
54 82
 }
55 83
 
56
-func Errorf(format string, a ...interface{}) {
57
-	logf(os.Stderr, error, format, a...)
84
+func (l Logger) Errorf(format string, a ...interface{}) (int, error) {
85
+	return l.logf(l.Err, errorPriority, format, a...)
58 86
 }
59 87
 
60
-func Fatalf(format string, a ...interface{}) {
61
-	logf(os.Stderr, fatal, format, a...)
88
+func (l Logger) Fatalf(format string, a ...interface{}) {
89
+	l.logf(l.Err, fatalPriority, format, a...)
62 90
 	os.Exit(1)
63 91
 }
64 92
 
65
-func logf(stream io.Writer, level priority, format string, a ...interface{}) {
93
+func (l Logger) logf(stream io.Writer, level priority, format string, a ...interface{}) (int, error) {
66 94
 	var prefix string
67 95
 
68
-	if level <= error || level == debug {
96
+	if level <= errorPriority || level == debugPriority {
69 97
 		// Retrieve the stack infos
70 98
 		_, file, line, ok := runtime.Caller(2)
71 99
 		if !ok {
... ...
@@ -74,10 +105,10 @@ func logf(stream io.Writer, level priority, format string, a ...interface{}) {
74 74
 		} else {
75 75
 			file = file[strings.LastIndex(file, "/")+1:]
76 76
 		}
77
-		prefix = fmt.Sprintf(errorFormat, level.String(), file, line, format)
77
+		prefix = fmt.Sprintf(errorFormat, time.Now().Format(timeutils.RFC3339NanoFixed), level.String(), file, line, format)
78 78
 	} else {
79
-		prefix = fmt.Sprintf(logFormat, level.String(), format)
79
+		prefix = fmt.Sprintf(logFormat, time.Now().Format(timeutils.RFC3339NanoFixed), level.String(), format)
80 80
 	}
81 81
 
82
-	fmt.Fprintf(stream, prefix, a...)
82
+	return fmt.Fprintf(stream, prefix, a...)
83 83
 }
... ...
@@ -7,6 +7,8 @@ import (
7 7
 	"testing"
8 8
 )
9 9
 
10
+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})?"
11
+
10 12
 func TestLogFatalf(t *testing.T) {
11 13
 	var output *bytes.Buffer
12 14
 
... ...
@@ -16,15 +18,15 @@ func TestLogFatalf(t *testing.T) {
16 16
 		Values          []interface{}
17 17
 		ExpectedPattern string
18 18
 	}{
19
-		{fatal, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[fatal\\] testing.go:\\d+ 1 \\+ 1 = 2"},
20
-		{error, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[error\\] testing.go:\\d+ 1 \\+ 1 = 2"},
21
-		{info, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[info\\] 1 \\+ 1 = 2"},
22
-		{debug, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[debug\\] testing.go:\\d+ 1 \\+ 1 = 2"},
19
+		{fatalPriority, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[" + reRFC3339NanoFixed + "\\] \\[fatal\\] testing.go:\\d+ 1 \\+ 1 = 2"},
20
+		{errorPriority, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[" + reRFC3339NanoFixed + "\\] \\[error\\] testing.go:\\d+ 1 \\+ 1 = 2"},
21
+		{infoPriority, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[" + reRFC3339NanoFixed + "\\] \\[info\\] 1 \\+ 1 = 2"},
22
+		{debugPriority, "%d + %d = %d", []interface{}{1, 1, 2}, "\\[" + reRFC3339NanoFixed + "\\] \\[debug\\] testing.go:\\d+ 1 \\+ 1 = 2"},
23 23
 	}
24 24
 
25 25
 	for i, test := range tests {
26 26
 		output = &bytes.Buffer{}
27
-		logf(output, test.Level, test.Format, test.Values...)
27
+		DefaultLogger.logf(output, test.Level, test.Format, test.Values...)
28 28
 
29 29
 		expected := regexp.MustCompile(test.ExpectedPattern)
30 30
 		if !expected.MatchString(output.String()) {
... ...
@@ -1,11 +1,12 @@
1 1
 package signal
2 2
 
3 3
 import (
4
-	"log"
5 4
 	"os"
6 5
 	gosignal "os/signal"
7 6
 	"sync/atomic"
8 7
 	"syscall"
8
+
9
+	"github.com/docker/docker/pkg/log"
9 10
 )
10 11
 
11 12
 // Trap sets up a simplified signal "trap", appropriate for common
... ...
@@ -28,7 +29,7 @@ func Trap(cleanup func()) {
28 28
 		interruptCount := uint32(0)
29 29
 		for sig := range c {
30 30
 			go func(sig os.Signal) {
31
-				log.Printf("Received signal '%v', starting shutdown of docker...\n", sig)
31
+				log.Infof("Received signal '%v', starting shutdown of docker...", sig)
32 32
 				switch sig {
33 33
 				case os.Interrupt, syscall.SIGTERM:
34 34
 					// If the user really wants to interrupt, let him do so.
... ...
@@ -43,7 +44,7 @@ func Trap(cleanup func()) {
43 43
 							return
44 44
 						}
45 45
 					} else {
46
-						log.Printf("Force shutdown of docker, interrupting cleanup\n")
46
+						log.Infof("Force shutdown of docker, interrupting cleanup")
47 47
 					}
48 48
 				case syscall.SIGQUIT:
49 49
 				}