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, ) } }