fix log callstack for log messages
Jeromy committed
Apr 22, 2015 at 17:11 UTC
5aea20673431f6f4b05536416d8106f901847023
25 files changed
+223
-91
Godeps/Godeps.json
+1
-1
@@ -174,7 +174,7 @@
174
},
175
{
176
"ImportPath": "github.com/jbenet/go-logging",
177
- "Rev": "74bec4b83f6d45d1402c1e9d94c0c29e39f6e0ea"
177
+ "Rev": "128b9855511a4ea3ccbcf712695baf2bab72e134"
178
},
179
{
180
"ImportPath": "github.com/jbenet/go-msgio",
Godeps/_workspace/src/github.com/jbenet/go-logging/examples/example.go
deleted
-46
@@ -1,46 +0,0 @@
1
-package main
2
-
3
-import (
4
- "os"
5
-
6
- "github.com/ipfs/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-logging"
7
-)
8
-
9
-var log = logging.MustGetLogger("example")
10
-
11
-// Example format string. Everything except the message has a custom color
12
-// which is dependent on the log level. Many fields have a custom output
13
-// formatting too, eg. the time returns the hour down to the milli second.
14
-var format = "%{color}%{time:15:04:05.000000} %{shortfunc} ▶ %{level:.4s} %{id:03x}%{color:reset} %{message}"
15
-
16
-// Password is just an example type implementing the Redactor interface. Any
17
-// time this is logged, the Redacted() function will be called.
18
-type Password string
19
-
20
-func (p Password) Redacted() interface{} {
21
- return logging.Redact(string(p))
22
-}
23
-
24
-func main() {
25
- // Setup one stderr and one syslog backend and combine them both into one
26
- // logging backend. By default stderr is used with the standard log flag.
27
- logBackend := logging.NewLogBackend(os.Stderr, "", 0)
28
- syslogBackend, err := logging.NewSyslogBackend("")
29
- if err != nil {
30
- log.Fatal(err)
31
- }
32
- logging.SetBackend(logBackend, syslogBackend)
33
- logging.SetFormatter(logging.MustStringFormatter(format))
34
-
35
- // For "example", set the log level to DEBUG and ERROR.
36
- for _, level := range []logging.Level{logging.DEBUG, logging.ERROR} {
37
- logging.SetLevel(level, "example")
38
-
39
- log.Debug("debug %s", Password("secret"))
40
- log.Info("info")
41
- log.Notice("notice")
42
- log.Warning("warning")
43
- log.Error("err")
44
- log.Critical("crit")
45
- }
46
-}
Godeps/_workspace/src/github.com/jbenet/go-logging/examples/example.png
Binary files a/Godeps/_workspace/src/github.com/jbenet/go-logging/examples/example.png and /dev/null differ
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/.travis.yml
renamed
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/CONTRIBUTORS
renamed
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/LICENSE
renamed
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/README.md
renamed
+30
-23
@@ -1,6 +1,6 @@
1
## Golang logging library
2
3
-[](https://travis-ci.org/op/go-logging)
3
+[](https://godoc.org/github.com/op/go-logging) [](https://travis-ci.org/op/go-logging)
4
5
Package logging implements a logging infrastructure for Go. Its output format
6
is customizable and supports different logging backends like syslog, file and
@@ -28,7 +28,9 @@ var log = logging.MustGetLogger("example")
28
// Example format string. Everything except the message has a custom color
29
// which is dependent on the log level. Many fields have a custom output
30
// formatting too, eg. the time returns the hour down to the milli second.
31
-var format = "%{color}%{time:15:04:05.000000} ▶ %{level:.4s} %{id:03x}%{color:reset} %{message}"
31
+var format = logging.MustStringFormatter(
32
+ "%{color}%{time:15:04:05.000} %{shortfunc} ▶ %{level:.4s} %{id:03x}%{color:reset} %{message}",
33
+)
34
35
// Password is just an example type implementing the Redactor interface. Any
36
// time this is logged, the Redacted() function will be called.
@@ -39,27 +41,28 @@ func (p Password) Redacted() interface{} {
41
}
42
43
func main() {
42
- // Setup one stderr and one syslog backend and combine them both into one
43
- // logging backend. By default stderr is used with the standard log flag.
44
- logBackend := logging.NewLogBackend(os.Stderr, "", 0)
45
- syslogBackend, err := logging.NewSyslogBackend("")
46
- if err != nil {
47
- log.Fatal(err)
48
- }
49
- logging.SetBackend(logBackend, syslogBackend)
50
- logging.SetFormatter(logging.MustStringFormatter(format))
51
-
52
- // For "example", set the log level to DEBUG and ERROR.
53
- for _, level := range []logging.Level{logging.DEBUG, logging.ERROR} {
54
- logging.SetLevel(level, "example")
55
-
56
- log.Debug("debug %s", Password("secret"))
57
- log.Info("info")
58
- log.Notice("notice")
59
- log.Warning("warning")
60
- log.Error("err")
61
- log.Critical("crit")
62
- }
44
+ // For demo purposes, create two backend for os.Stderr.
45
+ backend1 := logging.NewLogBackend(os.Stderr, "", 0)
46
+ backend2 := logging.NewLogBackend(os.Stderr, "", 0)
47
+
48
+ // For messages written to backend2 we want to add some additional
49
+ // information to the output, including the used log level and the name of
50
+ // the function.
51
+ backend2Formatter := logging.NewBackendFormatter(backend2, format)
52
+
53
+ // Only errors and more severe messages should be sent to backend1
54
+ backend1Leveled := logging.AddModuleLevel(backend1)
55
+ backend1Leveled.SetLevel(logging.ERROR, "")
56
+
57
+ // Set the backends to be used.
58
+ logging.SetBackend(backend1Leveled, backend2Formatter)
59
+
60
+ log.Debug("debug %s", Password("secret"))
61
+ log.Info("info")
62
+ log.Notice("notice")
63
+ log.Warning("warning")
64
+ log.Error("err")
65
+ log.Critical("crit")
66
}
67
```
68
@@ -80,3 +83,7 @@ You can use `go get -u` to update the package.
83
For docs, see http://godoc.org/github.com/op/go-logging or run:
84
85
$ godoc github.com/op/go-logging
86
+
87
+## Additional resources
88
+
89
+* [wslog](https://godoc.org/github.com/cryptix/go/logging/wslog) -- exposes log messages through a WebSocket.
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/backend.go
renamed
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/example_test.go
new
+40
@@ -0,0 +1,40 @@
1
+package logging
2
+
3
+import "os"
4
+
5
+func Example() {
6
+ // This call is for testing purposes and will set the time to unix epoch.
7
+ InitForTesting(DEBUG)
8
+
9
+ var log = MustGetLogger("example")
10
+
11
+ // For demo purposes, create two backend for os.Stdout.
12
+ //
13
+ // os.Stderr should most likely be used in the real world but then the
14
+ // "Output:" check in this example would not work.
15
+ backend1 := NewLogBackend(os.Stdout, "", 0)
16
+ backend2 := NewLogBackend(os.Stdout, "", 0)
17
+
18
+ // For messages written to backend2 we want to add some additional
19
+ // information to the output, including the used log level and the name of
20
+ // the function.
21
+ var format = MustStringFormatter(
22
+ "%{time:15:04:05.000} %{shortfunc} %{level:.1s} %{message}",
23
+ )
24
+ backend2Formatter := NewBackendFormatter(backend2, format)
25
+
26
+ // Only errors and more severe messages should be sent to backend2
27
+ backend2Leveled := AddModuleLevel(backend2Formatter)
28
+ backend2Leveled.SetLevel(ERROR, "")
29
+
30
+ // Set the backends to be used and the default level.
31
+ SetBackend(backend1, backend2Leveled)
32
+
33
+ log.Debug("debug %s", "arg")
34
+ log.Error("error")
35
+
36
+ // Output:
37
+ // debug arg
38
+ // error
39
+ // 00:00:00.000 Example E error
40
+}
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/examples/example.go
new
+49
@@ -0,0 +1,49 @@
1
+package main
2
+
3
+import (
4
+ "os"
5
+
6
+ "github.com/whyrusleeping/go-logging"
7
+)
8
+
9
+var log = logging.MustGetLogger("example")
10
+
11
+// Example format string. Everything except the message has a custom color
12
+// which is dependent on the log level. Many fields have a custom output
13
+// formatting too, eg. the time returns the hour down to the milli second.
14
+var format = logging.MustStringFormatter(
15
+ "%{color}%{time:15:04:05.000} %{shortfunc} ▶ %{level:.4s} %{id:03x}%{color:reset} %{message}",
16
+)
17
+
18
+// Password is just an example type implementing the Redactor interface. Any
19
+// time this is logged, the Redacted() function will be called.
20
+type Password string
21
+
22
+func (p Password) Redacted() interface{} {
23
+ return logging.Redact(string(p))
24
+}
25
+
26
+func main() {
27
+ // For demo purposes, create two backend for os.Stderr.
28
+ backend1 := logging.NewLogBackend(os.Stderr, "", 0)
29
+ backend2 := logging.NewLogBackend(os.Stderr, "", 0)
30
+
31
+ // For messages written to backend2 we want to add some additional
32
+ // information to the output, including the used log level and the name of
33
+ // the function.
34
+ backend2Formatter := logging.NewBackendFormatter(backend2, format)
35
+
36
+ // Only errors and more severe messages should be sent to backend1
37
+ backend1Leveled := logging.AddModuleLevel(backend1)
38
+ backend1Leveled.SetLevel(logging.ERROR, "")
39
+
40
+ // Set the backends to be used.
41
+ logging.SetBackend(backend1Leveled, backend2Formatter)
42
+
43
+ log.Debug("debug %s", Password("secret"))
44
+ log.Info("info")
45
+ log.Notice("notice")
46
+ log.Warning("warning")
47
+ log.Error("err")
48
+ log.Critical("crit")
49
+}
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/examples/example.png
Binary files /dev/null and b/Godeps/_workspace/src/github.com/whyrusleeping/go-logging/examples/example.png differ
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/format.go
renamed
+21
-2
@@ -241,8 +241,6 @@ func NewStringFormatter(format string) (*stringFormatter, error) {
241
return nil, err
242
}
243
244
- formatter.def = fmter
245
-
244
return fmter, nil
245
}
246
@@ -347,3 +345,24 @@ func formatFuncName(v fmtVerb, f string) string {
345
}
346
panic("unexpected func formatter")
347
}
348
+
349
+// backendFormatter combines a backend with a specific formatter making it
350
+// possible to have different log formats for different backends.
351
+type backendFormatter struct {
352
+ b Backend
353
+ f Formatter
354
+}
355
+
356
+// NewBackendFormatter creates a new backend which makes all records that
357
+// passes through it beeing formatted by the specific formatter.
358
+func NewBackendFormatter(b Backend, f Formatter) *backendFormatter {
359
+ return &backendFormatter{b, f}
360
+}
361
+
362
+// Log implements the Log function required by the Backend interface.
363
+func (bf *backendFormatter) Log(level Level, calldepth int, r *Record) error {
364
+ // Make a shallow copy of the record and replace any formatter
365
+ r2 := *r
366
+ r2.formatter = bf.f
367
+ return bf.b.Log(level, calldepth+1, &r2)
368
+}
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/format_test.go
renamed
+26
@@ -32,6 +32,10 @@ func logAndGetLine(backend *MemoryBackend) string {
32
return MemoryRecordN(backend, 0).Formatted(1)
33
}
34
35
+func getLastLine(backend *MemoryBackend) string {
36
+ return MemoryRecordN(backend, 0).Formatted(1)
37
+}
38
+
39
func realFunc(backend *MemoryBackend) string {
40
return logAndGetLine(backend)
41
}
@@ -138,6 +142,28 @@ func TestFormatFuncName(t *testing.T) {
142
}
143
}
144
145
+func TestBackendFormatter(t *testing.T) {
146
+ InitForTesting(DEBUG)
147
+
148
+ // Create two backends and wrap one of the with a backend formatter
149
+ b1 := NewMemoryBackend(1)
150
+ b2 := NewMemoryBackend(1)
151
+
152
+ f := MustStringFormatter("%{level} %{message}")
153
+ bf := NewBackendFormatter(b2, f)
154
+
155
+ SetBackend(b1, bf)
156
+
157
+ log := MustGetLogger("module")
158
+ log.Info("foo")
159
+ if "foo" != getLastLine(b1) {
160
+ t.Errorf("Unexpected line: %s", getLastLine(b1))
161
+ }
162
+ if "INFO foo" != getLastLine(b2) {
163
+ t.Errorf("Unexpected line: %s", getLastLine(b2))
164
+ }
165
+}
166
+
167
func BenchmarkStringFormatter(b *testing.B) {
168
fmt := "%{time:2006-01-02T15:04:05} %{level:.1s} %{id:04d} %{module} %{message}"
169
f := MustStringFormatter(fmt)
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/level.go
renamed
+1
@@ -107,6 +107,7 @@ func (l *moduleLeveled) IsEnabledFor(level Level, module string) bool {
107
108
func (l *moduleLeveled) Log(level Level, calldepth int, rec *Record) (err error) {
109
if l.IsEnabledFor(level, rec.Module) {
110
+ // TODO get rid of traces of formatter here. BackendFormatter should be used.
111
rec.formatter = l.getFormatterAndCacheCurrent()
112
err = l.backend.Log(level, calldepth+1, rec)
113
}
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/level_test.go
renamed
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/log.go
renamed
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/log_test.go
renamed
+35
-12
@@ -6,6 +6,7 @@ package logging
6
7
import (
8
"bytes"
9
+ "io/ioutil"
10
"log"
11
"strings"
12
"testing"
@@ -32,21 +33,18 @@ func TestLogCalldepth(t *testing.T) {
33
}
34
35
func BenchmarkLogMemoryBackendIgnored(b *testing.B) {
35
- b.StopTimer()
36
backend := SetBackend(NewMemoryBackend(1024))
37
backend.SetLevel(INFO, "")
38
RunLogBenchmark(b)
39
}
40
41
func BenchmarkLogMemoryBackend(b *testing.B) {
42
- b.StopTimer()
42
backend := SetBackend(NewMemoryBackend(1024))
43
backend.SetLevel(DEBUG, "")
44
RunLogBenchmark(b)
45
}
46
47
func BenchmarkLogChannelMemoryBackend(b *testing.B) {
49
- b.StopTimer()
48
channelBackend := NewChannelMemoryBackend(1024)
49
backend := SetBackend(channelBackend)
50
backend.SetLevel(DEBUG, "")
@@ -54,16 +52,21 @@ func BenchmarkLogChannelMemoryBackend(b *testing.B) {
52
channelBackend.Flush()
53
}
54
55
+func BenchmarkLogLeveled(b *testing.B) {
56
+ backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
57
+ backend.SetLevel(INFO, "")
58
+
59
+ RunLogBenchmark(b)
60
+}
61
+
62
func BenchmarkLogLogBackend(b *testing.B) {
58
- b.StopTimer()
59
- backend := SetBackend(NewLogBackend(&bytes.Buffer{}, "", 0))
63
+ backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
64
backend.SetLevel(DEBUG, "")
65
RunLogBenchmark(b)
66
}
67
68
func BenchmarkLogLogBackendColor(b *testing.B) {
65
- b.StopTimer()
66
- colorizer := NewLogBackend(&bytes.Buffer{}, "", 0)
69
+ colorizer := NewLogBackend(ioutil.Discard, "", 0)
70
colorizer.Color = true
71
backend := SetBackend(colorizer)
72
backend.SetLevel(DEBUG, "")
@@ -71,15 +74,13 @@ func BenchmarkLogLogBackendColor(b *testing.B) {
74
}
75
76
func BenchmarkLogLogBackendStdFlags(b *testing.B) {
74
- b.StopTimer()
75
- backend := SetBackend(NewLogBackend(&bytes.Buffer{}, "", log.LstdFlags))
77
+ backend := SetBackend(NewLogBackend(ioutil.Discard, "", log.LstdFlags))
78
backend.SetLevel(DEBUG, "")
79
RunLogBenchmark(b)
80
}
81
82
func BenchmarkLogLogBackendLongFileFlag(b *testing.B) {
81
- b.StopTimer()
82
- backend := SetBackend(NewLogBackend(&bytes.Buffer{}, "", log.Llongfile))
83
+ backend := SetBackend(NewLogBackend(ioutil.Discard, "", log.Llongfile))
84
backend.SetLevel(DEBUG, "")
85
RunLogBenchmark(b)
86
}
@@ -88,8 +89,30 @@ func RunLogBenchmark(b *testing.B) {
89
password := Password("foo")
90
log := MustGetLogger("test")
91
91
- b.StartTimer()
92
+ b.ResetTimer()
93
for i := 0; i < b.N; i++ {
94
log.Debug("log line for %d and this is rectified: %s", i, password)
95
}
96
}
97
+
98
+func BenchmarkLogFixed(b *testing.B) {
99
+ backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
100
+ backend.SetLevel(DEBUG, "")
101
+
102
+ RunLogBenchmarkFixedString(b)
103
+}
104
+
105
+func BenchmarkLogFixedIgnored(b *testing.B) {
106
+ backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
107
+ backend.SetLevel(INFO, "")
108
+ RunLogBenchmarkFixedString(b)
109
+}
110
+
111
+func RunLogBenchmarkFixedString(b *testing.B) {
112
+ log := MustGetLogger("test")
113
+
114
+ b.ResetTimer()
115
+ for i := 0; i < b.N; i++ {
116
+ log.Debug("some random fixed text")
117
+ }
118
+}
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/logger.go
renamed
+12
-2
@@ -87,6 +87,10 @@ type Logger struct {
87
Module string
88
backend LeveledBackend
89
haveBackend bool
90
+
91
+ // ExtraCallDepth can be used to add additional call depth when getting the
92
+ // calling function. This is normally used when wrapping a logger.
93
+ ExtraCalldepth int
94
}
95
96
// SetBackend changes the backend of the logger.
@@ -146,6 +150,10 @@ func (l *Logger) IsEnabledFor(level Level) bool {
150
}
151
152
func (l *Logger) log(lvl Level, format string, args ...interface{}) {
153
+ if !l.IsEnabledFor(lvl) {
154
+ return
155
+ }
156
+
157
// Create the logging record and pass it in to the backend
158
record := &Record{
159
Id: atomic.AddUint64(&sequenceNo, 1),
@@ -161,12 +169,14 @@ func (l *Logger) log(lvl Level, format string, args ...interface{}) {
169
170
// calldepth=2 brings the stack up to the caller of the level
171
// methods, Info(), Fatal(), etc.
172
+ // ExtraCallDepth allows this to be extended further up the stack in case we
173
+ // are wrapping these methods, eg. to expose them package level
174
if l.haveBackend {
165
- l.backend.Log(lvl, 2, record)
175
+ l.backend.Log(lvl, 2+l.ExtraCalldepth, record)
176
return
177
}
178
169
- defaultBackend.Log(lvl, 2, record)
179
+ defaultBackend.Log(lvl, 2+l.ExtraCalldepth, record)
180
}
181
182
// Fatal is equivalent to l.Critical(fmt.Sprint()) followed by a call to os.Exit(1).
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/logger_test.go
renamed
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/memory.go
renamed
+2
-2
@@ -148,6 +148,7 @@ func (b *ChannelMemoryBackend) Start() {
148
}
149
150
func (b *ChannelMemoryBackend) process() {
151
+ defer b.stopWg.Done()
152
for {
153
select {
154
case rec := <-b.incoming:
@@ -155,7 +156,7 @@ func (b *ChannelMemoryBackend) process() {
156
case e := <-b.events:
157
switch e {
158
case eventStop:
158
- break
159
+ return
160
case eventFlush:
161
for len(b.incoming) > 0 {
162
b.insertRecord(<-b.incoming)
@@ -164,7 +165,6 @@ func (b *ChannelMemoryBackend) process() {
165
}
166
}
167
}
167
- b.stopWg.Done()
168
}
169
170
func (b *ChannelMemoryBackend) insertRecord(rec *Record) {
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/memory_test.go
renamed
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/multi.go
renamed
+2
@@ -4,6 +4,8 @@
4
5
package logging
6
7
+// TODO remove Level stuff from the multi logger. Do one thing.
8
+
9
// multiLogger is a log multiplexer which can be used to utilize multiple log
10
// backends at once.
11
type multiLogger struct {
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/multi_test.go
renamed
+2
-2
@@ -43,9 +43,9 @@ func TestMultiLoggerLevel(t *testing.T) {
43
leveled1.SetLevel(DEBUG, "test")
44
log.Notice("log")
45
if "log" != MemoryRecordN(log1, 0).Formatted(0) {
46
- t.Errorf("log1 not receieved")
46
+ t.Errorf("log1 not received")
47
}
48
if nil != MemoryRecordN(log2, 0) {
49
- t.Errorf("log2 receieved")
49
+ t.Errorf("log2 received")
50
}
51
}
Godeps/_workspace/src/github.com/whyrusleeping/go-logging/syslog.go
renamed
util/log.go
+2
-1
@@ -3,7 +3,7 @@ package util
3
import (
4
"os"
5
6
- logging "github.com/ipfs/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-logging"
6
+ logging "github.com/ipfs/go-ipfs/Godeps/_workspace/src/github.com/whyrusleeping/go-logging"
7
)
8
9
func init() {
@@ -80,6 +80,7 @@ func SetAllLoggers(lvl logging.Level) {
80
// Logger retrieves a particular logger
81
func Logger(name string) *logging.Logger {
82
log := logging.MustGetLogger(name)
83
+ log.ExtraCalldepth = 1
84
loggers[name] = log
85
return log
86
}