From 31fe26085f1424a217edf2d9c0a2e3b007b6179a Mon Sep 17 00:00:00 2001
From: James Harris <contact@jamesharris.id.au>
Date: Tue, 9 Apr 2024 08:55:50 +1000
Subject: [PATCH] Add offset from when the logger was created.

---
 CHANGELOG.md   |  7 ++++++-
 spruce.go      | 18 +++++++++++++++++-
 spruce_test.go | 22 +++++++++++++---------
 3 files changed, 36 insertions(+), 11 deletions(-)

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 61b6a02..595887d 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -10,14 +10,19 @@ The format is based on [Keep a Changelog], and this project adheres to
 [Keep a Changelog]: https://keepachangelog.com/en/1.0.0/
 [Semantic Versioning]: https://semver.org/spec/v2.0.0.html
 
+## [0.1.1] - 2024-04-09
+
+- Include the elapsed duration since the logger was created in each log message.
+
 ## [0.1.0] - 2024-03-02
 
-- Initial release
+- Initial release.
 
 <!-- references -->
 
 [Unreleased]: https://github.com/dogmatiq/spruce
 [0.1.0]: https://github.com/dogmatiq/spruce/releases/tag/v0.1.0
+[0.1.1]: https://github.com/dogmatiq/spruce/releases/tag/v0.1.1
 
 <!-- version template
 ## [0.0.1] - YYYY-MM-DD
diff --git a/spruce.go b/spruce.go
index d465e2a..ec081a5 100644
--- a/spruce.go
+++ b/spruce.go
@@ -7,6 +7,7 @@ import (
 	"slices"
 	"strings"
 	"testing"
+	"time"
 )
 
 // TestingT is the subset of the [testing.TB] interface that is used to write
@@ -24,13 +25,17 @@ func NewLogger(t TestingT) *slog.Logger {
 
 // NewHandler returns a new [slog.Handler] that writes to t.
 func NewHandler(t TestingT) slog.Handler {
-	return &handler{T: t}
+	return &handler{
+		T:     t,
+		epoch: time.Now(),
+	}
 }
 
 type handler struct {
 	T      TestingT
 	attrs  []slog.Attr
 	groups []string
+	epoch  time.Time
 }
 
 func (h *handler) Enabled(context.Context, slog.Level) bool {
@@ -63,9 +68,18 @@ func (h *handler) Handle(_ context.Context, rec slog.Record) error {
 	}
 
 	level := rec.Level.String()
+
+	elapsed := rec.Time.Sub(h.epoch)
+
 	buf.WriteByte('[')
 	buf.WriteString(level)
+	buf.WriteByte(' ')
+	if elapsed > 0 {
+		buf.WriteByte('+')
+	}
+	buf.WriteString(elapsed.String())
 	buf.WriteString("] ")
+
 	buf.WriteString(rec.Message)
 
 	writeAttrs(buf, 0, attrs, true)
@@ -139,6 +153,7 @@ func (h *handler) WithAttrs(attrs []slog.Attr) slog.Handler {
 		T:      h.T,
 		attrs:  append(slices.Clone(h.attrs), attrs...),
 		groups: h.groups,
+		epoch:  h.epoch,
 	}
 }
 
@@ -147,5 +162,6 @@ func (h *handler) WithGroup(name string) slog.Handler {
 		T:      h.T,
 		attrs:  h.attrs,
 		groups: append(slices.Clone(h.groups), name),
+		epoch:  h.epoch,
 	}
 }
diff --git a/spruce_test.go b/spruce_test.go
index b1f39ae..2693fac 100644
--- a/spruce_test.go
+++ b/spruce_test.go
@@ -3,6 +3,7 @@ package spruce_test
 import (
 	"fmt"
 	"log/slog"
+	"regexp"
 	"strings"
 	"testing"
 	"time"
@@ -17,7 +18,7 @@ func TestHandler_noAttributes(t *testing.T) {
 
 	l.Info("<message>")
 	s.Expect(
-		`[INFO] <message>`,
+		`[INFO <timestamp>] <message>`,
 	)
 }
 
@@ -27,7 +28,7 @@ func TestHandler_stringAttribute(t *testing.T) {
 
 	l.Info("<message>", "<key>", "<value>")
 	s.Expect(
-		`[INFO] <message>`,
+		`[INFO <timestamp>] <message>`,
 		`╰── <key> ┈ <value>`,
 	)
 }
@@ -42,7 +43,7 @@ func TestHandler_stringerAttribute(t *testing.T) {
 		1*time.Second,
 	)
 	s.Expect(
-		`[INFO] <message>`,
+		`[INFO <timestamp>] <message>`,
 		`╰── duration ┈ 1s`,
 	)
 }
@@ -57,7 +58,7 @@ func TestHandler_attributeAlignment(t *testing.T) {
 		"<much longer>", "<value-2>",
 	)
 	s.Expect(
-		`[INFO] <message>`,
+		`[INFO <timestamp>] <message>`,
 		`├── <short> ┈┈┈┈┈┈┈ <value-1>`,
 		`╰── <much longer> ┈ <value-2>`,
 	)
@@ -80,7 +81,7 @@ func TestHandler_nestedAttributes(t *testing.T) {
 		),
 	)
 	s.Expect(
-		`[INFO] <message>`,
+		`[INFO <timestamp>] <message>`,
 		`├─┬ <group b>`,
 		`│ ├── <key-1> ┈ <value-1>`,
 		`│ ╰── <key-2> ┈ <value-2>`,
@@ -98,7 +99,7 @@ func TestHandler_whitespaceEscaping(t *testing.T) {
 		"<key>", "value\nwith\nnewlines",
 	)
 	s.Expect(
-		`[INFO] <message>`,
+		`[INFO <timestamp>] <message>`,
 		`╰── <key> ┈ "value\nwith\nnewlines"`,
 	)
 }
@@ -111,7 +112,7 @@ func TestHandler_WithAttrs(t *testing.T) {
 
 	l.Info("<message>")
 	s.Expect(
-		`[INFO] <message>`,
+		`[INFO <timestamp>] <message>`,
 		`╰── <key> ┈ <value>`,
 	)
 }
@@ -124,7 +125,7 @@ func TestHandler_WithAttrs_sameKey(t *testing.T) {
 
 	l.Info("<message>", "<key>", "<value-2>")
 	s.Expect(
-		`[INFO] <message>`,
+		`[INFO <timestamp>] <message>`,
 		`├── <key> ┈ <value-1>`,
 		`╰── <key> ┈ <value-2>`,
 	)
@@ -138,7 +139,7 @@ func TestHandler_WithGroup(t *testing.T) {
 
 	l.Info("<message>", "<key>", "<value>")
 	s.Expect(
-		`[INFO] <message>`,
+		`[INFO <timestamp>] <message>`,
 		`╰─┬ <group>`,
 		`  ╰── <key> ┈ <value>`,
 	)
@@ -155,8 +156,11 @@ func (s *testingTStub) Log(args ...any) {
 }
 
 func (s *testingTStub) Expect(lines ...string) {
+	timestamp := regexp.MustCompile(`\[([A-Z]+) .+?\]`)
+
 	expect := strings.Join(lines, "\n")
 	for _, line := range s.actual {
+		line = timestamp.ReplaceAllString(line, "[$1 <timestamp>]")
 		if line == expect {
 			return
 		}