webhooker/internal/gormlog/firstboot_test.go

package gormlog_test

import (
	"context"
	"database/sql"
	"os"
	"path/filepath"
	"testing"

	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
	"go.uber.org/fx"
	"go.uber.org/fx/fxtest"
	_ "modernc.org/sqlite" // Pure Go SQLite driver.
	"sneak.berlin/go/webhooker/internal/config"
	"sneak.berlin/go/webhooker/internal/database"
	"sneak.berlin/go/webhooker/internal/globals"
	"sneak.berlin/go/webhooker/internal/logger"
	"sneak.berlin/go/webhooker/internal/session"
)

// argon2Prefix opens every encoded Argon2id hash this service
// produces. It is asserted on separately from the hash itself, so that
// a change to the password encoding cannot quietly turn the hash
// assertion into a comparison against a string the log never held.
const argon2Prefix = "$argon2id$"

// settingsInsert and usersInsert are the two statements a first boot
// runs that carry a secret. The sqlite dialector quotes identifiers
// with backticks.
const (
	settingsInsert = "INSERT INTO `settings`"
	usersInsert    = "INSERT INTO `users`"
)

// captureStdoutToFile redirects os.Stdout into a file for the rest of
// the test and returns a function that reads back everything written
// to it.
//
// A file rather than a pipe: internal/logger writes synchronously to
// whatever os.Stdout is when it builds its handler, so once fx's start
// returns, every byte the boot produced is already in the file and no
// draining goroutine is needed to prove it. Redirecting the variable
// before the application is built is what puts the service logger —
// and therefore the GORM adapter, which writes through it — into the
// capture.
//
// The redirect also decides the handler: a regular file is not a
// character device, so internal/logger installs its JSON handler, the
// one it installs in production under a log collector.
func captureStdoutToFile(t *testing.T) func() string {
	t.Helper()

	path := filepath.Join(t.TempDir(), "stdout.log")

	//nolint:gosec // The path is this test's own t.TempDir().
	f, err := os.Create(path)
	require.NoError(t, err)

	orig := os.Stdout
	os.Stdout = f

	t.Cleanup(func() {
		os.Stdout = orig
		_ = f.Close()
	})

	return func() string {
		require.NoError(t, f.Sync())

		//nolint:gosec // As above.
		b, readErr := os.ReadFile(path)
		require.NoError(t, readErr)

		return string(b)
	}
}

// firstBootSecrets are the two values a first boot generates and
// stores, read back out of the database.
type firstBootSecrets struct {
	sessionKey   string
	passwordHash string
}

// readFirstBootSecrets reads those two secrets straight out of the
// SQLite file with database/sql rather than through GORM, so that
// reading them cannot itself add a line to the log under test.
func readFirstBootSecrets(
	t *testing.T, dataDir string,
) firstBootSecrets {
	t.Helper()

	db, err := sql.Open("sqlite", filepath.Join(
		dataDir, "webhooker.db",
	))
	require.NoError(t, err)

	defer func() { require.NoError(t, db.Close()) }()

	ctx := context.Background()

	var got firstBootSecrets

	require.NoError(t, db.QueryRowContext(
		ctx, `SELECT value FROM settings WHERE key = 'session_key'`,
	).Scan(&got.sessionKey))

	require.NoError(t, db.QueryRowContext(
		ctx, `SELECT password FROM users WHERE username = 'admin'`,
	).Scan(&got.passwordHash))

	require.NotEmpty(t, got.sessionKey)
	require.Contains(t, got.passwordHash, argon2Prefix)

	return got
}

// bootAtDebug starts and stops the real application graph against
// dataDir with DEBUG=true and nothing else set, and returns everything
// it wrote to standard output.
//
// config.New reads DEBUG from the environment exactly as the binary
// does, internal/logger builds the handler it builds in production,
// database.New runs the migrations and creates the admin user, and
// session.New takes the session key. Those four are the whole of the
// path that writes either secret.
func bootAtDebug(t *testing.T, dataDir string) string {
	t.Helper()

	config.ClearEnvForTest(t)
	t.Setenv("DEBUG", "true")
	t.Setenv("DATA_DIR", dataDir)

	read := captureStdoutToFile(t)

	var sess *session.Session

	app := fxtest.New(
		t,
		// fx's own log is discarded, not sent to t.Logf: a hook still
		// running after a start or stop timeout would write there after
		// the test has returned.
		fx.NopLogger,
		fx.Provide(
			globals.New,
			logger.New,
			config.New,
			database.New,
			session.New,
		),
		fx.Populate(&sess),
	)

	app.RequireStart()
	app.RequireStop()

	return read()
}

// requireFirstBootWasLogged is the non-vacuity half of the test below.
// Without it a build that logged no SQL at all, or that never reached
// DEBUG, would satisfy every absence assertion.
func requireFirstBootWasLogged(t *testing.T, out string) {
	t.Helper()

	require.Contains(
		t, out, `"level":"DEBUG"`,
		"DEBUG=true did not reach the logger",
	)
	require.Contains(
		t, out, settingsInsert,
		"the session key INSERT was not logged, so its absence "+
			"proves nothing",
	)
	require.Contains(
		t, out, usersInsert,
		"the admin user INSERT was not logged, so its absence "+
			"proves nothing",
	)
}

// TestFirstBootAtDebug_LogsNeitherSecret is the definition of done.
//
// A first boot is the only boot that writes either secret. The
// settings INSERT carries the base64 session encryption key, which is
// the whole of the session security model: anyone holding it can forge
// an authenticated session cookie. The users INSERT carries the admin
// account's Argon2id hash. Under interpolated statement logging both
// landed in the log an operator diagnosing a startup problem pastes
// into an issue.
//
// The secrets are read back out of the database file afterwards, so
// the assertions are made against the values this boot actually
// generated rather than against a pattern that might not match them.
//
// What this test does not cover: the initial admin password itself,
// which internal/database logs once in the clear, on purpose, because
// that line is the only place an operator ever sees it. That is a
// separate decision from the SQL log, and it is documented in the
// README rather than asserted here.
//
// Not parallel: it redirects os.Stdout and sets environment variables,
// both process-global.
//
//nolint:paralleltest // Deliberately sequential; see above.
func TestFirstBootAtDebug_LogsNeitherSecret(t *testing.T) {
	dataDir := t.TempDir()

	// An empty DATA_DIR is what makes this a first boot: with a
	// database already in place neither INSERT runs.
	entries, err := os.ReadDir(dataDir)
	require.NoError(t, err)
	require.Empty(t, entries, "DATA_DIR was not empty")

	out := bootAtDebug(t, dataDir)

	requireFirstBootWasLogged(t, out)

	secrets := readFirstBootSecrets(t, dataDir)

	assert.NotContains(
		t, out, secrets.sessionKey,
		"the session encryption key reached the debug log",
	)
	assert.NotContains(
		t, out, secrets.passwordHash,
		"the admin password hash reached the debug log",
	)
	assert.NotContains(
		t, out, argon2Prefix,
		"an encoded Argon2id hash reached the debug log",
	)
}