omeryanbas.com

Ömer Yanbaş

General Manager, Ticofab Yazılım

MessagingData

The delivery report that arrives before the record

An asynchronous callback can reach you before the row it refers to is committed. Keep the orphan, retry the match, and stop losing final states.

We send an item through a provider, the provider answers with an identifier, and we write a row that says the item is submitted. Some time later the provider calls our callback URL with the final state for that identifier. On a quiet system that order always holds. Under load it stops holding, and a handler that treats an unknown identifier as a bad request throws away the only notification that item will ever get.

What actually happens

The send and the report travel on two different paths and nothing synchronises them. The send is our outbound HTTP request or our open session to the provider. The report is an inbound HTTP request from the provider to us, made by a different machine, on a different connection, at a moment nobody coordinates.

A batch makes the gap wide enough to fall into. The shape I keep finding looks like this:

  1. We open a transaction.
  2. We submit five hundred items in a loop, collecting identifiers as we go.
  3. We insert five hundred rows.
  4. We commit.

The provider accepts the first item in tens of milliseconds and a handset can answer in well under a second. So the report for item number one arrives while we are still submitting item number three hundred. The callback handler runs a SELECT, and a SELECT in another connection cannot see rows from a transaction that has not committed. The row is not missing. It is invisible.

Then the handler decides what to do with something it cannot find, and the usual decision is the expensive one:

/* the version that loses reports */
app.post('/callbacks/report', async (req, res) => {
  const { ref, status, at } = parse(req.body);
  const row = await db.messages.findByRef(ref);
  if (!row) {
    log.warn('unknown report', { ref });
    return res.status(200).send('OK');   /* and the payload is gone */
  }
  await db.messages.update(row.id, { state: map(status), finalisedAt: at });
  res.status(200).send('OK');
});

It answers 200, which is right as far as the provider is concerned, and then drops the payload. Nobody sends that report again. The row commits half a second later and sits in the submitted state until someone opens a report and asks why a whole batch looks like it vanished.

There is a third contributor that is easy to miss. If the callback carries the provider's own identifier and our row stores ours, the join needs a mapping table, and that mapping row was written by the same transaction as the message row. It has exactly the same visibility problem, so adding the mapping table does not help.

How to see it

Two queries and one log count tell you whether you have a race or genuinely silent items. First, count items that never reached a final state, grouped by the hour they were created:

SELECT date_trunc('hour', created_at) AS hour,
       count(*) FILTER (WHERE finalised_at IS NULL) AS still_open,
       count(*) AS total
FROM messages
WHERE created_at < now() - interval '6 hours'
GROUP BY 1
ORDER BY 1 DESC
LIMIT 12;

Read the shape, not the total. If still_open is a small flat number in every hour, those are items the provider never reported on. If it rises and falls with the send volume of the hour, and the worst hours are the busiest ones, you are looking at a race.

Then count what the handler admitted it could not match:

grep -c "unknown report" /var/log/app/callbacks.log

If that count is close to the number of stuck items, the reports arrived and the code discarded them. That is the whole diagnosis, and it takes two minutes.

The fix

Three changes, in order of how much they matter.

Make the submit identifier the key the callback carries. Nearly every messaging API and SMPP binding accepts a client reference on submit and echoes it in the report. Generate that identifier yourself before anything leaves the process, so there is one key from end to end and no mapping table to go stale:

const ref = newId();                       /* ours, before the submit */
await provider.submit({ to, body, clientRef: ref });
await db.messages.insert({ ref, state: 'SUBMITTED', createdAt: new Date() });

Never discard an unmatched report. Write it to a small inbox table keyed by the fields the provider actually sends:

CREATE TABLE report_inbox (
  ref          text        NOT NULL,
  status       text        NOT NULL,
  reported_at  timestamptz NOT NULL,
  received_at  timestamptz NOT NULL DEFAULT now(),
  attempts     int         NOT NULL DEFAULT 0,
  next_try_at  timestamptz NOT NULL DEFAULT now(),
  PRIMARY KEY (ref, status, reported_at)
);

That primary key is doing real work. Providers resend reports, and a resend of the same state for the same reference at the same instant is the same fact, so an insert that conflicts on the key can be ignored instead of handled.

Retry the match with a growing delay. A worker walks the inbox, tries to attach each report to a row, and pushes the ones it cannot attach further out:

const BACKOFF = [1, 5, 15, 60, 300, 1800, 7200, 21600]; /* seconds */

for (const r of await inbox.due(200)) {
  const applied = await db.query(
    `UPDATE messages
        SET state = $2, finalised_at = $3
      WHERE ref = $1
        AND (finalised_at IS NULL OR finalised_at < $3)`,
    [r.ref, map(r.status), r.reported_at]
  );
  if (applied.rowCount > 0) { await inbox.remove(r); continue; }
  const next = BACKOFF[Math.min(r.attempts, BACKOFF.length - 1)];
  await inbox.defer(r, next);
}

The finalised_at < $3 guard is the second half of the fix. Reports do not arrive in order, and a stale intermediate state must not overwrite a newer terminal one.

One cheap addition closes the common case without waiting for a retry: right after the insert transaction commits, look in the inbox for the references you just wrote and apply anything waiting there. That turns a one second delay into no delay for the reports that lost the race by milliseconds.

What this costs is one table, one worker and a couple of extra writes per report. What it does not solve is a provider that never sends a report at all. For those you still need a cut off that moves an item to an unknown state after the longest plausible delivery window, so the queue does not grow forever. The same reasoning applies to a temporary rejection, which is not a permanent failure either and should not turn into a terminal state.

How to check it worked

Coverage is the number to watch, and it is not the delivered rate:

SELECT round(100.0 * count(*) FILTER (WHERE finalised_at IS NOT NULL) / count(*), 2) AS coverage_pct,
       round(100.0 * count(*) FILTER (WHERE state = 'DELIVERED')      / count(*), 2) AS delivered_pct
FROM messages
WHERE created_at BETWEEN now() - interval '48 hours' AND now() - interval '6 hours';

Coverage answers whether our pipeline recorded an outcome. The delivered share answers whether the route worked. On a platform I maintain, coverage sat in the low nineties for months and moved to 99.9 per cent within a day of the inbox going live, while the delivered share settled around 82 per cent and did not move at all. That difference is the point: the routing was always that good, we were just failing to write down what happened.

The inbox itself is the second check. It should stay near empty:

SELECT count(*) AS waiting, max(now() - received_at) AS oldest FROM report_inbox;

A few dozen rows with an age measured in seconds is a healthy race being absorbed. Thousands of rows with an age measured in hours means the reference on the submit and the reference in the callback are not the same key after all.

What to watch out for

  • Answer the callback with a 2xx even when you cannot match it. The only thing that should produce an error there is a failure to persist the payload. Anything else teaches the provider to retry or to stop.
  • Put retention on the inbox from the first day. Unmatched reports are small and they accumulate quickly at peak volume, and a table nobody prunes becomes a disk problem long before it becomes a query problem.
  • Use the provider timestamp for ordering and your own received time for retention. Their clock decides which of two reports is newer, yours decides when a row is old enough to delete.
  • Alert on three things: coverage below your threshold over a rolling window, the age of the oldest unmatched report, and the count of items still in a non final state past the longest delivery window you accept. The first catches a regression, the second catches a key mismatch, the third catches a provider going quiet.

The general lesson is about ownership of identifiers. When a system calls you back about something you sent, the only thing that reliably connects the two events is a key you generated yourself and put on both sides of the conversation. Everything else is a join against a row that may not have committed, against a clock you do not control, in an order nobody promised you. Treat a callback as a durable fact to be stored first and interpreted second, the same way a scheduled job needs its timestamps written in one agreed time zone rather than whatever the reader assumes. The code that stores first is barely longer than the code that drops the payload, and it is the difference between a report you can defend and a batch that looks like it never happened.

Questions and answers

Why would a delivery report arrive before the message record exists?
The send and the report are two separate requests over two separate connections, and nothing orders them. If you submit a batch inside one transaction and commit at the end, the provider can accept the first item, the handset can answer, and the callback can reach you while your transaction is still open. A query inside that callback cannot see uncommitted rows, so the record does not exist yet as far as the handler is concerned.
Should I return an error when the callback refers to an unknown identifier?
No. A non 2xx answer tells the provider that you failed, and most will retry on a schedule you do not control or give up after a few attempts. Accept the payload with a 2xx, store it, and do the matching on your own time. The callback endpoint should only fail when you genuinely could not persist the report.
What is a good delivery report coverage number?
Coverage is the share of items that ever received any final state, delivered or failed. Above 99 per cent is normal on a healthy pipeline, and anything in the nineties usually means reports are being lost rather than never sent. Track it separately from the delivered share, because a low delivered share is a routing problem and a low coverage is a code problem.
How long should I keep retrying to match an orphan report?
Longer than your slowest write path and shorter than your retention window. A backoff that runs from one second to six hours and gives up after a day covers an ordinary race and also covers an item that was queued for hours. Anything still unmatched after that is a genuine mismatch worth logging with the raw payload.