From 92df943fbf225d78b160babb36e9c6fd38cdc0d0 Mon Sep 17 00:00:00 2001 From: Vincent Batts Date: Thu, 25 Sep 2014 12:55:53 -0400 Subject: [PATCH] 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 --- docker/client.go | 2 +- docker/daemon.go | 5 +-- docker/docker.go | 4 +- engine/engine.go | 3 +- pkg/iptables/iptables.go | 7 ++-- pkg/log/log.go | 79 ++++++++++++++++++++++++++++------------ pkg/log/log_test.go | 12 +++--- pkg/signal/trap.go | 7 ++-- 8 files changed, 76 insertions(+), 43 deletions(-) diff --git a/docker/client.go b/docker/client.go index 27001cc557..58a67067bf 100644 --- a/docker/client.go +++ b/docker/client.go @@ -3,7 +3,7 @@ package main import ( - "log" + "github.com/docker/docker/pkg/log" ) const CanDaemon = false diff --git a/docker/daemon.go b/docker/daemon.go index eef17efdc4..2f65878472 100644 --- a/docker/daemon.go +++ b/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, diff --git a/docker/docker.go b/docker/docker.go index e906b2043e..473e424731 100644 --- a/docker/docker.go +++ b/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" @@ -103,7 +103,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) } diff --git a/engine/engine.go b/engine/engine.go index 5c708d405f..769f644a17 100644 --- a/engine/engine.go +++ b/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...) } diff --git a/pkg/iptables/iptables.go b/pkg/iptables/iptables.go index 88d8b5f352..b8d9e56705 100644 --- a/pkg/iptables/iptables.go +++ b/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 { diff --git a/pkg/log/log.go b/pkg/log/log.go index 53be6cf182..b06d958cb1 100644 --- a/pkg/log/log.go +++ b/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...) } diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go index 83ba5fd27c..4f5b3f82ed 100644 --- a/pkg/log/log_test.go +++ b/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()) { diff --git a/pkg/signal/trap.go b/pkg/signal/trap.go index cbdfd1ff17..42ddb4d277 100644 --- a/pkg/signal/trap.go +++ b/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: }