webhooker/internal/delivery/queue_depth_gormlog_test.go

package delivery_test

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

	"github.com/google/uuid"
	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
	"gorm.io/driver/sqlite"
	"gorm.io/gorm"
	"sneak.berlin/go/webhooker/internal/database"
	"sneak.berlin/go/webhooker/internal/delivery"
	"sneak.berlin/go/webhooker/internal/gormlog"
)

// qdAggregateMarker identifies the queue-depth aggregate in the
// captured SQL. It is the one statement in this test that binds
// anything, and the raw count() expression appears in no other.
const qdAggregateMarker = "count(*)"

// qdSyncBuf collects log output from whichever goroutine GORM writes
// on.
type qdSyncBuf struct {
	mu sync.Mutex
	b  bytes.Buffer
}

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

	return q.b.Write(p)
}

func (q *qdSyncBuf) String() string {
	q.mu.Lock()
	defer q.mu.Unlock()

	return q.b.String()
}

// qdMainDB opens a main database whose GORM logger is the service's
// adapter, writing through log.
func qdMainDB(t *testing.T, log *slog.Logger) *gorm.DB {
	t.Helper()

	sqlDB, err := database.OpenSQLite(
		filepath.Join(t.TempDir(), "main-gormlog.db"),
		database.SQLiteModeCreate,
	)
	require.NoError(t, err)

	t.Cleanup(func() { _ = sqlDB.Close() })

	db, err := gorm.Open(
		sqlite.Dialector{Conn: sqlDB},
		&gorm.Config{Logger: gormlog.New(log)},
	)
	require.NoError(t, err)

	require.NoError(t, db.AutoMigrate(
		&database.Webhook{},
		&database.Target{},
	))

	return db
}

// qdLinesContaining returns every captured line carrying marker.
func qdLinesContaining(out, marker string) []string {
	var found []string

	for line := range strings.SplitSeq(out, "\n") {
		if strings.Contains(line, marker) {
			found = append(found, line)
		}
	}

	return found
}

// TestQueueDepthSample_LogsNoBoundValue holds the queue-depth sampler
// to the values-off property internal/gormlog exists to provide.
//
// The aggregate binds the delivery status list. Read with
// (*gorm.DB).Scan it was logged with those values interpolated, because
// Scan records the statement through GORM's own traceRecorder, which
// does not implement gorm.ParamsFilter. Read with Find it goes through
// the normal query callback and the adapter's filter applies. Restore
// the Scan call in queue_depth.go and this fails on the status literals
// below; scan_guard_test.go catches the same regression statically.
func TestQueueDepthSample_LogsNoBoundValue(t *testing.T) {
	t.Parallel()

	buf := &qdSyncBuf{}
	log := slog.New(slog.NewTextHandler(
		buf, &slog.HandlerOptions{Level: slog.LevelDebug},
	))

	mainDB := qdMainDB(t, log)
	dbMgr := database.NewTestWebhookDBManagerWithLogger(
		t.TempDir(), log,
	)

	webhookID := uuid.New().String()
	webhookDB := iSeedWebhookDB(t, dbMgr, webhookID)

	iCreateWebhook(t, mainDB, webhookID, "queue-depth-gormlog")

	targetID := uuid.New().String()

	iCreateTarget(t, mainDB, targetID, webhookID,
		"queue-depth-gormlog-target", database.TargetTypeHTTP,
		iHTTPConfig("https://example.com/hook"), 3,
	)

	event := iSeedEvent(
		t, webhookDB, webhookID, `{"queued":true}`,
	)

	iSeedDelivery(
		t, webhookDB, event.ID, targetID,
		database.DeliveryStatusPending,
	)
	iSeedDelivery(
		t, webhookDB, event.ID, targetID,
		database.DeliveryStatusRetrying,
	)

	engine := delivery.NewTestEngineWithDB(
		database.NewTestDatabase(mainDB),
		dbMgr,
		log,
		&http.Client{Timeout: 5 * time.Second},
		2,
	)

	engine.ExportSampleQueueDepths(context.Background())

	out := buf.String()

	lines := qdLinesContaining(out, qdAggregateMarker)
	require.NotEmpty(
		t, lines,
		"the queue-depth aggregate was never logged, so the "+
			"assertions below are vacuous",
	)

	for _, line := range lines {
		assert.Contains(
			t, line, "?",
			"the aggregate was logged without its placeholders: %s",
			line,
		)

		for _, status := range []database.DeliveryStatus{
			database.DeliveryStatusPending,
			database.DeliveryStatusRetrying,
		} {
			assert.NotContains(
				t, line, string(status),
				"a bound status value was interpolated into the "+
					"logged statement: %s", line,
			)
		}
	}
}