feat: add timestamp (#24)

Makefile

@@ -1 +1,6 @@
 include github.com/hamba/make/golang
+
+# Run benchmarks
+bench:
+	@go test -bench=. ./...
+.PHONY: bench

bench_test.go

@@ -33,6 +33,36 @@ func BenchmarkLogger_Json(b *testing.B) {
 	})
 }
 
+func BenchmarkLogger_LogfmtWithTS(b *testing.B) {
+	log := logger.New(io.Discard, logger.LogfmtFormat(), logger.Debug)
+
+	cancel := log.WithTimestamp()
+	defer cancel()
+
+	b.ReportAllocs()
+	b.ResetTimer()
+	b.RunParallel(func(pb *testing.PB) {
+		for pb.Next() {
+			log.Error("some message")
+		}
+	})
+}
+
+func BenchmarkLogger_JsonWithTS(b *testing.B) {
+	log := logger.New(io.Discard, logger.JSONFormat(), logger.Debug)
+
+	cancel := log.WithTimestamp()
+	defer cancel()
+
+	b.ReportAllocs()
+	b.ResetTimer()
+	b.RunParallel(func(pb *testing.PB) {
+		for pb.Next() {
+			log.Error("some message")
+		}
+	})
+}
+
 func BenchmarkLogger_LogfmtCtx(b *testing.B) {
 	log := logger.New(io.Discard, logger.LogfmtFormat(), logger.Debug).With(ctx.Str("_n", "bench"), ctx.Int("_p", 1))
 

format.go

@@ -10,6 +10,8 @@ import (
 )
 
 const (
+	// TimestampKey is the key used for timestamps.
+	TimestampKey = "ts"
 	// LevelKey is the key used for message levels.
 	LevelKey = "lvl"
 	// MessageKey is the key used for message descriptions.
@@ -20,7 +22,7 @@ const (
 
 // Formatter represents a log message formatter.
 type Formatter interface {
-	WriteMessage(buf *bytes.Buffer, time int64, lvl Level, msg string)
+	WriteMessage(buf *bytes.Buffer, ts int64, lvl Level, msg string)
 	AppendEndMarker(buf *bytes.Buffer)
 	AppendArrayStart(buf *bytes.Buffer)
 	AppendArraySep(buf *bytes.Buffer)
@@ -43,8 +45,14 @@ func JSONFormat() Formatter {
 	return &json{}
 }
 
-func (j *json) WriteMessage(buf *bytes.Buffer, time int64, lvl Level, msg string) {
+func (j *json) WriteMessage(buf *bytes.Buffer, ts int64, lvl Level, msg string) {
 	buf.WriteString(`{"`)
+	if ts > 0 {
+		buf.WriteString(TimestampKey)
+		buf.WriteString(`":`)
+		buf.AppendInt(ts)
+		buf.WriteString(`,"`)
+	}
 	buf.WriteString(LevelKey)
 	buf.WriteString(`":"`)
 	buf.WriteString(lvl.String())
@@ -131,7 +139,13 @@ func (l *logfmt) needsQuote(s string) bool {
 	return false
 }
 
-func (l *logfmt) WriteMessage(buf *bytes.Buffer, time int64, lvl Level, msg string) {
+func (l *logfmt) WriteMessage(buf *bytes.Buffer, ts int64, lvl Level, msg string) {
+	if ts > 0 {
+		buf.WriteString(TimestampKey)
+		buf.WriteString(`=`)
+		buf.AppendInt(ts)
+		buf.WriteByte(' ')
+	}
 	buf.WriteString(LevelKey)
 	buf.WriteByte('=')
 	buf.WriteString(lvl.String())
@@ -261,7 +275,13 @@ func (c *console) lvlColor(lvl Level) color {
 	return newColor(colorWhite)
 }
 
-func (c *console) WriteMessage(buf *bytes.Buffer, time int64, lvl Level, msg string) {
+func (c *console) WriteMessage(buf *bytes.Buffer, ts int64, lvl Level, msg string) {
+	if ts > 0 {
+		withColor(newColor(colorBlue), buf, func() {
+			buf.AppendInt(ts)
+		})
+		buf.WriteByte(' ')
+	}
 	withColor(c.lvlColor(lvl), buf, func() {
 		buf.WriteString(strings.ToUpper(lvl.String()))
 	})

format_test.go

@@ -13,12 +13,12 @@ func TestJsonFormat(t *testing.T) {
 	fmtr := logger.JSONFormat()
 
 	buf := bytes.NewBuffer(512)
-	fmtr.WriteMessage(buf, 0, logger.Error, "some message")
+	fmtr.WriteMessage(buf, 123, logger.Error, "some message")
 	fmtr.AppendKey(buf, "error")
 	fmtr.AppendString(buf, "some error")
 	fmtr.AppendEndMarker(buf)
 
-	want := `{"lvl":"eror","msg":"some message","error":"some error"}` + "\n"
+	want := `{"ts":123,"lvl":"eror","msg":"some message","error":"some error"}` + "\n"
 	assert.Equal(t, want, string(buf.Bytes()))
 }
 
@@ -162,12 +162,12 @@ func TestLogfmtFormat(t *testing.T) {
 	fmtr := logger.LogfmtFormat()
 
 	buf := bytes.NewBuffer(512)
-	fmtr.WriteMessage(buf, 0, logger.Error, "some message")
+	fmtr.WriteMessage(buf, 123, logger.Error, "some message")
 	fmtr.AppendKey(buf, "error")
 	fmtr.AppendString(buf, "some error")
 	fmtr.AppendEndMarker(buf)
 
-	want := `lvl=eror msg="some message" error="some error"` + "\n"
+	want := `ts=123 lvl=eror msg="some message" error="some error"` + "\n"
 	assert.Equal(t, want, string(buf.Bytes()))
 }
 
@@ -311,12 +311,12 @@ func TestConsoleFormat(t *testing.T) {
 	fmtr := logger.ConsoleFormat()
 
 	buf := bytes.NewBuffer(512)
-	fmtr.WriteMessage(buf, 0, logger.Error, "some message")
+	fmtr.WriteMessage(buf, 123, logger.Error, "some message")
 	fmtr.AppendKey(buf, "error")
 	fmtr.AppendString(buf, "some error")
 	fmtr.AppendEndMarker(buf)
 
-	want := "\x1b[31mEROR\x1b[0m some message \x1b[31merror=\x1b[0msome error\n"
+	want := "\x1b[34m123\x1b[0m \x1b[31mEROR\x1b[0m some message \x1b[31merror=\x1b[0msome error\n"
 	assert.Equal(t, want, string(buf.Bytes()))
 }
 

logger.go

@@ -1,8 +1,11 @@
 package logger
 
 import (
+	"context"
 	"errors"
 	"io"
+	"sync/atomic"
+	"time"
 )
 
 // List of predefined log Levels.
@@ -59,10 +62,11 @@ type Field func(*Event)
 
 // Logger is a logger.
 type Logger struct {
-	w    io.Writer
-	fmtr Formatter
-	lvl  Level
-	ctx  []byte
+	w      io.Writer
+	fmtr   Formatter
+	timeFn func() int64
+	ctx    []byte
+	lvl    Level
 }
 
 // New creates a new Logger.
@@ -74,6 +78,41 @@ func New(w io.Writer, fmtr Formatter, lvl Level) *Logger {
 	}
 }
 
+// WithTimestamp adds a timestamp to each log lone. Sub-loggers
+// will inherit the timestamp.
+//
+// WithTimestamp is not thread safe.
+func (l *Logger) WithTimestamp() (cancel func()) {
+	if l.timeFn != nil {
+		return func() {}
+	}
+
+	ctx, cancel := context.WithCancel(context.Background())
+
+	var ts int64
+	atomic.StoreInt64(&ts, time.Now().UTC().Unix())
+
+	go func() {
+		tick := time.NewTicker(100 * time.Millisecond)
+		defer tick.Stop()
+
+		for {
+			select {
+			case <-ctx.Done():
+				return
+			case <-tick.C:
+				atomic.StoreInt64(&ts, time.Now().UTC().Unix())
+			}
+		}
+	}()
+
+	l.timeFn = func() int64 {
+		return atomic.LoadInt64(&ts)
+	}
+
+	return cancel
+}
+
 // With returns a new Logger with the given context.
 func (l *Logger) With(ctx ...Field) *Logger {
 	e := newEvent(l.fmtr)
@@ -89,10 +128,11 @@ func (l *Logger) With(ctx ...Field) *Logger {
 	copy(b, e.buf.Bytes())
 
 	return &Logger{
-		w:    l.w,
-		fmtr: l.fmtr,
-		lvl:  l.lvl,
-		ctx:  b,
+		w:      l.w,
+		fmtr:   l.fmtr,
+		timeFn: l.timeFn,
+		lvl:    l.lvl,
+		ctx:    b,
 	}
 }
 
@@ -128,7 +168,12 @@ func (l *Logger) write(msg string, lvl Level, ctx []Field) {
 
 	e := newEvent(l.fmtr)
 
-	e.fmtr.WriteMessage(e.buf, 0, lvl, msg)
+	var ts int64
+	if l.timeFn != nil {
+		ts = l.timeFn()
+	}
+
+	e.fmtr.WriteMessage(e.buf, ts, lvl, msg)
 	e.buf.Write(l.ctx)
 
 	for _, field := range ctx {

logger_test.go

@@ -226,3 +226,15 @@ func TestLogger_Stack(t *testing.T) {
 	want := `lvl=info msg="some message" stack=[github.com/hamba/logger/logger/logger_test.go:224]` + "\n"
 	assert.Equal(t, want, buf.String())
 }
+
+func TestLogger_Timestamp(t *testing.T) {
+	var buf bytes.Buffer
+	log := logger.New(&buf, logger.LogfmtFormat(), logger.Info)
+	cancel := log.WithTimestamp()
+	defer cancel()
+
+	log.Info("some message")
+
+	want := `^ts=\d+ lvl=info msg="some message"` + "\n$"
+	assert.Regexp(t, want, buf.String())
+}