diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 0000000..4b7d233 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,19 @@ +# Changelog + +## 2.0.0-rc1 (2016-02-11) + +Time flies and it has been three years since this package was first released. +There have been a couple of API changes I have wanted to do for some time but +I've tried to maintain backwards compatibility. Some inconsistencies in the +API have started to show, proper vendor support in Go out of the box and +the fact that `go vet` will give warnings -- I have decided to bump the major +version. + +* Make eg. `Info` and `Infof` do different things. You want to change all calls + to `Info` with a string format go to `Infof` etc. In many cases, `go vet` will + guide you. +* `Id` in `Record` is now called `ID` + +## 1.0.0 (2013-02-21) + +Initial release diff --git a/README.md b/README.md index 65177d1..aba9398 100644 --- a/README.md +++ b/README.md @@ -7,6 +7,10 @@ is customizable and supports different logging backends like syslog, file and memory. Multiple backends can be utilized with different log levels per backend and logger. +**_NOTE:_** backwards compatibility promise have been dropped for master. Please +vendor this package or use `gopkg.in/op/go-logging.v1` for previous version. See +[changelog](CHANGELOG.md) for details. + ## Example Let's have a look at an [example](examples/example.go) which demonstrates most @@ -74,7 +78,7 @@ func main() { After this command *go-logging* is ready to use. Its source will be in: - $GOROOT/src/pkg/github.com/op/go-logging + $GOPATH/src/pkg/github.com/op/go-logging You can use `go get -u` to update the package. diff --git a/backend.go b/backend.go index 74d9201..a387392 100644 --- a/backend.go +++ b/backend.go @@ -4,8 +4,17 @@ package logging +import ( + "sync" +) + // defaultBackend is the backend used for all logging calls. var defaultBackend LeveledBackend +var defaultBackendMutex sync.Mutex + +func init() { + defaultBackendMutex = sync.Mutex{} +} // Backend is the interface which a log backend need to implement to be able to // be used as a logging backend. @@ -23,7 +32,9 @@ func SetBackend(backends ...Backend) LeveledBackend { backend = MultiLogger(backends...) } + defaultBackendMutex.Lock() defaultBackend = AddModuleLevel(backend) + defaultBackendMutex.Unlock() return defaultBackend } diff --git a/format.go b/format.go index 0fb5a4f..7160674 100644 --- a/format.go +++ b/format.go @@ -14,6 +14,7 @@ import ( "path/filepath" "regexp" "runtime" + "strconv" "strings" "sync" "time" @@ -39,6 +40,7 @@ const ( fmtVerbShortpkg fmtVerbLongfunc fmtVerbShortfunc + fmtVerbCallpath fmtVerbLevelColor // Keep last, there are no match for these below. @@ -60,6 +62,7 @@ var fmtVerbs = []string{ "shortpkg", "longfunc", "shortfunc", + "callpath", "color", } @@ -79,6 +82,7 @@ var defaultVerbsLayout = []string{ "s", "s", "s", + "0", "", } @@ -159,6 +163,7 @@ type stringFormatter struct { // %{message} Message (string) // %{longfile} Full file name and line number: /a/b/c/d.go:23 // %{shortfile} Final file name element and line number: d.go:23 +// %{callpath} Callpath like main.a.b.c...c "..." meaning recursive call ~. meaning truncated path // %{color} ANSI color based on log level // // For normal types, the output can be customized by using the 'verbs' defined @@ -175,6 +180,9 @@ type stringFormatter struct { // "%{color:bold}%{time:15:04:05} %{level:-8s}%{color:reset} %{message}" will // just colorize the time and level, leaving the message uncolored. // +// For the 'callpath' verb, the output can be adjusted to limit the printing +// the stack depth. i.e. '%{callpath:3}' will print '~.a.b.c' +// // Colors on Windows is unfortunately not supported right now and is currently // a no-op. // @@ -187,6 +195,7 @@ type stringFormatter struct { // %{shortpkg} Base package path, eg. go-logging // %{longfunc} Full function name, eg. littleEndian.PutUint32 // %{shortfunc} Base function name, eg. PutUint32 +// %{callpath} Call function path, eg. main.a.b.c func NewStringFormatter(format string) (Formatter, error) { var fmter = &stringFormatter{} @@ -211,12 +220,12 @@ func NewStringFormatter(format string) (Formatter, error) { } // Handle layout customizations or use the default. If this is not for the - // time or color formatting, we need to prefix with %. + // time, color formatting or callpath, we need to prefix with %. layout := defaultVerbsLayout[verb] if m[4] != -1 { layout = format[m[4]:m[5]] } - if verb != fmtVerbTime && verb != fmtVerbLevelColor { + if verb != fmtVerbTime && verb != fmtVerbLevelColor && verb != fmtVerbCallpath { layout = "%" + layout } @@ -233,12 +242,13 @@ func NewStringFormatter(format string) (Formatter, error) { if err != nil { panic(err) } + testFmt := "hello %s" r := &Record{ - Id: 12345, + ID: 12345, Time: t, Module: "logger", - fmt: "hello %s", - args: []interface{}{"go"}, + Args: []interface{}{"go"}, + fmt: &testFmt, } if err := fmter.Format(0, r, &bytes.Buffer{}); err != nil { return nil, err @@ -269,6 +279,12 @@ func (f *stringFormatter) Format(calldepth int, r *Record, output io.Writer) err output.Write([]byte(r.Time.Format(part.layout))) } else if part.verb == fmtVerbLevelColor { doFmtVerbLevelColor(part.layout, r.Level, output) + } else if part.verb == fmtVerbCallpath { + depth, err := strconv.Atoi(part.layout) + if err != nil { + depth = 0 + } + output.Write([]byte(formatCallpath(calldepth+1, depth))) } else { var v interface{} switch part.verb { @@ -276,7 +292,7 @@ func (f *stringFormatter) Format(calldepth int, r *Record, output io.Writer) err v = r.Level break case fmtVerbID: - v = r.Id + v = r.ID break case fmtVerbPid: v = pid @@ -343,6 +359,39 @@ func formatFuncName(v fmtVerb, f string) string { panic("unexpected func formatter") } +func formatCallpath(calldepth int, depth int) string { + v := "" + callers := make([]uintptr, 64) + n := runtime.Callers(calldepth+2, callers) + oldPc := callers[n-1] + + start := n - 3 + if depth > 0 && start >= depth { + start = depth - 1 + v += "~." + } + recursiveCall := false + for i := start; i >= 0; i-- { + pc := callers[i] + if oldPc == pc { + recursiveCall = true + continue + } + oldPc = pc + if recursiveCall { + recursiveCall = false + v += ".." + } + if i < start { + v += "." + } + if f := runtime.FuncForPC(pc); f != nil { + v += formatFuncName(fmtVerbShortfunc, f.Name()) + } + } + return v +} + // backendFormatter combines a backend with a specific formatter making it // possible to have different log formats for different backends. type backendFormatter struct { diff --git a/level.go b/level.go index 98dd191..ca2a918 100644 --- a/level.go +++ b/level.go @@ -70,6 +70,7 @@ type moduleLeveled struct { backend Backend formatter Formatter once sync.Once + mutex sync.Mutex } // AddModuleLevel wraps a log backend with knobs to have different log levels @@ -81,6 +82,7 @@ func AddModuleLevel(backend Backend) LeveledBackend { leveled = &moduleLeveled{ levels: make(map[string]Level), backend: backend, + mutex: sync.Mutex{}, } } return leveled @@ -88,6 +90,7 @@ func AddModuleLevel(backend Backend) LeveledBackend { // GetLevel returns the log level for the given module. func (l *moduleLeveled) GetLevel(module string) Level { + l.mutex.Lock() level, exists := l.levels[module] if exists == false { level, exists = l.levels[""] @@ -96,12 +99,15 @@ func (l *moduleLeveled) GetLevel(module string) Level { level = DEBUG } } + l.mutex.Unlock() return level } // SetLevel sets the log level for the given module. func (l *moduleLeveled) SetLevel(level Level, module string) { + l.mutex.Lock() l.levels[module] = level + l.mutex.Unlock() } // IsEnabledFor will return true if logging is enabled for the given module. diff --git a/log_nix.go b/log_nix.go index c114117..435574d 100644 --- a/log_nix.go +++ b/log_nix.go @@ -14,8 +14,9 @@ import ( // LogBackend utilizes the standard log module. type LogBackend struct { - Logger *log.Logger - Color bool + Logger *log.Logger + Color bool + ColorConfig []string } // NewLogBackend creates a new LogBackend. @@ -26,8 +27,13 @@ func NewLogBackend(out io.Writer, prefix string, flag int) *LogBackend { // Log implements the Backend interface. func (b *LogBackend) Log(level Level, calldepth int, rec *Record) error { if b.Color { + col := colors[level] + if len(b.ColorConfig) > int(level) && b.ColorConfig[level] != "" { + col = b.ColorConfig[level] + } + buf := &bytes.Buffer{} - buf.Write([]byte(colors[level])) + buf.Write([]byte(col)) buf.Write([]byte(rec.Formatted(calldepth + 1))) buf.Write([]byte("\033[0m")) // For some reason, the Go logger arbitrarily decided "2" was the correct @@ -37,3 +43,4 @@ func (b *LogBackend) Log(level Level, calldepth int, rec *Record) error { return b.Logger.Output(calldepth+2, rec.Formatted(calldepth+1)) } + diff --git a/log_test.go b/log_test.go index 0ddcdf3..c7a645f 100644 --- a/log_test.go +++ b/log_test.go @@ -32,6 +32,51 @@ func TestLogCalldepth(t *testing.T) { } } +func c(log *Logger) { log.Info("test callpath") } +func b(log *Logger) { c(log) } +func a(log *Logger) { b(log) } + +func rec(log *Logger, r int) { + if r == 0 { + a(log) + return + } + rec(log, r-1) +} + +func testCallpath(t *testing.T, format string, expect string) { + buf := &bytes.Buffer{} + SetBackend(NewLogBackend(buf, "", log.Lshortfile)) + SetFormatter(MustStringFormatter(format)) + + logger := MustGetLogger("test") + rec(logger, 6) + + parts := strings.SplitN(buf.String(), " ", 3) + + // Verify that the correct filename is registered by the stdlib logger + if !strings.HasPrefix(parts[0], "log_test.go:") { + t.Errorf("incorrect filename: %s", parts[0]) + } + // Verify that the correct callpath is registered by go-logging + if !strings.HasPrefix(parts[1], expect) { + t.Errorf("incorrect callpath: %s", parts[1]) + } + // Verify that the correct message is registered by go-logging + if !strings.HasPrefix(parts[2], "test callpath") { + t.Errorf("incorrect message: %s", parts[2]) + } +} + +func TestLogCallpath(t *testing.T) { + testCallpath(t, "%{callpath} %{message}", "TestLogCallpath.testCallpath.rec...rec.a.b.c") + testCallpath(t, "%{callpath:-1} %{message}", "TestLogCallpath.testCallpath.rec...rec.a.b.c") + testCallpath(t, "%{callpath:0} %{message}", "TestLogCallpath.testCallpath.rec...rec.a.b.c") + testCallpath(t, "%{callpath:1} %{message}", "~.c") + testCallpath(t, "%{callpath:2} %{message}", "~.b.c") + testCallpath(t, "%{callpath:3} %{message}", "~.a.b.c") +} + func BenchmarkLogMemoryBackendIgnored(b *testing.B) { backend := SetBackend(NewMemoryBackend(1024)) backend.SetLevel(INFO, "") diff --git a/logger.go b/logger.go index b430124..553ba4a 100644 --- a/logger.go +++ b/logger.go @@ -41,16 +41,16 @@ var ( // was created, an increasing id, filename and line and finally the actual // formatted log line. type Record struct { - Id uint64 + ID uint64 Time time.Time Module string Level Level + Args []interface{} // message is kept as a pointer to have shallow copies update this once // needed. message *string - args []interface{} - fmt string + fmt *string formatter Formatter formatted string } @@ -69,12 +69,20 @@ func (r *Record) Formatted(calldepth int) string { func (r *Record) Message() string { if r.message == nil { // Redact the arguments that implements the Redactor interface - for i, arg := range r.args { + for i, arg := range r.Args { if redactor, ok := arg.(Redactor); ok == true { - r.args[i] = redactor.Redacted() + r.Args[i] = redactor.Redacted() } } - msg := fmt.Sprintf(r.fmt, r.args...) + var buf bytes.Buffer + if r.fmt != nil { + fmt.Fprintf(&buf, *r.fmt, r.Args...) + } else { + // use Fprintln to make sure we always get space between arguments + fmt.Fprintln(&buf, r.Args...) + buf.Truncate(buf.Len() - 1) // strip newline + } + msg := buf.String() r.message = &msg } return *r.message @@ -132,19 +140,19 @@ func (l *Logger) IsEnabledFor(level Level) bool { return defaultBackend.IsEnabledFor(level, l.Module) } -func (l *Logger) log(lvl Level, format string, args ...interface{}) { +func (l *Logger) log(lvl Level, format *string, args ...interface{}) { if !l.IsEnabledFor(lvl) { return } // Create the logging record and pass it in to the backend record := &Record{ - Id: atomic.AddUint64(&sequenceNo, 1), + ID: atomic.AddUint64(&sequenceNo, 1), Time: timeNow(), Module: l.Module, Level: lvl, fmt: format, - args: args, + Args: args, } // TODO use channels to fan out the records to all backends? @@ -159,89 +167,93 @@ func (l *Logger) log(lvl Level, format string, args ...interface{}) { return } + defaultBackendMutex.Lock() defaultBackend.Log(lvl, 2+l.ExtraCalldepth, record) + defaultBackendMutex.Unlock() } // Fatal is equivalent to l.Critical(fmt.Sprint()) followed by a call to os.Exit(1). func (l *Logger) Fatal(args ...interface{}) { - s := fmt.Sprint(args...) - l.log(CRITICAL, "%s", s) + l.log(CRITICAL, nil, args...) os.Exit(1) } // Fatalf is equivalent to l.Critical followed by a call to os.Exit(1). func (l *Logger) Fatalf(format string, args ...interface{}) { - l.log(CRITICAL, format, args...) + l.log(CRITICAL, &format, args...) os.Exit(1) } // Panic is equivalent to l.Critical(fmt.Sprint()) followed by a call to panic(). func (l *Logger) Panic(args ...interface{}) { - s := fmt.Sprint(args...) - l.log(CRITICAL, "%s", s) - panic(s) + l.log(CRITICAL, nil, args...) + panic(fmt.Sprint(args...)) } // Panicf is equivalent to l.Critical followed by a call to panic(). func (l *Logger) Panicf(format string, args ...interface{}) { - s := fmt.Sprintf(format, args...) - l.log(CRITICAL, "%s", s) - panic(s) + l.log(CRITICAL, &format, args...) + panic(fmt.Sprintf(format, args...)) } // Critical logs a message using CRITICAL as log level. -func (l *Logger) Critical(format string, args ...interface{}) { - l.log(CRITICAL, format, args...) +func (l *Logger) Critical(args ...interface{}) { + l.log(CRITICAL, nil, args...) +} + +// Criticalf logs a message using CRITICAL as log level. +func (l *Logger) Criticalf(format string, args ...interface{}) { + l.log(CRITICAL, &format, args...) } // Error logs a message using ERROR as log level. -func (l *Logger) Error(format string, args ...interface{}) { - l.log(ERROR, format, args...) +func (l *Logger) Error(args ...interface{}) { + l.log(ERROR, nil, args...) } // Errorf logs a message using ERROR as log level. func (l *Logger) Errorf(format string, args ...interface{}) { - l.log(ERROR, format, args...) + l.log(ERROR, &format, args...) } // Warning logs a message using WARNING as log level. -func (l *Logger) Warning(format string, args ...interface{}) { - l.log(WARNING, format, args...) +func (l *Logger) Warning(args ...interface{}) { + l.log(WARNING, nil, args...) } // Warningf logs a message using WARNING as log level. func (l *Logger) Warningf(format string, args ...interface{}) { - l.log(WARNING, format, args...) + l.log(WARNING, &format, args...) } // Notice logs a message using NOTICE as log level. -func (l *Logger) Notice(format string, args ...interface{}) { - l.log(NOTICE, format, args...) +func (l *Logger) Notice(args ...interface{}) { + l.log(NOTICE, nil, args...) } // Noticef logs a message using NOTICE as log level. func (l *Logger) Noticef(format string, args ...interface{}) { - l.log(NOTICE, format, args...) + l.log(NOTICE, &format, args...) } // Info logs a message using INFO as log level. -func (l *Logger) Info(format string, args ...interface{}) { - l.log(INFO, format, args...) +func (l *Logger) Info(args ...interface{}) { + l.log(INFO, nil, args...) } // Infof logs a message using INFO as log level. func (l *Logger) Infof(format string, args ...interface{}) { - l.log(INFO, format, args...) + l.log(INFO, &format, args...) } // Debug logs a message using DEBUG as log level. -func (l *Logger) Debug(format string, args ...interface{}) { - l.log(DEBUG, format, args...) +func (l *Logger) Debug(args ...interface{}) { + l.log(DEBUG, nil, args...) } // Debugf logs a message using DEBUG as log level. func (l *Logger) Debugf(format string, args ...interface{}) { - l.log(DEBUG, format, args...) + l.log(DEBUG, &format, args...) } func init() { diff --git a/logger_test.go b/logger_test.go index 77ff0d8..b9f7fe7 100644 --- a/logger_test.go +++ b/logger_test.go @@ -20,8 +20,8 @@ func TestSequenceNoOverflow(t *testing.T) { log := MustGetLogger("test") log.Debug("test") - if MemoryRecordN(backend, 0).Id != 0 { - t.Errorf("Unexpected sequence no: %v", MemoryRecordN(backend, 0).Id) + if MemoryRecordN(backend, 0).ID != 0 { + t.Errorf("Unexpected sequence no: %v", MemoryRecordN(backend, 0).ID) } } @@ -29,12 +29,22 @@ func TestRedact(t *testing.T) { backend := InitForTesting(DEBUG) password := Password("123456") log := MustGetLogger("test") - log.Debug("foo %s", password) + log.Debug("foo", password) if "foo ******" != MemoryRecordN(backend, 0).Formatted(0) { t.Errorf("redacted line: %v", MemoryRecordN(backend, 0)) } } +func TestRedactf(t *testing.T) { + backend := InitForTesting(DEBUG) + password := Password("123456") + log := MustGetLogger("test") + log.Debugf("foo %s", password) + if "foo ******" != MemoryRecordN(backend, 0).Formatted(0) { + t.Errorf("redacted line: %v", MemoryRecordN(backend, 0).Formatted(0)) + } +} + func TestPrivateBackend(t *testing.T) { stdBackend := InitForTesting(DEBUG) log := MustGetLogger("test") @@ -49,5 +59,4 @@ func TestPrivateBackend(t *testing.T) { if "to private baсkend" == MemoryRecordN(privateBackend, 0).Formatted(0) { t.Error("logged to defaultBackend:", MemoryRecordN(privateBackend, 0)) } - } diff --git a/memory_test.go b/memory_test.go index fe5a82e..c2fe6c8 100644 --- a/memory_test.go +++ b/memory_test.go @@ -51,7 +51,7 @@ func TestMemoryBackend(t *testing.T) { // Run 13 times, the resulting vector should be [5..12] for i := 0; i < 13; i++ { - log.Info("%d", i) + log.Infof("%d", i) } if 8 != backend.size { @@ -89,7 +89,7 @@ func TestChannelMemoryBackend(t *testing.T) { // Run 13 times, the resulting vector should be [5..12] for i := 0; i < 13; i++ { - log.Info("%d", i) + log.Infof("%d", i) } backend.Flush()