Back to Blog
Insights

The Failures That Log Success: Why a Log Line Is a Claim, Not Evidence

An error is a gift. It has a timestamp, a stack, and a place to start looking. Every developer says they hate them and every developer would rather have one than the alternative, which is a system that finishes cleanly, returns 200, writes a reassuring line to the log, and did not do the thing.

What follows is four shapes of that failure, each found in one sweep of our own fleet of seven Shopify apps at the end of August and each fixed at the layer all seven share, what made each one invisible, and the structural change that makes the category harder to repeat. If you run more than one service, the last section is the part worth stealing.

One: The Error That Would Not Say Who

Two uninstall webhooks arrived four days apart and logged, in full: post-auth error: Response 500.

That line is not wrong. There was a 500, and it is a known one — when a shop uninstalls, the framework tries to refresh an expiring offline token against a token that has just been revoked, and it throws. The shared wrapper catches that, runs a fallback cleanup, and returns 200 to Shopify, which is exactly right: a webhook endpoint that returns 500 gets retried and eventually gets you removed from the delivery list. The swallow is correct. The handling is correct.

What the line lacked was which store had uninstalled.

The detail that generalises: the shop domain was on the request the entire time, in an HMAC-verified header, and the wrapper was already reading it to run the fallback cleanup. It read the value, used it, and never put it in the sentence. The information was in the function's own scope.

The failure was the silence, not the exception

It is easy to read this as "an error was swallowed." It was not: the exception was handled deliberately and correctly. What was lost was the identity attached to it. A correctly-handled error that cannot be attributed to anything is an event you can count and never act on, which over time is indistinguishable from noise. All seven apps share that wrapper, so all seven now name the shop, include the response body, log the fallback cleanup succeeding, and shout when the header is missing — because a cleanup that got skipped should be louder than one that worked.

Two: The Erasure That Was Narrower Than Its Log Line

Shopify sends a shop/redact webhook when a merchant's data must be erased. The handler logged erasing all shop data, and the sentence had been true when it was written, when the only shop-keyed table was the session store. The schema had since grown a subscription mirror, and in five apps a settings table, and the handler had not grown with it. That was confirmed against production before the fix rather than inferred from the code.

What makes this instructive rather than merely a missed table is why the mirror row exists. It is deliberately designed to survive an uninstall. It carries the flag that records whether a shop has already used its free trial, and if uninstalling wiped it, uninstall-and-reinstall would be a free trial generator. Surviving uninstall is a feature.

But redact is not uninstall. Uninstall is a business event; redact is a legal erasure mandate. And a row keyed by the merchant's own domain is, unambiguously, shop data. The correct answer turned out not to be "make the mirror survive less" or "make redact delete more" in general, but to separate the two paths on purpose: uninstall purges sessions only; redact erases every shop-keyed model. Two webhooks that look adjacent, with deliberately different jobs, in all seven apps.

Why a log line is not evidence

“Erasing all shop data” was written by a developer describing what the function was for. Nothing checked that the sentence and the behaviour still matched, and over time and across seven codebases they drifted apart. A log line is a claim, and an unverified claim in a log is worse than no line at all, because it converts a question into a false answer.

Three: The Mailer That Degrades So Gracefully It Does Nothing

The third one had not run yet. It was scheduled for the following Monday.

One app had just gained a monthly compliance statement — an email summarising a merchant's verification log. The mailer was written to degrade gracefully: if SMTP is not configured, log SMTP not configured, send nothing, throw nothing. That is a reasonable design in isolation. It means a missing credential in a development environment does not crash a scheduled job.

The credential was not yet in the production environment. So the first run would have sent zero emails, and every other line in that job's log would have looked completely healthy: shops processed, statements generated, run completed. One quiet line in the middle, indistinguishable from a dev-environment message, standing between a feature and its entire purpose.

The detail that generalises past this one case: a deploy dry run could not have caught it. A dry run skips the transport, which is the whole point of a dry run — and it is exactly why a dry run is a check on your intent to deploy, not on whether the deployed thing works. We have written before about the gap between a service being enabled and a service being alive. This is the same gap, one layer up.

The fix location mattered as much as the fix. The credential block went into the deploy master rather than being added by hand to the live environment file, because the master regenerates that file on every deploy and would have silently overwritten a hand fix on the next update. A repair that the next deploy erases is not a repair; it is a delay with a false sense of completion attached.

Four: The Retry With No Way to Stop

The last one is small and worth the paragraph because of its shape.

A scheduled monitoring job classifies failures as permanent or transient: a store that is gone forever should be dropped, a store that timed out should be retried tomorrow. A shop whose session records had disappeared — uninstalled at some point with the webhook missed — threw a session-not-found error that matched none of the permanent-failure patterns. So it was transient. So it would be retried. Tomorrow, and the day after, and every day after that, quietly, in a job whose summary line would report a small number of failures every morning and never change.

Session-not-found is now permanent. But the general lesson is about the default: an unrecognised failure classified as “retry” produces an infinite loop, while an unrecognised failure classified as “stop” produces an alert. Both defaults are wrong sometimes. Only one of them is wrong quietly.

What the Four Have in Common

Line them up and the pattern is not really about logging.

What each one produced

  • A correct 200, and no attribution
  • A log line describing an erasure that partly happened
  • A healthy job summary with nothing sent
  • A daily failure count that never changed

What each one needed

  • The identity that was already in scope
  • A check that behaviour still matches the claim
  • A test that exercises the transport
  • A default that stops rather than loops

Every one of them was a place where the system had the information it needed and did not use it. The shop domain was in the request. The list of models was in the schema. The absent credential was in the environment. The unmatched error string was in the exception. None of these required a new signal; they required something to look at a signal already present and compare it against a promise.

The Move Worth Stealing: Re-derive, Don't Restate

The fix that matters most here is not any of the four. It is the test written for the second one, and the idea behind it applies to almost any codebase.

The obvious way to test an erasure routine is to list the models it should delete and assert it deletes them. That test passes forever and protects nothing, because the day someone adds a new table to a schema, the test does not know the table exists. The list in the test is a restatement of the schema, and restatements go stale silently — which is the exact failure mode this whole article is about.

So the test reads each app's schema directly and re-derives which models are shop-keyed, then asserts that the erasure covers every one of them. Add a model to any of the seven schemas and the test fails until its erasure line exists. Nobody has to remember. The test also pins two things that would otherwise be silent: an erasure aimed at a renamed model (which, inside a handler that deliberately returns 200 on error, would void the erasure without a sound), and the fact that uninstall keeps the mirror row — so a future well-meaning developer cannot "complete" the uninstall path and hand out free trials.

The general rule

If a test contains a list that also exists somewhere else in your codebase, the test is a copy and the copy will rot. Read the source of truth at test time and derive the list. It is usually five extra lines, and it converts a check that guards today into one that guards every day after.

What the Response Looked Like

Each fix went to the layer all seven apps share, so every app got it at once. Production was checked rather than assumed. The fix location was chosen so the next deploy could not undo it. And the test that pins the erasure derives from the schema rather than repeating it, which is the only part that makes next time genuinely less likely.

The lesson we would actually press on anyone running a fleet: go and grep your own codebase for log lines that describe an outcome. Every “erasing…”, “sent…”, “cleaned up…”, “completed…”. Each one is a claim somebody made about behaviour at the moment they wrote it, and nothing in your test suite is checking that the sentence is still true. Most of ours were fine. The interesting ones were the ones this article is about.

Previous: Payout Guard vs the Payouts Page Next: The Lot Dev Log #1