'A simple, iterative workflow to debug sqlmock expectation errors when testing GORM by using its built-in logger to reveal the exact SQL queries.'
When writing tests for our Go backend, we rely heavily on sqlmock to ensure our database logic is solid without hitting a real database. It's a fantastic tool, but it has one strict requirement: your mock expectations must exactly match the SQL queries your code generates.
This can get tricky when using an ORM like GORM. GORM is great for productivity, but the SQL it generates under the hood—especially for complex operations like AutoMigrate with multiple index creations—isn't always obvious. We found ourselves in a cycle of "guess, run, fail, repeat."
So, how do you find out the exact SQL GORM is trying to run?
We've settled on a simple, iterative debugging workflow that turns this guessing game into a straightforward process. Here’s how we do it.
The Challenge: Unpredictable SQL
The core problem is that sqlmock fails if the expected query string doesn't match the actual query string. With GORM's AutoMigrate, for example, the order in which it decides to create tables and indexes can change as you add new models or even between GORM versions. You might expect CREATE INDEX idx_A before CREATE INDEX idx_B, but GORM does the opposite, and your test fails with a cryptic message.
The Technique: Let the ORM Tell You What It's Doing
Instead of trying to guess the SQL, we make GORM tell us directly. The key is its built-in logger.
Here's our step-by-step process:
Step 1: Isolate the Failing Test
Run your tests and find the first sqlmock expectation that fails. The error message is your starting point. It will usually say something like:
Error: call to ExecQuery '...' with args [...] was not expected, next expectation is: ...
Step 2: Enable Verbose Logging
In your test setup where you initialize your GORM connection with the mocked SQL connection, temporarily switch the GORM logger to Info mode.
// In your test file...
import "gorm.io/gorm/logger"
// ...
// Temporarily change logger.Silent to logger.Info
gormDB, err := gorm.Open(dialector, &gorm.Config{ Logger: logger.Default.LogMode(logger.Info), })
Step 3: Run the Test and Observe
Run the single failing test again (e.g., go test -run TestMyFailingTest). Now, look at your console output. Because the logger is in Info mode, GORM will print the exact SQL query it's generating, right before sqlmock reports the failure.
The output will look something like this:
[info] /path/to/your/code.go:123 [SQL] CREATE INDEX "idx_commission_withdrawals_timestamp" ON "commission_withdrawals" ("timestamp") ... [error] ExecQuery: could not match actual sql: "CREATE INDEX..." with expected regexp "CREATE INDEX...recipient_address..."
Step 4: Copy, Paste, and Adapt
The "actual sql" from the log is the source of truth.
- Copy the SQL query from the log output.
- Paste it into your test file, replacing or reordering the incorrect expectation in
mock.ExpectExec(...)ormock.ExpectQuery(...). - Adapt it for
sqlmock. You might need to escape special characters for the regex matcher (like parentheses\(and\)).
Step 5: Rinse and Repeat
Your test will now pass the first expectation and likely fail on the next one in the sequence. That's progress! Just repeat steps 3 and 4 for the new failing expectation until the entire test passes.
Step 6: Clean Up
Once the test is green, remember to switch the GORM logger back to logger.Silent to keep your test logs clean for everyone else.
// Change it back for clean test runs
gormDB, err := gorm.Open(dialector, &gorm.Config{ Logger: logger.Default.LogMode(logger.Silent), })
This simple, iterative process has saved us countless hours of frustration. By using the ORM's own logging, we get a definitive answer to "What query are you actually running?" and can write precise, reliable database tests.
Hope this helps you in your projects!
Top comments (0)