Log SQL with placeholders, never bound values (closes #207) (#222)

internal/gormlog/values_test.go

@@ -0,0 +1,185 @@
+package gormlog_test
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/gorm"
+)
+
+// secretValue is bound as a parameter by every case below. Nothing
+// else in this package writes it, so finding it in captured output
+// means a bound value was rendered into the log.
+const secretValue = "QQBOUNDVALUEMARKERQQ"
+
+// The three messages Trace emits under, one per arm.
+//
+// routineLine is a substring of slowLine, so a case that wants the
+// routine arm has to rule the slow one out as well rather than rely on
+// Contains alone.
+const (
+	routineLine = "sql statement"
+	slowLine    = "slow sql statement"
+	errorLine   = "sql statement failed"
+)
+
+// boundValueCase is one arm of Trace, driven by a statement that binds
+// secretValue.
+type boundValueCase struct {
+	name  string
+	slow  time.Duration
+	want  string
+	drive func(t *testing.T, gdb *gorm.DB)
+}
+
+// insertSecret returns a driver that inserts one row whose Name is the
+// secret.
+func insertSecret(id string) func(*testing.T, *gorm.DB) {
+	return func(t *testing.T, gdb *gorm.DB) {
+		t.Helper()
+
+		require.NoError(t, gdb.Create(&thing{
+			ID: id, Name: secretValue,
+		}).Error)
+	}
+}
+
+// insertSecretTwice drives the error arm: the same primary key a
+// second time is a UNIQUE constraint failure, which is an error GORM
+// logs with the statement.
+func insertSecretTwice(t *testing.T, gdb *gorm.DB) {
+	t.Helper()
+
+	require.NoError(t, gdb.Create(&thing{
+		ID: secretValue, Name: secretValue,
+	}).Error)
+	require.Error(t, gdb.Create(&thing{
+		ID: secretValue, Name: "other",
+	}).Error)
+}
+
+// selectSecret drives a query whose WHERE clause binds the secret,
+// covering the read side as well as the write side.
+func selectSecret(t *testing.T, gdb *gorm.DB) {
+	t.Helper()
+
+	var got []thing
+
+	require.NoError(
+		t, gdb.Where("name = ?", secretValue).Find(&got).Error,
+	)
+}
+
+func boundValueCases() []boundValueCase {
+	return []boundValueCase{
+		{
+			name: "routine", slow: neverSlow,
+			want: routineLine, drive: insertSecret("routine"),
+		},
+		{
+			name: "slow", slow: alwaysSlow,
+			want: slowLine, drive: insertSecret("slow"),
+		},
+		{
+			name: "error", slow: neverSlow,
+			want: errorLine, drive: insertSecretTwice,
+		},
+		{
+			name: "select", slow: neverSlow,
+			want: routineLine, drive: selectSecret,
+		},
+	}
+}
+
+// TestBoundValues_NeverReachTheLog states the values-off property
+// directly, on each arm of Trace that emits.
+//
+// Truncation is not what is being asserted. A bounded secret is still
+// a secret: the session key is 44 base64 characters and an Argon2id
+// hash under 100, so both fit inside every budget this package
+// applies. What keeps them out is that the adapter logs the
+// statement's shape and discards its parameters — see
+// (*Logger).ParamsFilter — and that has to hold at DEBUG as much as on
+// an error, because DEBUG is the level at which a successful INSERT is
+// written at all.
+//
+// Each case also requires a placeholder in the logged statement.
+// Without that, the absence of the value would be satisfied by a
+// logger that wrote nothing useful.
+func TestBoundValues_NeverReachTheLog(t *testing.T) {
+	t.Parallel()
+
+	for _, tc := range boundValueCases() {
+		for _, h := range handlers() {
+			t.Run(tc.name+"/"+h.name, func(t *testing.T) {
+				t.Parallel()
+
+				var buf bytes.Buffer
+
+				gdb := openDB(t, &buf, h.make(&buf), tc.slow)
+
+				tc.drive(t, gdb)
+
+				assertNoBoundValue(t, buf.String(), tc.want)
+			})
+		}
+	}
+}
+
+// assertNoBoundValue holds one captured arm to the property: it wrote
+// the line it was supposed to write, that line kept its placeholders,
+// and it carried no bound value.
+func assertNoBoundValue(t *testing.T, out, want string) {
+	t.Helper()
+
+	require.Contains(
+		t, out, want,
+		"the arm under test wrote nothing, so the assertions "+
+			"below are vacuous",
+	)
+	assert.NotContains(
+		t, out, secretValue,
+		"a bound parameter was rendered into the log",
+	)
+	assert.Contains(
+		t, out, "?",
+		"the statement was logged without its placeholders",
+	)
+}
+
+// TestInsert_KeepsOnePlaceholderPerBoundValue pins the shape of the
+// INSERT specifically, since that is the statement that carries both
+// first-boot secrets. A statement that dropped one value and kept the
+// other would satisfy the assertions above.
+func TestInsert_KeepsOnePlaceholderPerBoundValue(t *testing.T) {
+	t.Parallel()
+
+	var buf bytes.Buffer
+
+	gdb := openDB(t, &buf, handlers()[0].make(&buf), neverSlow)
+
+	require.NoError(t, gdb.Create(&thing{
+		ID: "m", Name: secretValue,
+	}).Error)
+
+	out := buf.String()
+
+	require.Contains(t, out, "INSERT INTO")
+	assert.NotContains(t, out, secretValue)
+
+	for line := range strings.SplitSeq(out, "\n") {
+		if !strings.Contains(line, "INSERT INTO") {
+			continue
+		}
+
+		assert.GreaterOrEqual(
+			t, strings.Count(line, "?"), 2,
+			"insert logged fewer placeholders than it bound "+
+				"values: %s", line,
+		)
+	}
+}