Forecourt Engineering, Part 2: The Side Effect That Gave the Fuel Away

On one of our QA rigs, a card went into a pay-at-pump terminal, got its pre-authorisation, and the customer filled up. Then the terminal and the till both reported the sale as delivered for £0, and nothing was ever collected. The fuel was real. We'd just failed to charge for it.

The ticket suspected a fuel grade mismatch. It wasn't the grade. It was a hidden side effect inside a generic stop command, reused for something its author never had in mind, and this post is about how I found it, why I didn't just guard the £0, and what "fix the cause" cost in practice.

This is Part 2 of Forecourt Engineering. Part 1 covered the payment side of a pay-at-pump sale. This one is about the pump side, where our service tells the pump controller what to do.

Following one sale through three logs

The first rule of a money bug is to follow one sale, end to end, and not trust anyone's summary of it, including the ticket's.

So I followed that sale by its correlation id through three sources: our service log, the terminal's log and the pump controller's traces. The grade was allowed. The comms were clean. The controller had read the finished sale perfectly well, with the right volume and the right amount.

The grade theory wasn't silly, for what it's worth. A card approval can restrict which fuel grades the customer is allowed, as Part 1 explained, so a mismatch between the approved grades and the dispensed one is a real failure mode. It just wasn't this one, and following the sale proved that in minutes.Everything upstream was fine. The money went missing inside our own service, in the step where a finished sale gets taken off the pump, which is called cashing out.

How a sale ends up worth nothing

To see how, you need one detail about the pump controller. It keeps two transaction slots per pump, so a pump can hold a finished sale while the next customer starts. When a sale finishes, our service cashes out the slot whose owed amount matches a limit we pass in.

Here's the shape of that gate, as generic C#:

// Cash out the slot that owes exactly what we expect for this sale.
bool ShouldCashOut(PumpSlot slot, int expectedPence) =>
    _pump.IsIdle && slot.AmountOwedPence == expectedPence;

Most of the time the expected amount is the delivered amount, and exactly one slot matches. But there's a branch that passes zero on purpose, for sales that aren't ours to collect. This sale had gone down that branch.

With an expected amount of zero, the only slot owing zero was the empty one. So we cashed out an empty slot, told the terminal the sale was worth £0, and left the real sale sitting on the pump, owed and uncollected.

That's the symptom fully explained. The more useful question was why a pay-at-pump sale, which is ours to collect, had gone down the zero branch at all.

Two ways into the zero branch

The branch had two conditions, and either one sent a finished sale down it. The first was the pump already being marked as paid. That's how the original QA sale went in, and I closed that route in a follow-up change.

The second was the terminal not being in control of the pump. A comment on the ticket pointed at the pump's control flag dropping mid-sale, and that deserved a proper look rather than a guess.

So I set up the scenario on a dev rig: a sale that triggers the backoff behaviour near the limit, where the service stops the pump as it approaches the authorised amount. I turned the controller's frame logging up to debug so I could see the raw messages, not just our interpretation of them. The frames showed the terminal losing control of the pump a fraction of a second after our own service sent a release.

Nobody had meant to send a release. It came from inside a generic stop command.

Getting the logging to show it

Turning the frame logging up took two attempts, and it's a trap worth knowing about in any .NET service that uses a logging framework with levels on both the logger and the output. Lowering the logger to debug wasn't enough. The file output had its own threshold, and until I lowered that too, the decoded fields never reached the file.

Then a search for the control flag's property name found nothing, because the frame decoder logged it under a human-readable label with spaces in it. Neither problem is interesting on its own. Together they're the difference between "the logs don't show it" and "the logs show it if you ask them properly".

The weak fix: guard the symptom

The obvious fix was right there. The money was lost in the zero branch, so guard the zero branch: if a pay-at-pump sale arrives with an expected amount of zero, don't cash it out.

It would have stopped the money going missing. It would also have left the pump's control flag wrong mid-sale, and anything else that reads that flag would still be working from a lie. Guarding the symptom fixes the one reader you've noticed and leaves every other reader broken.

Fix it where every caller routes through, not where the ticket noticed it. The £0 was where the damage showed. The release inside the stop was where it started.

The better fix: find the side effect and move it

Here's what the stop looked like, made generic:

public void Stop(int pumpId)
{
    _controller.SendStop(pumpId);
    _site.ReleasePump(pumpId);   // always gives up ownership
}

For a stop that ends a session, releasing the pump is correct. The customer's done, the terminal's done, and someone else can have the pump.

But the backoff logic reused the same stop for a temporary pause near the limit. A pause isn't the end of anything. The pump was about to carry on, and we'd just told the controller the terminal no longer owned it.

I had three options. Re-claim the pump when it restarts after the pause, guard the zero branch, or take the release out of the stop. Re-claiming would have left one backoff mode broken, because that mode stops without restarting, so there's nothing to hook into. Guarding the branch was the symptom fix above.

Taking the release out of the stop fixed both backoff modes at the source. The question was whether anything relied on the stop releasing.

The audit that made it safe

My first design threaded a flag through the pump controller interface, so each caller could say "release" or "don't release". It was careful, and it was wrong, because I hadn't looked at the callers yet.

So I audited every caller of that stop. There were three. The two backoff callers wanted no release at all. The third was the cancelled-payment path, which calls another method straight afterwards that removes the authorisation and releases the pump on its own.

So no caller needed the stop to release. The flag wasn't needed, and I dropped it. The shipped change was one line, commented out with a note saying where release actually lives:

public void Stop(int pumpId)
{
    _controller.SendStop(pumpId);
    // Release is owned by CashOut, Release and RemoveAuthorisation, not by Stop.
}

And a regression test pins the one behaviour the audit said mattered:

[Fact]
public void Cancelled_payment_still_releases_the_pump()
{
    // Arrange
    var pump = GivenAClaimedPump();
 
    // Act
    _controller.PaymentCancelled(pump.Id);
 
    // Assert
    _site.Received(1).ReleasePump(pump.Id);
}

The whole fix is smaller than the flag design would have been, and it touches no interface at all. That's usually what happens when you read every caller before you write the abstraction. The audit is the work; the diff is the receipt.

What made this findable

I want to be honest about how much of this was method and how much was luck.

The method was following one sale through every log by its correlation id, and refusing the ticket's theory until the evidence agreed. That got me to "the money went missing when we cashed out" quickly.

The luck was a comment on the ticket that pointed at the control flag. Without it, I might have closed the first route, seen the tests pass and moved on. The rig run with frame logging at debug turned that comment into proof: the flag dropped after our release, which meant the service was doing it, not the pump or the network.

Nothing in our normal logging would have caught this on a live site. That's the part that still bothers me, and it's why the next section exists.

Sites on a different kind of pump controller were never affected. That controller's stop doesn't touch ownership at all, which is its own small argument for keeping "stop" and "release" as separate operations.

Why didn't a test catch it earlier? Because every piece was correct on its own.

A unit test of the stop would assert that it releases the pump, and pass, because that's what it was written to do. The bug only exists in the combination: a pause that reuses the stop, followed by a cash-out that reads the control flag. Tests written one method at a time can't see a side effect that only matters two calls later.

Where it falls over

The branch had two ways in, and my first change closed only one. The original QA sale went in because the pump was already marked as paid. A follow-up change closed that route too, but the first fix on its own wasn't the whole story, and I should have mapped both entrances before shipping either.

"Who frees the pump" is now an implicit rule. The comment in the stop says where release lives, and a test pins the cancelled path. But a future caller could still read "stop" and assume it releases, because that's what it used to do. I'd rather that invariant lived in a test for every caller than in one comment.

The cash-out gate still isn't fail-safe. An expected amount of zero will happily cash out an empty slot while the other slot owes real money. My investigation recommended holding and warning in that case instead, something like this:

if (expectedPence == 0 && slots.Any(s => s.AmountOwedPence > 0))
{
    Log.Warning("Refusing to cash out an empty slot while another slot owes money");
    return false;
}

That would turn this whole class of bug into a warning instead of lost revenue. I'd still push for it.

Audit the callers before you move a side effect

My position: when a method has a side effect its name doesn't mention, sooner or later someone reuses it for something the side effect breaks. "Stop" that also means "give up ownership" was fine until someone needed a pause.

When you find one, don't guard the symptom where the ticket noticed it. Search for every caller, work out which of them actually want the side effect, and move it to the one place that should own it. Then pin the behaviour that matters with a test, because the next person to reuse the method won't read your comment.

Next in the series: a whole bank of card terminals that went dark overnight, and a dependency that was perfectly healthy until every client signed in at the same moment. The rest of my writing is on the blog.