From a6aa79aab2cf4f87ebe38cc7deae751e536d486f Mon Sep 17 00:00:00 2001 From: Chris Lu Date: Sat, 11 Jul 2015 01:06:58 -0700 Subject: [PATCH] merge with latest glog --- go/glog/glog.go | 194 +++++++++++++++++++++++++++++++++++++------ go/glog/glog_file.go | 4 +- go/glog/glog_test.go | 92 ++++++++++++++++++-- 3 files changed, 259 insertions(+), 31 deletions(-) diff --git a/go/glog/glog.go b/go/glog/glog.go index fb55c0356..abd5678d4 100644 --- a/go/glog/glog.go +++ b/go/glog/glog.go @@ -37,6 +37,7 @@ // // By default, all log statements write to files in a temporary directory. // This package provides several flags that modify this behavior. +// As a result, flag.Parse must be called before any logging is done. // // -logtostderr=false // Logs are written to standard error instead of to files. @@ -45,6 +46,9 @@ // -stderrthreshold=ERROR // Log events at or above this severity are logged to standard // error as well as to files. +// -log_dir="" +// Log files will be written to this directory instead of the +// default temporary directory. // // Other flags provide aids to debugging. // @@ -73,6 +77,7 @@ import ( "flag" "fmt" "io" + stdLog "log" "os" "path/filepath" "runtime" @@ -89,6 +94,9 @@ import ( // the corresponding constants in C++. type severity int32 // sync/atomic int32 +// These constants identify the log levels in order of increasing severity. +// A message written to a high-severity log file is also written to each +// lower-severity log file. const ( infoLog severity = iota warningLog @@ -307,7 +315,7 @@ func (m *moduleSpec) Set(value string) error { // isLiteral reports whether the pattern is a literal string, that is, has no metacharacters // that require filepath.Match to be called to match the pattern. func isLiteral(pattern string) bool { - return !strings.ContainsAny(pattern, `*?[]\`) + return !strings.ContainsAny(pattern, `\*?[]`) } // traceLocation represents the setting of the -log_backtrace_at flag. @@ -446,8 +454,7 @@ type loggingT struct { vmodule moduleSpec // The state of the -vmodule flag. verbosity Level // V logging level, the value of the -v flag/ - // If the logging exits, the system should still run. - // This flag is to disable the logging if logging exited. + // added by seaweedfs exited bool } @@ -466,7 +473,7 @@ func (l *loggingT) setVState(verbosity Level, filter []modulePat, setFilter bool // Turn verbosity off so V will not fire while we are in transition. logging.verbosity.set(0) // Ditto for filter length. - logging.filterLength = 0 + atomic.StoreInt32(&logging.filterLength, 0) // Set the new filters and wipe the pc->Level map if the filter has changed. if setFilter { @@ -513,7 +520,8 @@ var timeNow = time.Now // Stubbed out for testing. /* header formats a log header as defined by the C++ implementation. -It returns a buffer containing the formatted header. +It returns a buffer containing the formatted header and the user's file and line number. +The depth specifies how many stack frames above lives the source line to be identified in the log message. Log lines have this form: Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg... @@ -527,10 +535,8 @@ where the fields are defined as follows: line The line number msg The user-supplied message */ -func (l *loggingT) header(s severity) *buffer { - // Lmmdd hh:mm:ss.uuuuuu threadid file:line] - now := timeNow() - _, file, line, ok := runtime.Caller(3) // It's always the same number of frames to the user's call. +func (l *loggingT) header(s severity, depth int) (*buffer, string, int) { + _, file, line, ok := runtime.Caller(3 + depth) if !ok { file = "???" line = 1 @@ -540,6 +546,12 @@ func (l *loggingT) header(s severity) *buffer { file = file[slash+1:] } } + return l.formatHeader(s, file, line), file, line +} + +// formatHeader formats a log header using the provided file name and line number. +func (l *loggingT) formatHeader(s severity, file string, line int) *buffer { + now := timeNow() if line < 0 { line = 0 // not a real line number, but acceptable to someDigits } @@ -552,6 +564,7 @@ func (l *loggingT) header(s severity) *buffer { // It's worth about 3X. Fprintf is hard. _, month, day := now.Date() hour, minute, second := now.Clock() + // Lmmdd hh:mm:ss.uuuuuu threadid file:line] buf.tmp[0] = severityChar[s] buf.twoDigits(1, int(month)) buf.twoDigits(3, day) @@ -562,7 +575,7 @@ func (l *loggingT) header(s severity) *buffer { buf.tmp[11] = ':' buf.twoDigits(12, second) buf.tmp[14] = ' ' - buf.nDigits(5, 15, pid) // TODO: should be TID + buf.nDigits(5, 15, pid, ' ') // TODO: should be TID buf.tmp[20] = ' ' buf.Write(buf.tmp[:21]) buf.WriteString(file) @@ -585,12 +598,18 @@ func (buf *buffer) twoDigits(i, d int) { buf.tmp[i] = digits[d%10] } -// nDigits formats a zero-prefixed n-digit integer at buf.tmp[i]. -func (buf *buffer) nDigits(n, i, d int) { - for j := n - 1; j >= 0; j-- { +// nDigits formats an n-digit integer at buf.tmp[i], +// padding with pad on the left. +// It assumes d >= 0. +func (buf *buffer) nDigits(n, i, d int, pad byte) { + j := n - 1 + for ; j >= 0 && d > 0; j-- { buf.tmp[i+j] = digits[d%10] d /= 10 } + for ; j >= 0; j-- { + buf.tmp[i+j] = pad + } } // someDigits formats a zero-prefixed variable-width integer at buf.tmp[i]. @@ -610,35 +629,50 @@ func (buf *buffer) someDigits(i, d int) int { } func (l *loggingT) println(s severity, args ...interface{}) { - buf := l.header(s) + buf, file, line := l.header(s, 0) fmt.Fprintln(buf, args...) - l.output(s, buf) + l.output(s, buf, file, line, false) } func (l *loggingT) print(s severity, args ...interface{}) { - buf := l.header(s) + l.printDepth(s, 1, args...) +} + +func (l *loggingT) printDepth(s severity, depth int, args ...interface{}) { + buf, file, line := l.header(s, depth) fmt.Fprint(buf, args...) if buf.Bytes()[buf.Len()-1] != '\n' { buf.WriteByte('\n') } - l.output(s, buf) + l.output(s, buf, file, line, false) } func (l *loggingT) printf(s severity, format string, args ...interface{}) { - buf := l.header(s) + buf, file, line := l.header(s, 0) fmt.Fprintf(buf, format, args...) if buf.Bytes()[buf.Len()-1] != '\n' { buf.WriteByte('\n') } - l.output(s, buf) + l.output(s, buf, file, line, false) +} + +// printWithFileLine behaves like print but uses the provided file and line number. If +// alsoLogToStderr is true, the log message always appears on standard error; it +// will also appear in the log file unless --logtostderr is set. +func (l *loggingT) printWithFileLine(s severity, file string, line int, alsoToStderr bool, args ...interface{}) { + buf := l.formatHeader(s, file, line) + fmt.Fprint(buf, args...) + if buf.Bytes()[buf.Len()-1] != '\n' { + buf.WriteByte('\n') + } + l.output(s, buf, file, line, alsoToStderr) } // output writes the data to the log files and releases the buffer. -func (l *loggingT) output(s severity, buf *buffer) { +func (l *loggingT) output(s severity, buf *buffer, file string, line int, alsoToStderr bool) { l.mu.Lock() if l.traceLocation.isSet() { - _, file, line, ok := runtime.Caller(3) // It's always the same number of frames to the user's call (same as header). - if ok && l.traceLocation.match(file, line) { + if l.traceLocation.match(file, line) { buf.Write(stacks(false)) } } @@ -646,7 +680,7 @@ func (l *loggingT) output(s severity, buf *buffer) { if l.toStderr { os.Stderr.Write(data) } else { - if l.alsoToStderr || s >= l.stderrThreshold.get() { + if alsoToStderr || l.alsoToStderr || s >= l.stderrThreshold.get() { os.Stderr.Write(data) } if l.file[s] == nil { @@ -670,7 +704,16 @@ func (l *loggingT) output(s severity, buf *buffer) { } } if s == fatalLog { - // Make sure we see the trace for the current goroutine on standard error. + // If we got here via Exit rather than Fatal, print no stacks. + if atomic.LoadUint32(&fatalNoStacks) > 0 { + l.mu.Unlock() + timeoutFlush(10 * time.Second) + os.Exit(1) + } + // Dump all goroutine stacks before exiting. + // First, make sure we see the trace for the current goroutine on standard error. + // If -logtostderr has been specified, the loop below will do that anyway + // as the first stack in the full dump. if !l.toStderr { os.Stderr.Write(stacks(false)) } @@ -862,6 +905,54 @@ func (l *loggingT) flushAll() { } } +// CopyStandardLogTo arranges for messages written to the Go "log" package's +// default logs to also appear in the Google logs for the named and lower +// severities. Subsequent changes to the standard log's default output location +// or format may break this behavior. +// +// Valid names are "INFO", "WARNING", "ERROR", and "FATAL". If the name is not +// recognized, CopyStandardLogTo panics. +func CopyStandardLogTo(name string) { + sev, ok := severityByName(name) + if !ok { + panic(fmt.Sprintf("log.CopyStandardLogTo(%q): unrecognized severity name", name)) + } + // Set a log format that captures the user's file and line: + // d.go:23: message + stdLog.SetFlags(stdLog.Lshortfile) + stdLog.SetOutput(logBridge(sev)) +} + +// logBridge provides the Write method that enables CopyStandardLogTo to connect +// Go's standard logs to the logs provided by this package. +type logBridge severity + +// Write parses the standard logging line and passes its components to the +// logger for severity(lb). +func (lb logBridge) Write(b []byte) (n int, err error) { + var ( + file = "???" + line = 1 + text string + ) + // Split "d.go:23: message" into "d.go", "23", and "message". + if parts := bytes.SplitN(b, []byte{':'}, 3); len(parts) != 3 || len(parts[0]) < 1 || len(parts[2]) < 1 { + text = fmt.Sprintf("bad log format: %s", b) + } else { + file = string(parts[0]) + text = string(parts[2][1:]) // skip leading space + line, err = strconv.Atoi(string(parts[1])) + if err != nil { + text = fmt.Sprintf("bad line number: %s", b) + line = 1 + } + } + // printWithFileLine with alsoToStderr=true, so standard log messages + // always appear on standard error. + logging.printWithFileLine(severity(lb), file, line, true, text) + return len(b), nil +} + // setV computes and remembers the V level for a given PC // when vmodule is enabled. // File pattern matching takes the basename of the file, stripped @@ -965,6 +1056,12 @@ func Info(args ...interface{}) { logging.print(infoLog, args...) } +// InfoDepth acts as Info but uses depth to determine which call frame to log. +// InfoDepth(0, "msg") is the same as Info("msg"). +func InfoDepth(depth int, args ...interface{}) { + logging.printDepth(infoLog, depth, args...) +} + // Infoln logs to the INFO log. // Arguments are handled in the manner of fmt.Println; a newline is appended if missing. func Infoln(args ...interface{}) { @@ -983,6 +1080,12 @@ func Warning(args ...interface{}) { logging.print(warningLog, args...) } +// WarningDepth acts as Warning but uses depth to determine which call frame to log. +// WarningDepth(0, "msg") is the same as Warning("msg"). +func WarningDepth(depth int, args ...interface{}) { + logging.printDepth(warningLog, depth, args...) +} + // Warningln logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Println; a newline is appended if missing. func Warningln(args ...interface{}) { @@ -1001,6 +1104,12 @@ func Error(args ...interface{}) { logging.print(errorLog, args...) } +// ErrorDepth acts as Error but uses depth to determine which call frame to log. +// ErrorDepth(0, "msg") is the same as Error("msg"). +func ErrorDepth(depth int, args ...interface{}) { + logging.printDepth(errorLog, depth, args...) +} + // Errorln logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Println; a newline is appended if missing. func Errorln(args ...interface{}) { @@ -1020,6 +1129,12 @@ func Fatal(args ...interface{}) { logging.print(fatalLog, args...) } +// FatalDepth acts as Fatal but uses depth to determine which call frame to log. +// FatalDepth(0, "msg") is the same as Fatal("msg"). +func FatalDepth(depth int, args ...interface{}) { + logging.printDepth(fatalLog, depth, args...) +} + // Fatalln logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls os.Exit(255). // Arguments are handled in the manner of fmt.Println; a newline is appended if missing. @@ -1033,3 +1148,34 @@ func Fatalln(args ...interface{}) { func Fatalf(format string, args ...interface{}) { logging.printf(fatalLog, format, args...) } + +// fatalNoStacks is non-zero if we are to exit without dumping goroutine stacks. +// It allows Exit and relatives to use the Fatal logs. +var fatalNoStacks uint32 + +// Exit logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). +// Arguments are handled in the manner of fmt.Print; a newline is appended if missing. +func Exit(args ...interface{}) { + atomic.StoreUint32(&fatalNoStacks, 1) + logging.print(fatalLog, args...) +} + +// ExitDepth acts as Exit but uses depth to determine which call frame to log. +// ExitDepth(0, "msg") is the same as Exit("msg"). +func ExitDepth(depth int, args ...interface{}) { + atomic.StoreUint32(&fatalNoStacks, 1) + logging.printDepth(fatalLog, depth, args...) +} + +// Exitln logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). +func Exitln(args ...interface{}) { + atomic.StoreUint32(&fatalNoStacks, 1) + logging.println(fatalLog, args...) +} + +// Exitf logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). +// Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. +func Exitf(format string, args ...interface{}) { + atomic.StoreUint32(&fatalNoStacks, 1) + logging.printf(fatalLog, format, args...) +} diff --git a/go/glog/glog_file.go b/go/glog/glog_file.go index 8dcb2bc08..65075d281 100644 --- a/go/glog/glog_file.go +++ b/go/glog/glog_file.go @@ -114,8 +114,8 @@ func create(tag string, t time.Time) (f *os.File, filename string, err error) { f, err := os.Create(fname) if err == nil { symlink := filepath.Join(dir, link) - os.Remove(symlink) // ignore err - os.Symlink(fname, symlink) // ignore err + os.Remove(symlink) // ignore err + os.Symlink(name, symlink) // ignore err return f, fname, nil } lastErr = err diff --git a/go/glog/glog_test.go b/go/glog/glog_test.go index 711c37dbf..0fb376e1f 100644 --- a/go/glog/glog_test.go +++ b/go/glog/glog_test.go @@ -19,8 +19,10 @@ package glog import ( "bytes" "fmt" + stdLog "log" "path/filepath" "runtime" + "strconv" "strings" "testing" "time" @@ -96,20 +98,99 @@ func TestInfo(t *testing.T) { } } +func TestInfoDepth(t *testing.T) { + setFlags() + defer logging.swap(logging.newBuffers()) + + f := func() { InfoDepth(1, "depth-test1") } + + // The next three lines must stay together + _, _, wantLine, _ := runtime.Caller(0) + InfoDepth(0, "depth-test0") + f() + + msgs := strings.Split(strings.TrimSuffix(contents(infoLog), "\n"), "\n") + if len(msgs) != 2 { + t.Fatalf("Got %d lines, expected 2", len(msgs)) + } + + for i, m := range msgs { + if !strings.HasPrefix(m, "I") { + t.Errorf("InfoDepth[%d] has wrong character: %q", i, m) + } + w := fmt.Sprintf("depth-test%d", i) + if !strings.Contains(m, w) { + t.Errorf("InfoDepth[%d] missing %q: %q", i, w, m) + } + + // pull out the line number (between : and ]) + msg := m[strings.LastIndex(m, ":")+1:] + x := strings.Index(msg, "]") + if x < 0 { + t.Errorf("InfoDepth[%d]: missing ']': %q", i, m) + continue + } + line, err := strconv.Atoi(msg[:x]) + if err != nil { + t.Errorf("InfoDepth[%d]: bad line number: %q", i, m) + continue + } + wantLine++ + if wantLine != line { + t.Errorf("InfoDepth[%d]: got line %d, want %d", i, line, wantLine) + } + } +} + +func init() { + CopyStandardLogTo("INFO") +} + +// Test that CopyStandardLogTo panics on bad input. +func TestCopyStandardLogToPanic(t *testing.T) { + defer func() { + if s, ok := recover().(string); !ok || !strings.Contains(s, "LOG") { + t.Errorf(`CopyStandardLogTo("LOG") should have panicked: %v`, s) + } + }() + CopyStandardLogTo("LOG") +} + +// Test that using the standard log package logs to INFO. +func TestStandardLog(t *testing.T) { + setFlags() + defer logging.swap(logging.newBuffers()) + stdLog.Print("test") + if !contains(infoLog, "I", t) { + t.Errorf("Info has wrong character: %q", contents(infoLog)) + } + if !contains(infoLog, "test", t) { + t.Error("Info failed") + } +} + // Test that the header has the correct format. func TestHeader(t *testing.T) { setFlags() defer logging.swap(logging.newBuffers()) defer func(previous func() time.Time) { timeNow = previous }(timeNow) timeNow = func() time.Time { - return time.Date(2006, 1, 2, 15, 4, 5, .678901e9, time.Local) + return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local) } + pid = 1234 Info("test") - var line, pid int - n, err := fmt.Sscanf(contents(infoLog), "I0102 15:04:05 %d glog_test.go:%d] test\n", &pid, &line) - if n != 2 || err != nil { + var line int + format := "I0102 15:04:05.067890 1234 glog_test.go:%d] test\n" + n, err := fmt.Sscanf(contents(infoLog), format, &line) + if n != 1 || err != nil { t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog)) } + // Scanf treats multiple spaces as equivalent to a single space, + // so check for correct space-padding also. + want := fmt.Sprintf(format, line) + if contents(infoLog) != want { + t.Errorf("log format error: got:\n\t%q\nwant:\t%q", contents(infoLog), want) + } } // Test that an Error log goes to Warning and Info. @@ -328,6 +409,7 @@ func TestLogBacktraceAt(t *testing.T) { func BenchmarkHeader(b *testing.B) { for i := 0; i < b.N; i++ { - logging.putBuffer(logging.header(infoLog)) + buf, _, _ := logging.header(infoLog, 0) + logging.putBuffer(buf) } }