Merge pull request #2 from go-nacelle/configurable-depth

Configurable depth

README.md

@@ -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(1).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.
@@ -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!")
 }
 ```
@@ -71,6 +85,7 @@ The following environment variables change the behavior of the loggers when usin
 | Environment Variable         | Default | Description |
 | ---------------------------- | ------- | ----------- |
 | LOG_COLORIZE                 | true    | Colorize log messages by level when true. Works with `console` encoding only. |
+| LOG_JSON_FIELD_NAMES         |         | A JSON-encoded map to rename the fields for `message`, `timestamp`, and/or `level`. |
 | LOG_DISPLAY_FIELDS           | true    | Omit log fields from output when false. Works with `console` encoding only. |
 | LOG_DISPLAY_MULTILINE_FIELDS | false   | Print fields on one line when true, one field per line when false. Works with `console` encoding only. |
 | LOG_ENCODING                 | console | `console` for human-readable output and `json` for JSON-formatted output. |

base_logger.go

@@ -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(

caller.go

@@ -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

caller_test.go

@@ -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(3)
+
+		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)
@@ -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) }

config.go

@@ -9,7 +9,7 @@ type Config struct {
 	LogLevel                  string            `env:"log_level" file:"log_level" default:"info"`
 	LogEncoding               string            `env:"log_encoding" file:"log_encoding" default:"console"`
 	LogColorize               bool              `env:"log_colorize" file:"log_colorize" default:"true"`
-	LogJSONFieldNames         map[string]string `env:"log_json_field_names" file:"log_json_field_names"` // TODO - not in config
+	LogJSONFieldNames         map[string]string `env:"log_json_field_names" file:"log_json_field_names"`
 	LogInitialFields          LogFields         `env:"log_fields" file:"log_fields"`
 	LogShortTime              bool              `env:"log_short_time" file:"log_short_time" default:"false"`
 	LogDisplayFields          bool              `env:"log_display_fields" file:"log_display_fields" default:"true"`

logger.go

@@ -2,6 +2,7 @@ package log
 
 type (
 	Logger interface {
+		WithIndirectCaller(frames int) Logger
 		WithFields(LogFields) Logger
 		LogWithFields(LogLevel, LogFields, string, ...interface{})
 		Sync() error

main_test.go

@@ -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,
 	})