Skip to content

Commit

Permalink
Add WithIndirectCaller method.
Browse files Browse the repository at this point in the history
  • Loading branch information
efritz committed Oct 7, 2019
1 parent 4f0bfe2 commit e96cc14
Show file tree
Hide file tree
Showing 11 changed files with 211 additions and 39 deletions.
16 changes: 15 additions & 1 deletion README.md
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,20 @@ requestLogger := logger.WithFields(nacelle.LogFields{
requestLogger.Info("Accepted request from %s", remoteAddr)
```

### Caller Stack

Sometimes it is useful to define helper functions that logs messages for you in a common way (applying common context, performing additional behavior on errors, etc). Unfortunately, this can interfere with the way the caller file and line number are discovered. The logger has a `WithIndirectCaller` method that will increase the depth used when scanning the stack for callers. This should be used at each log location that aggregates log calls (e.g. any place where knowing this source location would not be helpful).

```go
func logForMe(message string) {
parentLogger.WithIndirectCaller().Log(message)
}

logForMe("foobar")
```

Using a logger instance directly does not require this additional hint.

### Adapters

Nacelle ships with a handful of useful logging adapters. These are extensions of the logger interface that add additional behavior or additional structured data. A custom adapter can be created for behavior that is not provided here.
Expand Down Expand Up @@ -59,7 +73,7 @@ logger := NewRollupAdapter(
time.Second, // rollup window
)

for i:=0; i < 10000; i++ {
for i := 0; i < 10000; i++ {
logger.Debug("Some problem here!")
}
```
Expand Down
2 changes: 1 addition & 1 deletion base_logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -67,7 +67,7 @@ func (s *baseShim) LogWithFields(level LogLevel, fields LogFields, format string
}

seq := atomic.AddUint64(&s.wrapper.sequence, 1)
fields = addCaller(fields).normalizeTimeValues()
fields = fields.normalizeTimeValues()
fields["sequenceNumber"] = seq

s.wrapper.logger.Log(
Expand Down
2 changes: 1 addition & 1 deletion base_logger_mock_test.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

8 changes: 4 additions & 4 deletions caller.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,20 +6,20 @@ import (
"strings"
)

func addCaller(fields LogFields) LogFields {
func addCaller(fields LogFields, depth int) LogFields {
if fields == nil {
fields = LogFields{}
}

if _, ok := fields["caller"]; !ok {
fields["caller"] = getCaller()
fields["caller"] = getCaller(depth)
}

return fields
}

func getCaller() string {
for i := 3; ; i++ {
func getCaller(depth int) string {
for i := 3 + depth; ; i++ {
_, file, line, _ := runtime.Caller(i)
if file == "<autogenerated>" {
continue
Expand Down
41 changes: 41 additions & 0 deletions caller_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -126,6 +126,46 @@ func (s *CallerSuite) testRollup(init func(*Config) (Logger, error)) {
Expect(data2["caller"]).To(Equal(fmt.Sprintf("log/caller_test.go:%d", start)))
}

func (s *CallerSuite) testAdapter(init func(*Config) (Logger, error)) {
stderr := captureStderr(func() {
logger, err := init(&Config{LogLevel: "info", LogEncoding: "json"})
Expect(err).To(BeNil())
// Push caller stack out once for each indirection
indirectLogger := logger.WithIndirectCaller().WithIndirectCaller().WithIndirectCaller()

log3 := func(message string) { indirectLogger.Info(message) }
log2 := func(message string) { log3(message) }
log1 := func(message string) { log2(message) }

log1("X")
log1("Y")
log1("Z")
logger.Sync()
})

lines := strings.Split(strings.TrimSpace(stderr), "\n")
Expect(lines).To(HaveLen(3))

var (
data1 = LogFields{}
data2 = LogFields{}
data3 = LogFields{}
)

Expect(json.Unmarshal([]byte(lines[0]), &data1)).To(BeNil())
Expect(json.Unmarshal([]byte(lines[1]), &data2)).To(BeNil())
Expect(json.Unmarshal([]byte(lines[2]), &data3)).To(BeNil())

// Note: this value refers to the line number containing `logger.Info("X")` in
// the function literal above. If code is added before that line, this value
// must be updated.
start := 140

Expect(data1["caller"]).To(Equal(fmt.Sprintf("log/caller_test.go:%d", start+0)))
Expect(data2["caller"]).To(Equal(fmt.Sprintf("log/caller_test.go:%d", start+1)))
Expect(data3["caller"]).To(Equal(fmt.Sprintf("log/caller_test.go:%d", start+2)))
}

func (s *CallerSuite) testFields(init func(*Config) (Logger, error)) {
s.testBasic(func(config *Config) (Logger, error) {
logger, err := init(config)
Expand Down Expand Up @@ -172,6 +212,7 @@ func (s *CallerSuite) TestTrimPath(t sweet.T) {
}

func (s *CallerSuite) TestLogger(t sweet.T) { s.testBasic(InitLogger) }
func (s *CallerSuite) TestAdapter(t sweet.T) { s.testAdapter(InitLogger) }
func (s *CallerSuite) TestLoggerWithFields(t sweet.T) { s.testFields(InitLogger) }
func (s *CallerSuite) TestLoggerWithReplayAdapter(t sweet.T) { s.testReplayAdapter(InitLogger) }
func (s *CallerSuite) TestLoggerWithRollupAdapter(t sweet.T) { s.testRollupAdapter(InitLogger) }
Expand Down
1 change: 1 addition & 0 deletions logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package log

type (
Logger interface {
WithIndirectCaller() Logger
WithFields(LogFields) Logger
LogWithFields(LogLevel, LogFields, string, ...interface{})
Sync() error
Expand Down
2 changes: 1 addition & 1 deletion main_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,7 @@ func (ts *testShim) LogWithFields(level LogLevel, fields LogFields, format strin

ts.messages = append(ts.messages, &logMessage{
level: level,
fields: addCaller(fields),
fields: fields,
format: format,
args: args,
})
Expand Down
Loading

0 comments on commit e96cc14

Please sign in to comment.