improved logging formats.

R=rsc
DELTA=210  (118 added, 60 deleted, 32 changed)
OCL=23508
CL=23518

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))
 }

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);
+	}
 }