log_test.go

package log_test

import (
	"bytes"
	"fmt"
	"io"
	"log/slog"
	"net/http"
	"os"
	"strings"
	"sync"
	"testing"
	"time"

	"go.followtheprocess.codes/hue"
	"go.followtheprocess.codes/log"
	"go.followtheprocess.codes/test"
)

func TestVisual(t *testing.T) {
	hue.Enabled(true) // Force colour

	logger := log.New(os.Stdout, log.WithLevel(log.LevelDebug))
	prefixed := logger.Prefixed("cooking")

	logger.Debug("Doing some debuggy things")
	logger.Info("Logging in")
	logger.Warn("Config file missing, falling back to defaults")
	logger.Error("File not found")

	prefixed.Warn("Pizza is burning!", slog.String("flavour", "pepperoni"))
	prefixed.Info("Response from oven API", slog.Int("status", http.StatusOK), slog.Duration("duration", 57*time.Millisecond))
}

func TestDebug(t *testing.T) {
	hue.Enabled(false) // Force no color

	// Constantly return the same time
	fixedTime := func() time.Time {
		fixed, err := time.Parse(time.RFC3339, "2025-04-01T13:34:03Z")
		test.Ok(t, err)

		return fixed
	}

	fixedTimeString := fixedTime().Format(time.RFC3339)

	tests := []struct {
		name    string       // Name of the test case
		msg     string       // Message to log
		attrs   []slog.Attr  // Additional attributes to pass to the log method
		want    string       // Expected log line
		options []log.Option // Options to customise the logger under test
	}{
		{
			name: "disabled",
			options: []log.Option{
				log.WithLevel(log.LevelInfo),
			},
			msg:  "You should not see me",
			want: "", // Debug logs should not show up if the level is info
		},
		{
			name: "enabled",
			options: []log.Option{
				log.WithLevel(log.LevelDebug),
			},
			msg:  "Hello debug!",
			want: "[TIME] DEBUG: Hello debug!\n",
		},
		{
			name: "prefix",
			options: []log.Option{
				log.WithLevel(log.LevelDebug),
				log.Prefix("building"),
			},
			msg:  "Hello debug!",
			want: "[TIME] DEBUG building: Hello debug!\n",
		},
		{
			name: "with attrs",
			options: []log.Option{
				log.WithLevel(log.LevelDebug),
			},
			msg: "Hello debug!",
			attrs: []slog.Attr{
				slog.Int("number", 12),
				slog.Duration("duration", 30*time.Second),
				slog.Bool("enabled", true),
			},
			want: "[TIME] DEBUG: Hello debug! number=12 duration=30s enabled=true\n",
		},
		{
			name: "with attrs quoted",
			options: []log.Option{
				log.WithLevel(log.LevelDebug),
			},
			msg: "Hello debug!",
			attrs: []slog.Attr{
				slog.Int("number", 12),
				slog.Duration("duration", 30*time.Second),
				slog.String("sentence", "this has spaces"),
			},
			want: `[TIME] DEBUG: Hello debug! number=12 duration=30s sentence="this has spaces"` + "\n",
		},
		{
			name: "with attrs escape chars",
			options: []log.Option{
				log.WithLevel(log.LevelDebug),
			},
			msg: "Hello debug!",
			attrs: []slog.Attr{
				slog.Int("number", 12),
				slog.Duration("duration", 30*time.Second),
				slog.String("sentence", "ooh\t\nstuff"),
			},
			want: `[TIME] DEBUG: Hello debug! number=12 duration=30s sentence="ooh\t\nstuff"` + "\n",
		},
		{
			name: "custom time format",
			options: []log.Option{
				log.WithLevel(log.LevelDebug),
				log.TimeFormat(time.Kitchen),
			},
			msg:  "The oven is done",
			want: "1:34PM DEBUG: The oven is done\n",
		},
	}

	for _, tt := range tests {
		t.Run(tt.name, func(t *testing.T) {
			buf := &bytes.Buffer{}

			// Ensure that the time is always deterministic
			tt.options = append(tt.options, log.TimeFunc(fixedTime))

			logger := log.New(buf, tt.options...)

			logger.Debug(tt.msg, tt.attrs...)

			got := buf.String()
			got = strings.ReplaceAll(got, fixedTimeString, "[TIME]")

			test.Diff(t, got, tt.want)
		})
	}
}

func TestWith(t *testing.T) {
	hue.Enabled(false) // Force no color

	// Constantly return the same time
	fixedTime := func() time.Time {
		fixed, err := time.Parse(time.RFC3339, "2025-04-01T13:34:03Z")
		test.Ok(t, err)

		return fixed
	}

	fixedTimeString := fixedTime().Format(time.RFC3339)

	tests := []struct {
		name string
		fn   func() string // Exercise the logger, return output
		want string
	}{
		{
			name: "attrs appear on sub logger",
			fn: func() string {
				buf := &bytes.Buffer{}
				l := log.New(buf, log.TimeFunc(fixedTime))
				l.Info("I'm an info message")
				sub := l.With(slog.Bool("sub", true), slog.String("hello", "world"))
				sub.Info("I'm also an info message")

				return buf.String()
			},
			want: "[TIME] INFO:  I'm an info message\n[TIME] INFO:  I'm also an info message sub=true hello=world\n",
		},
		{
			name: "chained With preserves earlier attrs",
			fn: func() string {
				buf := &bytes.Buffer{}
				l := log.New(buf, log.TimeFunc(fixedTime))
				l.With(slog.String("a", "1")).With(slog.String("b", "2")).Info("chained")

				return buf.String()
			},
			want: "[TIME] INFO:  chained a=1 b=2\n",
		},
		{
			name: "Prefixed preserves attrs from With",
			fn: func() string {
				buf := &bytes.Buffer{}
				l := log.New(buf, log.TimeFunc(fixedTime))
				l.With(slog.String("a", "1")).Prefixed("svc").Info("prefixed")

				return buf.String()
			},
			want: "[TIME] INFO svc:  prefixed a=1\n",
		},
		{
			name: "parent logger not affected by child With",
			fn: func() string {
				buf := &bytes.Buffer{}
				l := log.New(buf, log.TimeFunc(fixedTime))
				_ = l.With(slog.String("child", "attr"))
				l.Info("parent should have no attrs")

				return buf.String()
			},
			want: "[TIME] INFO:  parent should have no attrs\n",
		},
	}

	for _, tt := range tests {
		t.Run(tt.name, func(t *testing.T) {
			got := tt.fn()
			got = strings.ReplaceAll(got, fixedTimeString, "[TIME]")
			test.Diff(t, got, tt.want)
		})
	}
}

func TestRace(t *testing.T) {
	buf := &bytes.Buffer{}

	// Constantly return the same time
	fixedTime := func() time.Time {
		fixed, err := time.Parse(time.RFC3339, "2025-04-01T13:34:03Z")
		test.Ok(t, err)

		return fixed
	}

	logger := log.New(buf, log.TimeFunc(fixedTime))
	sub := logger.Prefixed("sub")

	const n = 1000

	var wg sync.WaitGroup
	wg.Add(n)

	for i := range n {
		go func(wg *sync.WaitGroup, i int) {
			defer wg.Done()

			logger.Info(fmt.Sprintf("Something: %d", i))
		}(&wg, i)
	}

	wg.Add(n)

	for i := range n {
		go func(wg *sync.WaitGroup, i int) {
			defer wg.Done()

			sub.Info(fmt.Sprintf("Other: %d", i))
		}(&wg, i)
	}

	wg.Wait()

	// Make sure they all got written, order doesn't matter because concurrency
	got := strings.TrimSpace(buf.String())
	lines := strings.Split(got, "\n")

	test.Equal(t, len(lines), n*2, test.Context("expected %d log lines", n*2))
}

func BenchmarkLogger(b *testing.B) {
	hue.Enabled(true) // Force colour

	// Declare the buffer out here otherwise the benchmarks
	// pick up the growing and re-allocating of this buffer
	// which is just an artifact of the benchmark
	buf := &bytes.Buffer{}

	// Likewise the loggers are declared out here because creating the logger
	// is typically done once in an application and the logger is re-used a bunch
	// of times to write log lines
	debugLogger := log.New(buf, log.WithLevel(log.LevelDebug))
	infoLogger := log.New(buf, log.WithLevel(log.LevelInfo))
	discardLogger := log.New(io.Discard, log.WithLevel(log.LevelDebug))

	b.Run("enabled", func(b *testing.B) {
		for b.Loop() {
			debugLogger.Debug("A message!")
		}

		buf.Reset()
	})

	b.Run("disabled", func(b *testing.B) {
		for b.Loop() {
			infoLogger.Debug("A message!")
		}

		buf.Reset()
	})

	b.Run("discard", func(b *testing.B) {
		// Here to test that effectively nothing is done
		// when w == io.Discard
		for b.Loop() {
			discardLogger.Debug("Nothing")
		}

		buf.Reset()
	})
}