Merge pull request #1124 from ipfs/fix/logging-stack

fix log callstack for log messages

Godeps/Godeps.json

@@ -174,7 +174,7 @@
 		},
 		{
 			"ImportPath": "github.com/jbenet/go-logging",
-			"Rev": "74bec4b83f6d45d1402c1e9d94c0c29e39f6e0ea"
+			"Rev": "128b9855511a4ea3ccbcf712695baf2bab72e134"
 		},
 		{
 			"ImportPath": "github.com/jbenet/go-msgio",

Godeps/_workspace/src/github.com/jbenet/go-logging/examples/example.go

@@ -1,46 +0,0 @@
-package main
-
-import (
-	"os"
-
-	"github.com/ipfs/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-logging"
-)
-
-var log = logging.MustGetLogger("example")
-
-// Example format string. Everything except the message has a custom color
-// which is dependent on the log level. Many fields have a custom output
-// formatting too, eg. the time returns the hour down to the milli second.
-var format = "%{color}%{time:15:04:05.000000} %{shortfunc} ▶ %{level:.4s} %{id:03x}%{color:reset} %{message}"
-
-// Password is just an example type implementing the Redactor interface. Any
-// time this is logged, the Redacted() function will be called.
-type Password string
-
-func (p Password) Redacted() interface{} {
-	return logging.Redact(string(p))
-}
-
-func main() {
-	// Setup one stderr and one syslog backend and combine them both into one
-	// logging backend. By default stderr is used with the standard log flag.
-	logBackend := logging.NewLogBackend(os.Stderr, "", 0)
-	syslogBackend, err := logging.NewSyslogBackend("")
-	if err != nil {
-		log.Fatal(err)
-	}
-	logging.SetBackend(logBackend, syslogBackend)
-	logging.SetFormatter(logging.MustStringFormatter(format))
-
-	// For "example", set the log level to DEBUG and ERROR.
-	for _, level := range []logging.Level{logging.DEBUG, logging.ERROR} {
-		logging.SetLevel(level, "example")
-
-		log.Debug("debug %s", Password("secret"))
-		log.Info("info")
-		log.Notice("notice")
-		log.Warning("warning")
-		log.Error("err")
-		log.Critical("crit")
-	}
-}

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/README.md

@@ -1,6 +1,6 @@
 ## Golang logging library
 
-[![Build Status](https://travis-ci.org/op/go-logging.png)](https://travis-ci.org/op/go-logging)
+[![godoc](http://img.shields.io/badge/godoc-reference-blue.svg?style=flat)](https://godoc.org/github.com/op/go-logging) [![build](https://img.shields.io/travis/op/go-logging.svg?style=flat)](https://travis-ci.org/op/go-logging)
 
 Package logging implements a logging infrastructure for Go. Its output format
 is customizable and supports different logging backends like syslog, file and
@@ -28,7 +28,9 @@ var log = logging.MustGetLogger("example")
 // Example format string. Everything except the message has a custom color
 // which is dependent on the log level. Many fields have a custom output
 // formatting too, eg. the time returns the hour down to the milli second.
-var format = "%{color}%{time:15:04:05.000000} ▶ %{level:.4s} %{id:03x}%{color:reset} %{message}"
+var format = logging.MustStringFormatter(
+	"%{color}%{time:15:04:05.000} %{shortfunc} ▶ %{level:.4s} %{id:03x}%{color:reset} %{message}",
+)
 
 // Password is just an example type implementing the Redactor interface. Any
 // time this is logged, the Redacted() function will be called.
@@ -39,27 +41,28 @@ func (p Password) Redacted() interface{} {
 }
 
 func main() {
-	// Setup one stderr and one syslog backend and combine them both into one
-	// logging backend. By default stderr is used with the standard log flag.
-	logBackend := logging.NewLogBackend(os.Stderr, "", 0)
-	syslogBackend, err := logging.NewSyslogBackend("")
-	if err != nil {
-		log.Fatal(err)
-	}
-	logging.SetBackend(logBackend, syslogBackend)
-	logging.SetFormatter(logging.MustStringFormatter(format))
+	// For demo purposes, create two backend for os.Stderr.
+	backend1 := logging.NewLogBackend(os.Stderr, "", 0)
+	backend2 := logging.NewLogBackend(os.Stderr, "", 0)
 
-	// For "example", set the log level to DEBUG and ERROR.
-	for _, level := range []logging.Level{logging.DEBUG, logging.ERROR} {
-		logging.SetLevel(level, "example")
+	// For messages written to backend2 we want to add some additional
+	// information to the output, including the used log level and the name of
+	// the function.
+	backend2Formatter := logging.NewBackendFormatter(backend2, format)
 
-		log.Debug("debug %s", Password("secret"))
-		log.Info("info")
-		log.Notice("notice")
-		log.Warning("warning")
-		log.Error("err")
-		log.Critical("crit")
-	}
+	// Only errors and more severe messages should be sent to backend1
+	backend1Leveled := logging.AddModuleLevel(backend1)
+	backend1Leveled.SetLevel(logging.ERROR, "")
+
+	// Set the backends to be used.
+	logging.SetBackend(backend1Leveled, backend2Formatter)
+
+	log.Debug("debug %s", Password("secret"))
+	log.Info("info")
+	log.Notice("notice")
+	log.Warning("warning")
+	log.Error("err")
+	log.Critical("crit")
 }
 ```
 
@@ -80,3 +83,7 @@ You can use `go get -u` to update the package.
 For docs, see http://godoc.org/github.com/op/go-logging or run:
 
     $ godoc github.com/op/go-logging
+
+## Additional resources
+
+* [wslog](https://godoc.org/github.com/cryptix/go/logging/wslog) -- exposes log messages through a WebSocket.

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/example_test.go

@@ -0,0 +1,40 @@
+package logging
+
+import "os"
+
+func Example() {
+	// This call is for testing purposes and will set the time to unix epoch.
+	InitForTesting(DEBUG)
+
+	var log = MustGetLogger("example")
+
+	// For demo purposes, create two backend for os.Stdout.
+	//
+	// os.Stderr should most likely be used in the real world but then the
+	// "Output:" check in this example would not work.
+	backend1 := NewLogBackend(os.Stdout, "", 0)
+	backend2 := NewLogBackend(os.Stdout, "", 0)
+
+	// For messages written to backend2 we want to add some additional
+	// information to the output, including the used log level and the name of
+	// the function.
+	var format = MustStringFormatter(
+		"%{time:15:04:05.000} %{shortfunc} %{level:.1s} %{message}",
+	)
+	backend2Formatter := NewBackendFormatter(backend2, format)
+
+	// Only errors and more severe messages should be sent to backend2
+	backend2Leveled := AddModuleLevel(backend2Formatter)
+	backend2Leveled.SetLevel(ERROR, "")
+
+	// Set the backends to be used and the default level.
+	SetBackend(backend1, backend2Leveled)
+
+	log.Debug("debug %s", "arg")
+	log.Error("error")
+
+	// Output:
+	// debug arg
+	// error
+	// 00:00:00.000 Example E error
+}

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/examples/example.go

@@ -0,0 +1,49 @@
+package main
+
+import (
+	"os"
+
+	"github.com/whyrusleeping/go-logging"
+)
+
+var log = logging.MustGetLogger("example")
+
+// Example format string. Everything except the message has a custom color
+// which is dependent on the log level. Many fields have a custom output
+// formatting too, eg. the time returns the hour down to the milli second.
+var format = logging.MustStringFormatter(
+	"%{color}%{time:15:04:05.000} %{shortfunc} ▶ %{level:.4s} %{id:03x}%{color:reset} %{message}",
+)
+
+// Password is just an example type implementing the Redactor interface. Any
+// time this is logged, the Redacted() function will be called.
+type Password string
+
+func (p Password) Redacted() interface{} {
+	return logging.Redact(string(p))
+}
+
+func main() {
+	// For demo purposes, create two backend for os.Stderr.
+	backend1 := logging.NewLogBackend(os.Stderr, "", 0)
+	backend2 := logging.NewLogBackend(os.Stderr, "", 0)
+
+	// For messages written to backend2 we want to add some additional
+	// information to the output, including the used log level and the name of
+	// the function.
+	backend2Formatter := logging.NewBackendFormatter(backend2, format)
+
+	// Only errors and more severe messages should be sent to backend1
+	backend1Leveled := logging.AddModuleLevel(backend1)
+	backend1Leveled.SetLevel(logging.ERROR, "")
+
+	// Set the backends to be used.
+	logging.SetBackend(backend1Leveled, backend2Formatter)
+
+	log.Debug("debug %s", Password("secret"))
+	log.Info("info")
+	log.Notice("notice")
+	log.Warning("warning")
+	log.Error("err")
+	log.Critical("crit")
+}

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/format.go

@@ -241,8 +241,6 @@ func NewStringFormatter(format string) (*stringFormatter, error) {
 		return nil, err
 	}
 
-	formatter.def = fmter
-
 	return fmter, nil
 }
 
@@ -347,3 +345,24 @@ func formatFuncName(v fmtVerb, f string) string {
 	}
 	panic("unexpected func formatter")
 }
+
+// backendFormatter combines a backend with a specific formatter making it
+// possible to have different log formats for different backends.
+type backendFormatter struct {
+	b Backend
+	f Formatter
+}
+
+// NewBackendFormatter creates a new backend which makes all records that
+// passes through it beeing formatted by the specific formatter.
+func NewBackendFormatter(b Backend, f Formatter) *backendFormatter {
+	return &backendFormatter{b, f}
+}
+
+// Log implements the Log function required by the Backend interface.
+func (bf *backendFormatter) Log(level Level, calldepth int, r *Record) error {
+	// Make a shallow copy of the record and replace any formatter
+	r2 := *r
+	r2.formatter = bf.f
+	return bf.b.Log(level, calldepth+1, &r2)
+}

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/format_test.go

@@ -32,6 +32,10 @@ func logAndGetLine(backend *MemoryBackend) string {
 	return MemoryRecordN(backend, 0).Formatted(1)
 }
 
+func getLastLine(backend *MemoryBackend) string {
+	return MemoryRecordN(backend, 0).Formatted(1)
+}
+
 func realFunc(backend *MemoryBackend) string {
 	return logAndGetLine(backend)
 }
@@ -138,6 +142,28 @@ func TestFormatFuncName(t *testing.T) {
 	}
 }
 
+func TestBackendFormatter(t *testing.T) {
+	InitForTesting(DEBUG)
+
+	// Create two backends and wrap one of the with a backend formatter
+	b1 := NewMemoryBackend(1)
+	b2 := NewMemoryBackend(1)
+
+	f := MustStringFormatter("%{level} %{message}")
+	bf := NewBackendFormatter(b2, f)
+
+	SetBackend(b1, bf)
+
+	log := MustGetLogger("module")
+	log.Info("foo")
+	if "foo" != getLastLine(b1) {
+		t.Errorf("Unexpected line: %s", getLastLine(b1))
+	}
+	if "INFO foo" != getLastLine(b2) {
+		t.Errorf("Unexpected line: %s", getLastLine(b2))
+	}
+}
+
 func BenchmarkStringFormatter(b *testing.B) {
 	fmt := "%{time:2006-01-02T15:04:05} %{level:.1s} %{id:04d} %{module} %{message}"
 	f := MustStringFormatter(fmt)

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/level.go

@@ -107,6 +107,7 @@ func (l *moduleLeveled) IsEnabledFor(level Level, module string) bool {
 
 func (l *moduleLeveled) Log(level Level, calldepth int, rec *Record) (err error) {
 	if l.IsEnabledFor(level, rec.Module) {
+		// TODO get rid of traces of formatter here. BackendFormatter should be used.
 		rec.formatter = l.getFormatterAndCacheCurrent()
 		err = l.backend.Log(level, calldepth+1, rec)
 	}

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/log_test.go

@@ -6,6 +6,7 @@ package logging
 
 import (
 	"bytes"
+	"io/ioutil"
 	"log"
 	"strings"
 	"testing"
@@ -32,21 +33,18 @@ func TestLogCalldepth(t *testing.T) {
 }
 
 func BenchmarkLogMemoryBackendIgnored(b *testing.B) {
-	b.StopTimer()
 	backend := SetBackend(NewMemoryBackend(1024))
 	backend.SetLevel(INFO, "")
 	RunLogBenchmark(b)
 }
 
 func BenchmarkLogMemoryBackend(b *testing.B) {
-	b.StopTimer()
 	backend := SetBackend(NewMemoryBackend(1024))
 	backend.SetLevel(DEBUG, "")
 	RunLogBenchmark(b)
 }
 
 func BenchmarkLogChannelMemoryBackend(b *testing.B) {
-	b.StopTimer()
 	channelBackend := NewChannelMemoryBackend(1024)
 	backend := SetBackend(channelBackend)
 	backend.SetLevel(DEBUG, "")
@@ -54,16 +52,21 @@ func BenchmarkLogChannelMemoryBackend(b *testing.B) {
 	channelBackend.Flush()
 }
 
+func BenchmarkLogLeveled(b *testing.B) {
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
+	backend.SetLevel(INFO, "")
+
+	RunLogBenchmark(b)
+}
+
 func BenchmarkLogLogBackend(b *testing.B) {
-	b.StopTimer()
-	backend := SetBackend(NewLogBackend(&bytes.Buffer{}, "", 0))
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
 	backend.SetLevel(DEBUG, "")
 	RunLogBenchmark(b)
 }
 
 func BenchmarkLogLogBackendColor(b *testing.B) {
-	b.StopTimer()
-	colorizer := NewLogBackend(&bytes.Buffer{}, "", 0)
+	colorizer := NewLogBackend(ioutil.Discard, "", 0)
 	colorizer.Color = true
 	backend := SetBackend(colorizer)
 	backend.SetLevel(DEBUG, "")
@@ -71,15 +74,13 @@ func BenchmarkLogLogBackendColor(b *testing.B) {
 }
 
 func BenchmarkLogLogBackendStdFlags(b *testing.B) {
-	b.StopTimer()
-	backend := SetBackend(NewLogBackend(&bytes.Buffer{}, "", log.LstdFlags))
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", log.LstdFlags))
 	backend.SetLevel(DEBUG, "")
 	RunLogBenchmark(b)
 }
 
 func BenchmarkLogLogBackendLongFileFlag(b *testing.B) {
-	b.StopTimer()
-	backend := SetBackend(NewLogBackend(&bytes.Buffer{}, "", log.Llongfile))
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", log.Llongfile))
 	backend.SetLevel(DEBUG, "")
 	RunLogBenchmark(b)
 }
@@ -88,8 +89,30 @@ func RunLogBenchmark(b *testing.B) {
 	password := Password("foo")
 	log := MustGetLogger("test")
 
-	b.StartTimer()
+	b.ResetTimer()
 	for i := 0; i < b.N; i++ {
 		log.Debug("log line for %d and this is rectified: %s", i, password)
 	}
 }
+
+func BenchmarkLogFixed(b *testing.B) {
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
+	backend.SetLevel(DEBUG, "")
+
+	RunLogBenchmarkFixedString(b)
+}
+
+func BenchmarkLogFixedIgnored(b *testing.B) {
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
+	backend.SetLevel(INFO, "")
+	RunLogBenchmarkFixedString(b)
+}
+
+func RunLogBenchmarkFixedString(b *testing.B) {
+	log := MustGetLogger("test")
+
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		log.Debug("some random fixed text")
+	}
+}

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/logger.go

@@ -87,6 +87,10 @@ type Logger struct {
 	Module      string
 	backend     LeveledBackend
 	haveBackend bool
+
+	// ExtraCallDepth can be used to add additional call depth when getting the
+	// calling function. This is normally used when wrapping a logger.
+	ExtraCalldepth int
 }
 
 // SetBackend changes the backend of the logger.
@@ -146,6 +150,10 @@ func (l *Logger) IsEnabledFor(level Level) bool {
 }
 
 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),
@@ -161,12 +169,14 @@ func (l *Logger) log(lvl Level, format string, args ...interface{}) {
 
 	// calldepth=2 brings the stack up to the caller of the level
 	// methods, Info(), Fatal(), etc.
+	// ExtraCallDepth allows this to be extended further up the stack in case we
+	// are wrapping these methods, eg. to expose them package level
 	if l.haveBackend {
-		l.backend.Log(lvl, 2, record)
+		l.backend.Log(lvl, 2+l.ExtraCalldepth, record)
 		return
 	}
 
-	defaultBackend.Log(lvl, 2, record)
+	defaultBackend.Log(lvl, 2+l.ExtraCalldepth, record)
 }
 
 // Fatal is equivalent to l.Critical(fmt.Sprint()) followed by a call to os.Exit(1).

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/memory.go

@@ -148,6 +148,7 @@ func (b *ChannelMemoryBackend) Start() {
 }
 
 func (b *ChannelMemoryBackend) process() {
+	defer b.stopWg.Done()
 	for {
 		select {
 		case rec := <-b.incoming:
@@ -155,7 +156,7 @@ func (b *ChannelMemoryBackend) process() {
 		case e := <-b.events:
 			switch e {
 			case eventStop:
-				break
+				return
 			case eventFlush:
 				for len(b.incoming) > 0 {
 					b.insertRecord(<-b.incoming)
@@ -164,7 +165,6 @@ func (b *ChannelMemoryBackend) process() {
 			}
 		}
 	}
-	b.stopWg.Done()
 }
 
 func (b *ChannelMemoryBackend) insertRecord(rec *Record) {

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/multi.go

@@ -4,6 +4,8 @@
 
 package logging
 
+// TODO remove Level stuff from the multi logger. Do one thing.
+
 // multiLogger is a log multiplexer which can be used to utilize multiple log
 // backends at once.
 type multiLogger struct {

Godeps/_workspace/src/github.com/whyrusleeping/go-logging/multi_test.go

@@ -43,9 +43,9 @@ func TestMultiLoggerLevel(t *testing.T) {
 	leveled1.SetLevel(DEBUG, "test")
 	log.Notice("log")
 	if "log" != MemoryRecordN(log1, 0).Formatted(0) {
-		t.Errorf("log1 not receieved")
+		t.Errorf("log1 not received")
 	}
 	if nil != MemoryRecordN(log2, 0) {
-		t.Errorf("log2 receieved")
+		t.Errorf("log2 received")
 	}
 }

util/log.go

@@ -3,7 +3,7 @@ package util
 import (
 	"os"
 
-	logging "github.com/ipfs/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-logging"
+	logging "github.com/ipfs/go-ipfs/Godeps/_workspace/src/github.com/whyrusleeping/go-logging"
 )
 
 func init() {
@@ -80,6 +80,7 @@ func SetAllLoggers(lvl logging.Level) {
 // Logger retrieves a particular logger
 func Logger(name string) *logging.Logger {
 	log := logging.MustGetLogger(name)
+	log.ExtraCalldepth = 1
 	loggers[name] = log
 	return log
 }