add WithTraceAt() method to adjust Trace() log level

The Trace() and Stop() methods for an Entry default to Info-level
logging, and previously didn't offer a way to log non-errors at any
other level. Add a WithTraceAt() method to allow that level to be
configured.

fixes apex#93

entry.go

@@ -15,19 +15,21 @@ var Now = time.Now
 
 // Entry represents a single log entry.
 type Entry struct {
-	Logger    *Logger   `json:"-"`
-	Fields    Fields    `json:"fields"`
-	Level     Level     `json:"level"`
-	Timestamp time.Time `json:"timestamp"`
-	Message   string    `json:"message"`
-	start     time.Time
-	fields    []Fields
+	Logger     *Logger   `json:"-"`
+	Fields     Fields    `json:"fields"`
+	Level      Level     `json:"level"`
+	Timestamp  time.Time `json:"timestamp"`
+	Message    string    `json:"message"`
+	start      time.Time
+	fields     []Fields
+	traceLevel Level
 }
 
 // NewEntry returns a new entry for `log`.
 func NewEntry(log *Logger) *Entry {
 	return &Entry{
-		Logger: log,
+		Logger:     log,
+		traceLevel: InfoLevel,
 	}
 }
 
@@ -37,8 +39,9 @@ func (e *Entry) WithFields(fields Fielder) *Entry {
 	f = append(f, e.fields...)
 	f = append(f, fields.Fields())
 	return &Entry{
-		Logger: e.Logger,
-		fields: f,
+		Logger:     e.Logger,
+		fields:     f,
+		traceLevel: InfoLevel,
 	}
 }
 
@@ -86,6 +89,14 @@ func (e *Entry) WithError(err error) *Entry {
 	return ctx
 }
 
+// WithTraceAt returns a new entry with Trace() and Stop() methods
+// that log non-errors at the requested level.
+func (e *Entry) WithTraceAt(level Level) *Entry {
+	l := e.WithFields(e.Fields)
+	l.traceLevel = level
+	return l
+}
+
 // Debug level message.
 func (e *Entry) Debug(msg string) {
 	e.Logger.log(DebugLevel, e, msg)
@@ -140,18 +151,20 @@ func (e *Entry) Fatalf(msg string, v ...interface{}) {
 // Trace returns a new entry with a Stop method to fire off
 // a corresponding completion log, useful with defer.
 func (e *Entry) Trace(msg string) *Entry {
-	e.Info(msg)
+	e.Logger.log(e.traceLevel, e, msg)
 	v := e.WithFields(e.Fields)
 	v.Message = msg
 	v.start = time.Now()
+	v.traceLevel = e.traceLevel
 	return v
 }
 
 // Stop should be used with Trace, to fire off the completion message. When
 // an `err` is passed the "error" field is set, and the log level is error.
 func (e *Entry) Stop(err *error) {
 	if err == nil || *err == nil {
-		e.WithDuration(time.Since(e.start)).Info(e.Message)
+		d := e.WithDuration(time.Since(e.start))
+		d.Logger.log(e.traceLevel, d, e.Message)
 	} else {
 		e.WithDuration(time.Since(e.start)).WithError(*err).Error(e.Message)
 	}
@@ -173,10 +186,11 @@ func (e *Entry) mergedFields() Fields {
 // finalize returns a copy of the Entry with Fields merged.
 func (e *Entry) finalize(level Level, msg string) *Entry {
 	return &Entry{
-		Logger:    e.Logger,
-		Fields:    e.mergedFields(),
-		Level:     level,
-		Message:   msg,
-		Timestamp: Now(),
+		Logger:     e.Logger,
+		Fields:     e.mergedFields(),
+		Level:      level,
+		Message:    msg,
+		Timestamp:  Now(),
+		traceLevel: e.traceLevel,
 	}
 }

interface.go

@@ -7,6 +7,7 @@ type Interface interface {
 	WithFields(Fielder) *Entry
 	WithField(string, interface{}) *Entry
 	WithDuration(time.Duration) *Entry
+	WithTraceAt(Level) *Entry
 	WithError(error) *Entry
 	Debug(string)
 	Info(string)

logger.go

@@ -86,6 +86,12 @@ func (l *Logger) WithError(err error) *Entry {
 	return NewEntry(l).WithError(err)
 }
 
+// WithTraceAt returns a new entry with Trace() and Stop() methods
+// that log non-errors at the requested level.
+func (l *Logger) WithTraceAt(level Level) *Entry {
+	return NewEntry(l).WithTraceAt(level)
+}
+
 // Debug level message.
 func (l *Logger) Debug(msg string) {
 	NewEntry(l).Debug(msg)

logger_test.go

@@ -176,6 +176,99 @@ func TestLogger_Trace_nil(t *testing.T) {
 	}
 }
 
+func TestLogger_WithTraceAt_Trace_level(t *testing.T) {
+	h := memory.New()
+
+	l := &log.Logger{
+		Handler: h,
+		Level:   log.DebugLevel,
+	}
+
+	func() (err error) {
+		defer l.WithField("file", "sloth.png").WithTraceAt(log.DebugLevel).Trace("upload").Stop(&err)
+		return nil
+	}()
+
+	assert.Equal(t, 2, len(h.Entries))
+
+	{
+		e := h.Entries[0]
+		assert.Equal(t, e.Message, "upload")
+		assert.Equal(t, e.Level, log.DebugLevel)
+		assert.Equal(t, log.Fields{"file": "sloth.png"}, e.Fields)
+	}
+
+	{
+		e := h.Entries[1]
+		assert.Equal(t, e.Message, "upload")
+		assert.Equal(t, e.Level, log.DebugLevel)
+		assert.Equal(t, "sloth.png", e.Fields["file"])
+		assert.IsType(t, int64(0), e.Fields["duration"])
+	}
+}
+
+func TestLogger_WithTraceAt_Trace_err(t *testing.T) {
+	h := memory.New()
+
+	l := &log.Logger{
+		Handler: h,
+		Level:   log.DebugLevel,
+	}
+
+	func() (err error) {
+		defer l.WithField("file", "sloth.png").WithTraceAt(log.DebugLevel).Trace("upload").Stop(&err)
+		return fmt.Errorf("boom")
+	}()
+
+	assert.Equal(t, 2, len(h.Entries))
+
+	{
+		e := h.Entries[0]
+		assert.Equal(t, e.Message, "upload")
+		assert.Equal(t, e.Level, log.DebugLevel)
+		assert.Equal(t, "sloth.png", e.Fields["file"])
+	}
+
+	{
+		e := h.Entries[1]
+		assert.Equal(t, e.Message, "upload")
+		assert.Equal(t, e.Level, log.ErrorLevel)
+		assert.Equal(t, "sloth.png", e.Fields["file"])
+		assert.Equal(t, "boom", e.Fields["error"])
+		assert.IsType(t, int64(0), e.Fields["duration"])
+	}
+}
+
+func TestLogger_WithTraceAt_Trace_nil(t *testing.T) {
+	h := memory.New()
+
+	l := &log.Logger{
+		Handler: h,
+		Level:   log.DebugLevel,
+	}
+
+	func() {
+		defer l.WithField("file", "sloth.png").WithTraceAt(log.DebugLevel).Trace("upload").Stop(nil)
+	}()
+
+	assert.Equal(t, 2, len(h.Entries))
+
+	{
+		e := h.Entries[0]
+		assert.Equal(t, e.Message, "upload")
+		assert.Equal(t, e.Level, log.DebugLevel)
+		assert.Equal(t, log.Fields{"file": "sloth.png"}, e.Fields)
+	}
+
+	{
+		e := h.Entries[1]
+		assert.Equal(t, e.Message, "upload")
+		assert.Equal(t, e.Level, log.DebugLevel)
+		assert.Equal(t, "sloth.png", e.Fields["file"])
+		assert.IsType(t, int64(0), e.Fields["duration"])
+	}
+}
+
 func TestLogger_HandlerFunc(t *testing.T) {
 	h := memory.New()
 	f := func(e *log.Entry) error {

pkg.go

@@ -51,6 +51,12 @@ func WithError(err error) *Entry {
 	return Log.WithError(err)
 }
 
+// WithTraceAt returns a new entry with Trace() and Stop() methods
+// that log non-errors at the requested level.
+func WithTraceAt(level Level) *Entry {
+	return Log.WithTraceAt(level)
+}
+
 // Debug level message.
 func Debug(msg string) {
 	Log.Debug(msg)