From 646b3b5c02f15fa057a0ba9dcff2f5ccb2ff11ed Mon Sep 17 00:00:00 2001 From: Rob Pike Date: Mon, 26 Jan 2009 15:34:16 -0800 Subject: [PATCH] improved logging formats. R=rsc DELTA=210 (118 added, 60 deleted, 32 changed) OCL=23508 CL=23518 --- src/lib/log.go | 137 +++++++++++++++++++++++++++++--------------- src/lib/log_test.go | 89 ++++++++++++++++------------ 2 files changed, 142 insertions(+), 84 deletions(-) diff --git a/src/lib/log.go b/src/lib/log.go index a54ba9f98b..1134ace32c 100644 --- a/src/lib/log.go +++ b/src/lib/log.go @@ -18,73 +18,116 @@ import ( "time"; ) -// Lshortname can be or'd in to cause only the last element of the file name to be printed. const ( + // Flags Lok = iota; Lexit; // terminate execution when written Lcrash; // crash (panic) when written - Lshortname = 1 << 5; + // Bits or'ed together to control what's printed. There is no control over the + // order they appear (the order listed here) or the format they present (as + // described in the comments). A colon appears after these items: + // 2009/0123 01:23:23.123123 /a/b/c/d.go:23: message + Ldate = 1 << iota; // the date: 2009/0123 + Ltime; // the time: 01:23:23 + Lmicroseconds; // microsecond resolution: 01:23:23.123123. assumes Ltime. + Llongfile; // full file name and line number: /a/b/c/d.go:23 + Lshortfile; // final file name element and line number: d.go:23. overrides Llongfile + lAllBits = Ldate | Ltime | Lmicroseconds | Llongfile | Lshortfile; ) type Logger struct { out0 io.Write; out1 io.Write; + prefix string; flag int; } -func NewLogger(out0, out1 io.Write, flag int) *Logger { - return &Logger{out0, out1, flag} +func NewLogger(out0, out1 io.Write, prefix string, flag int) *Logger { + return &Logger{out0, out1, prefix, flag} } var ( - stdout = NewLogger(os.Stdout, nil, Lok); - stderr = NewLogger(os.Stderr, nil, Lok); - exit = NewLogger(os.Stderr, nil, Lexit); - crash = NewLogger(os.Stderr, nil, Lcrash); + stdout = NewLogger(os.Stdout, nil, "", Lok|Ldate|Ltime); + stderr = NewLogger(os.Stderr, nil, "", Lok|Ldate|Ltime); + exit = NewLogger(os.Stderr, nil, "", Lexit|Ldate|Ltime); + crash = NewLogger(os.Stderr, nil, "", Lcrash|Ldate|Ltime); ) -func timestamp(ns int64) string { - t := time.SecondsToLocalTime(ns/1e9); - // why are time fields private? - s := t.RFC1123(); - return s[5:12] + s[17:25]; // TODO(r): placeholder. this gives "24 Jan 15:50:18" +var shortnames = make(map[string] string) // cache of short names to avoid allocation. + +// Cheap integer to fixed-width decimal ASCII. Use a negative width to avoid zero-padding +func itoa(i int, wid int) string { + var u uint = uint(i); + if u == 0 && wid <= 1 { + return "0" + } + + // Assemble decimal in reverse order. + var b [32]byte; + bp := len(b); + for ; u > 0 || wid > 0; u /= 10 { + bp--; + wid--; + b[bp] = byte(u%10) + '0'; + } + + return string(b[bp:len(b)]) } -var shortnames = make(map[string] string) // cache of short names to avoid allocation. +func (l *Logger) formatHeader(ns int64, calldepth int) string { + h := l.prefix; + if l.flag & (Ldate | Ltime | Lmicroseconds) != 0 { + t := time.SecondsToLocalTime(ns/1e9); + if l.flag & (Ldate) != 0 { + h += itoa(int(t.Year), 4) + "/" + itoa(t.Month, 2) + itoa(t.Day, 2) + " " + } + if l.flag & (Ltime | Lmicroseconds) != 0 { + h += itoa(t.Hour, 2) + ":" + itoa(t.Minute, 2) + ":" + itoa(t.Second, 2); + if l.flag & Lmicroseconds != 0 { + h += "." + itoa(int(ns % 1e9)/1e3, 6); + } + h += " "; + } + } + if l.flag & (Lshortfile | Llongfile) != 0 { + pc, file, line, ok := sys.Caller(calldepth); + if ok { + if l.flag & Lshortfile != 0 { + short, ok := shortnames[file]; + if !ok { + short = file; + for i := len(file) - 1; i > 0; i-- { + if file[i] == '/' { + short = file[i+1:len(file)]; + break; + } + } + shortnames[file] = short; + } + file = short; + } + } else { + file = "???"; + line = 0; + } + h += file + ":" + itoa(line, -1) + ": "; + } + return h; +} // The calldepth is provided for generality, although at the moment on all paths it will be 2. -func (l *Logger) output(calldepth int, s string) { +func (l *Logger) Output(calldepth int, s string) { now := time.Nanoseconds(); // get this early. newline := "\n"; if len(s) > 0 && s[len(s)-1] == '\n' { newline = "" } - pc, file, line, ok := sys.Caller(calldepth); - if ok { - if l.flag & Lshortname == Lshortname { - short, ok := shortnames[file]; - if !ok { - short = file; - for i := len(file) - 1; i > 0; i-- { - if file[i] == '/' { - short = file[i+1:len(file)]; - shortnames[file] = short; - break; - } - } - } - file = short; - } - } else { - file = "???"; - line = 0; - } - s = fmt.Sprintf("%s %s:%d: %s%s", timestamp(now), file, line, s, newline); + s = l.formatHeader(now, calldepth+1) + s + newline; io.WriteString(l.out0, s); if l.out1 != nil { io.WriteString(l.out1, s); } - switch l.flag & ^Lshortname { + switch l.flag & ^lAllBits { case Lcrash: panic("log: fatal error"); case Lexit: @@ -94,42 +137,42 @@ func (l *Logger) output(calldepth int, s string) { // Basic methods on Logger, analogous to Printf and Print func (l *Logger) Logf(format string, v ...) { - l.output(2, fmt.Sprintf(format, v)) + l.Output(2, fmt.Sprintf(format, v)) } func (l *Logger) Log(v ...) { - l.output(2, fmt.Sprintln(v)) + l.Output(2, fmt.Sprintln(v)) } // Helper functions for lightweight simple logging to predefined Loggers. func Stdout(v ...) { - stdout.output(2, fmt.Sprint(v)) + stdout.Output(2, fmt.Sprint(v)) } func Stderr(v ...) { - stdout.output(2, fmt.Sprintln(v)) + stdout.Output(2, fmt.Sprintln(v)) } func Stdoutf(format string, v ...) { - stdout.output(2, fmt.Sprintf(format, v)) + stdout.Output(2, fmt.Sprintf(format, v)) } func Stderrf(format string, v ...) { - stderr.output(2, fmt.Sprintf(format, v)) + stderr.Output(2, fmt.Sprintf(format, v)) } func Exit(v ...) { - exit.output(2, fmt.Sprintln(v)) + exit.Output(2, fmt.Sprintln(v)) } func Exitf(format string, v ...) { - exit.output(2, fmt.Sprintf(format, v)) + exit.Output(2, fmt.Sprintf(format, v)) } func Crash(v ...) { - crash.output(2, fmt.Sprintln(v)) + crash.Output(2, fmt.Sprintln(v)) } func Crashf(format string, v ...) { - crash.output(2, fmt.Sprintf(format, v)) + crash.Output(2, fmt.Sprintf(format, v)) } diff --git a/src/lib/log_test.go b/src/lib/log_test.go index f0cfb13bce..d813941bb8 100644 --- a/src/lib/log_test.go +++ b/src/lib/log_test.go @@ -10,61 +10,76 @@ import ( "bufio"; "log"; "os"; + "regexp"; "testing"; ) -func test(t *testing.T, flag int, expect string) { - fd0, fd1, err1 := os.Pipe(); - if err1 != nil { - t.Error("pipe", err1); - } - buf, err2 := bufio.NewBufRead(fd0); - if err2 != nil { - t.Error("bufio.NewBufRead", err2); - } - l := NewLogger(fd1, nil, flag); - l.Log("hello", 23, "world"); /// the line number of this line needs to be placed in the expect strings - line, err3 := buf.ReadLineString('\n', false); - if line[len(line)-len(expect):len(line)] != expect { - t.Error("log output should be ...", expect, "; is " , line); - } - t.Log(line); - fd0.Close(); - fd1.Close(); -} +const ( + Rdate = `[0-9][0-9][0-9][0-9]/[0-9][0-9][0-9][0-9]`; + Rtime = `[0-9][0-9]:[0-9][0-9]:[0-9][0-9]`; + Rmicroseconds = `\.[0-9][0-9][0-9][0-9][0-9][0-9]`; + Rline = `[0-9]+:`; + Rlongfile = `/[A-Za-z0-9_/]+\.go:` + Rline; + Rshortfile = `[A-Za-z0-9_]+\.go:` + Rline; +) -func TestRegularLog(t *testing.T) { - test(t, Lok, "/go/src/lib/log_test.go:25: hello 23 world"); +type tester struct { + flag int; + prefix string; + pattern string; // regexp that log output must match; we add ^ and expected_text$ always } -func TestShortNameLog(t *testing.T) { - test(t, Lok|Lshortname, " log_test.go:25: hello 23 world") +var tests = []tester { + // individual pieces: + tester{ 0, "", "" }, + tester{ 0, "XXX", "XXX" }, + tester{ Lok|Ldate, "", Rdate+" " }, + tester{ Lok|Ltime, "", Rtime+" " }, + tester{ Lok|Ltime|Lmicroseconds, "", Rtime+Rmicroseconds+" " }, + tester{ Lok|Lmicroseconds, "", Rtime+Rmicroseconds+" " }, // microsec implies time + tester{ Lok|Llongfile, "", Rlongfile+" " }, + tester{ Lok|Lshortfile, "", Rshortfile+" " }, + tester{ Lok|Llongfile|Lshortfile, "", Rshortfile+" " }, // shortfile overrides longfile + // everything at once: + tester{ Lok|Ldate|Ltime|Lmicroseconds|Llongfile, "XXX", "XXX"+Rdate+" "+Rtime+Rmicroseconds+" "+Rlongfile+" " }, + tester{ Lok|Ldate|Ltime|Lmicroseconds|Lshortfile, "XXX", "XXX"+Rdate+" "+Rtime+Rmicroseconds+" "+Rshortfile+" " }, } -func testFormatted(t *testing.T, flag int, expect string) { +// Test using Log("hello", 23, "world") or using Logf("hello %d world", 23) +func testLog(t *testing.T, flag int, prefix string, pattern string, useLogf bool) { fd0, fd1, err1 := os.Pipe(); if err1 != nil { - t.Error("pipe", err1); + t.Fatal("pipe", err1); } buf, err2 := bufio.NewBufRead(fd0); if err2 != nil { - t.Error("bufio.NewBufRead", err2); + t.Fatal("bufio.NewBufRead", err2); + } + l := NewLogger(fd1, nil, prefix, flag); + if useLogf { + l.Logf("hello %d world", 23); + } else { + l.Log("hello", 23, "world"); } - l := NewLogger(fd1, nil, flag); - l.Logf("hello %d world", 23); /// the line number of this line needs to be placed in the expect strings line, err3 := buf.ReadLineString('\n', false); - if line[len(line)-len(expect):len(line)] != expect { - t.Error("log output should be ...", expect, "; is " , line); + if err3 != nil { + t.Fatal("log error", err3); + } + pattern = "^"+pattern+"hello 23 world$"; + matched, err4 := regexp.Match(pattern, line); + if err4 != nil{ + t.Fatal("pattern did not compile:", err4); + } + if !matched { + t.Errorf("log output should match %q is %q", pattern, line); } - t.Log(line); fd0.Close(); fd1.Close(); } -func TestRegularLogFormatted(t *testing.T) { - testFormatted(t, Lok, "/go/src/lib/log_test.go:53: hello 23 world"); -} - -func TestShortNameLogFormatted(t *testing.T) { - testFormatted(t, Lok|Lshortname, " log_test.go:53: hello 23 world") +func TestAllLog(t *testing.T) { + for i, testcase := range(tests) { + testLog(t, testcase.flag, testcase.prefix, testcase.pattern, false); + testLog(t, testcase.flag, testcase.prefix, testcase.pattern, true); + } } -- 2.48.1