webhooker/internal/archive/writer_gormlog_test.go

package archive_test

import (
	"bytes"
	"log"
	"log/slog"
	"path/filepath"
	"strings"
	"sync"
	"testing"
	"time"

	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
	"gorm.io/gorm"
	gormlogger "gorm.io/gorm/logger"
	"sneak.berlin/go/webhooker/internal/archive"
	"sneak.berlin/go/webhooker/internal/middleware"
)

// archiveGORMTailMarker sits at the far end of the value this file
// drives into an archive lookup. Its presence in a log line means the
// whole value reached the log, so nothing truncated it.
const archiveGORMTailMarker = "ENDOFCLIENTVALUE"

// archiveGORMFillBytes is how much text the lookup carries. It is far
// past every budget in play.
const archiveGORMFillBytes = 8 << 10

// gormDefaultBuf collects what GORM's package-level default logger
// writes, if anything reaches it.
type gormDefaultBuf struct {
	mu sync.Mutex
	b  bytes.Buffer
}

func (g *gormDefaultBuf) Write(p []byte) (int, error) {
	g.mu.Lock()
	defer g.mu.Unlock()

	return g.b.Write(p)
}

func (g *gormDefaultBuf) String() string {
	g.mu.Lock()
	defer g.mu.Unlock()

	return g.b.String()
}

// captureArchiveGORMDefault replaces GORM's package-level default
// logger with one configured exactly as GORM configures its own,
// writing to a buffer.
//
// This duplicates the detector in internal/handlers rather than
// sharing it: a test helper cannot cross a package's test boundary
// without exporting production code to carry it, and a logging
// detector is not worth a production symbol. What it detects is the
// third gorm.Open in this service, at
// internal/archive/writer.go — the archive writer,
// whose type is unexported, so nothing outside this package can drive
// it.
func captureArchiveGORMDefault(t *testing.T) *gormDefaultBuf {
	t.Helper()

	buf := &gormDefaultBuf{}
	orig := gormlogger.Default

	gormlogger.Default = gormlogger.New(
		log.New(buf, "", log.LstdFlags),
		gormlogger.Config{
			SlowThreshold:             200 * time.Millisecond,
			LogLevel:                  gormlogger.Warn,
			IgnoreRecordNotFoundError: false,
			Colorful:                  false,
		},
	)

	t.Cleanup(func() { gormlogger.Default = orig })

	return buf
}

// TestArchiveWriter_NeverUsesGORMsDefaultLogger pins the archive
// writer's gorm.Open to the adapter.
//
// Restore a bare &gorm.Config{} at
// internal/archive/writer.go and this fails: the
// default logger prints the fully interpolated SELECT on every
// ErrRecordNotFound, so the client-chosen event id below arrives whole
// and unbounded on stdout, answering to no level the operator set.
//
// Not parallel: gormlogger.Default is process-global. Go runs every
// non-parallel top-level test to completion before it resumes the
// parallel ones.
//
//nolint:paralleltest // Deliberately sequential; see above.
func TestArchiveWriter_NeverUsesGORMsDefaultLogger(t *testing.T) {
	var captured bytes.Buffer

	gormDefault := captureArchiveGORMDefault(t)

	w := archive.NewExportArchiveWriter(
		filepath.Join(t.TempDir(), "archive.db"),
		slog.New(slog.NewTextHandler(
			&captured, &slog.HandlerOptions{Level: slog.LevelDebug},
		)),
		0,
	)

	require.NoError(t, w.Open(0))

	t.Cleanup(w.Evict)

	// A lookup that misses, carrying a value the size of an inbound
	// event id. Under the default logger this is the line that gets
	// interpolated and printed.
	value := strings.Repeat("\x01", archiveGORMFillBytes) +
		archiveGORMTailMarker

	var row archive.ExportArchivedEvent

	err := w.DB().Where("event_id = ?", value).First(&row).Error
	require.ErrorIs(t, err, gorm.ErrRecordNotFound)

	got := gormDefault.String()
	assert.Empty(
		t, got,
		"GORM's default logger wrote %d bytes, so the archive "+
			"writer's gorm.Open is back on a bare &gorm.Config{}; "+
			"the first of them: %s",
		len(got), got[:min(len(got), 300)],
	)

	// The adapter drops a miss, so this should be silent too — and
	// whatever it does write stays inside the stated ceiling.
	out := captured.String()

	assert.NotContains(
		t, out, archiveGORMTailMarker,
		"the far end of the client-chosen value reached the log",
	)

	for line := range strings.SplitSeq(strings.TrimRight(out, "\n"), "\n") {
		if line == "" {
			continue
		}

		assert.LessOrEqual(
			t, len(line), middleware.MaxAccessLogLineBytes,
			"log line exceeded its bound: %s",
			line[:min(len(line), 300)],
		)
	}
}