Log-Based Alerting for Mail Queues: Catch Deferral Spikes and Rejection Surges Before Anyone Complains
Your dashboard is green while mail silently backs up. By the time Gmail Postmaster or an angry customer tells you, you have been deferring for six hours. Here is how to alert on the rate of change of queue depth, deferral ratio, and reject rate with grep-grade tooling that fires in three minutes, not two hours.
EvilMail TeamJuly 28, 202612 min read
It is 03:00. Your uptime monitor is green, the SMTP port answers, and postqueue -p | tail -1 reports 214 messages. Looks fine. Except that snapshot is a lie: the queue held 90 messages ten minutes ago and it is climbing 40 msg/min. In two hours it will be 5,000, in four hours Gmail will start tempfailing you in earnest, and by the time a customer ticket wakes you up you will have been quietly deferring for six hours. The snapshot told you nothing because the snapshot has no memory. The mail log does.
Most mail monitoring is built backwards. People wire up an exporter that scrapes postqueue every minute and alert on queue > 5000. That threshold fires late — by 5,000 the outage is mature — and it flaps, because real traffic is diurnal and a healthy Monday-morning burst looks identical to a stuck queue at a single point in time. The signal you actually want is not the depth. It is the derivative: how fast the queue is growing, what fraction of delivery attempts are deferring, and how the reject rate compares to five minutes ago. All three move minutes before any external symptom, and you can capture them from the log with tooling barely more sophisticated than grep.
The three signals that actually predict an outage
There are exactly three numbers worth paging on, and none of them is a raw count.
Queue net-growth rate. Arrivals minus departures per minute. Sustained and positive means you are taking in mail faster than you can deliver it — a backlog forming, regardless of current depth. A queue of 200 growing at +40/min is a five-alarm fire; a queue of 3,000 shrinking at -100/min is a system recovering, and you should not page for it.
Deferral ratio.deferred / (sent + deferred) over a rolling 5-minute window. A pure quality signal, independent of volume. At 2% you are healthy. At 35% something is refusing your mail — a provider is throttling you, or a local resource is broken.
Reject rate versus baseline. 4xx/5xx rejections per minute at smtpd, compared against the trailing 30-minute average. On inbound — the front door of a temp-mail platform like evilmail.pro, which takes a firehose of mail — a reject surge usually means a spam wave or a misfiring RBL, not your fault. On outbound, a 5xx surge from remote servers means your reputation just cratered.
Static thresholds fail on all three because they encode an assumption that traffic is constant. It never is. Rate-of-change and ratios are scale-invariant: they read the same at 10 msg/min and 10,000 msg/min, which is exactly what you want from an alert that has to survive both 3am quiet and a Black Friday campaign.
Where the truth lives: reading the mail log correctly
On Debian/Ubuntu the log is /var/log/mail.log; on RHEL it is /var/log/maillog; under a modern systemd-journal setup, journalctl -u postfix@- -f. Every delivery attempt leaves a line whose status= field is the whole game:
Jul 8 03:12:44 mx1 postfix/smtp[20881]: 8F2A1C0A3B: to=<[email protected]>,
relay=gmail-smtp-in.l.google.com[142.250.x.x]:25, delay=1.9, dsn=4.7.0,
status=deferred (host ... said: 421-4.7.0 Our system has detected an
unusual rate of unsolicited mail from your IP)
Learn the four terminal states cold:
`status=sent` — delivered, gone from the queue.
`status=deferred` — a 4xx transient failure. The message stays queued and Postfix retries with backoff. This is your backlog, and a deferral spike is the earliest honest warning you get.
`status=bounced` — a 5xx hard failure. The remote refused permanently and a bounce is generated.
`status=expired` — the message sat deferred until it hit maximal_queue_lifetime (default 5 days) and was given up on. A rising expired count means you have been silently deferring for days. If you ever see these in volume, your alerting failed catastrophically upstream — the entire point of this article is to fire long before anything expires.
The dsn= field tells you *why*: 4.7.1 and a 421 reply are rate-limiting or greylisting; 4.7.0 is a generic policy tempfail; 5.7.1 is a hard policy block; 5.1.1 is no-such-user. Inbound rejections look different — they come from smtpd as NOQUEUE:
Jul 8 03:14:02 mx1 postfix/smtpd[20990]: NOQUEUE: reject: RCPT from
unknown[203.0.113.9]: 554 5.7.1 Service unavailable; Client host
[203.0.113.9] blocked using zen.spamhaus.org; from=<x@spam> to=<[email protected]>
For instantaneous ground truth about *what* is stuck, nothing beats qshape. qshape deferred prints a matrix of destination domain against message age — one glance tells you whether the backlog is 4,000 messages all bound for gmail.com (a reputation problem with one provider) or spread evenly across every domain (a local problem). postqueue -p | tail -1 gives the summary count; qshape active shows what is being worked right now. Keep these three in muscle memory — they are the first commands you run when an alert fires.
Turning log lines into numbers you can alert on
Two layers, and you want both. The cheap, immediate layer is a tail-and-bucket process that reads the log stream, counts events per minute, and emits the three metrics. You do not need Prometheus to start:
python
#!/usr/bin/env python3
# tail mail.log, emit per-minute mail-health metrics to a webhook. stdlib only.
import sys, re, time, json, urllib.request
from collections import defaultdict
WEBHOOK = "https://hooks.slack.com/services/XXX"
sent = deferred = arrivals = departures = rejects = 0
rej_hist = [] # trailing per-minute reject counts (baseline)
defer_by_domain = defaultdict(int)
bucket = int(time.time() // 60)
def flush():
global sent, deferred, arrivals, departures, rejects
total = sent + deferred
ratio = deferred / total if total else 0.0
net = arrivals - departures
base = sum(rej_hist) / len(rej_hist) if rej_hist else 0.0 # prior minutes only
top = sorted(defer_by_domain.items(), key=lambda kv: -kv[1])[:3]
alert = (total > 50 and ratio > 0.35) \
or net > 30 \
or (base > 1 and rejects > 5 * base)
if alert:
text = (f":rotating_light: mail: defer_ratio={ratio:.0%} "
f"net_queue={net:+d}/min rejects={rejects} (base {base:.1f}) "
f"top_defer={top}")
urllib.request.urlopen(urllib.request.Request(
WEBHOOK, json.dumps({"text": text}).encode()))
rej_hist.append(rejects)
del rej_hist[:-30] # keep a 30-minute window
sent = deferred = arrivals = departures = rejects = 0
defer_by_domain.clear()
for line in sys.stdin:
now = int(time.time() // 60)
if now != bucket:
flush(); bucket = now
if "status=sent" in line:
sent += 1; departures += 1
elif "status=deferred" in line:
deferred += 1
m = re.search(r"to=<[^@]+@([^>]+)>", line)
if m: defer_by_domain[m.group(1)] += 1
elif "status=bounced" in line or "status=expired" in line:
departures += 1
elif re.search(r"qmgr\[\d+\]: \w+: from=", line):
arrivals += 1
elif "NOQUEUE: reject:" in line:
rejects += 1
The trick for queue growth is to never poll `postqueue` in a loop — that is expensive and races the qmgr. Derive it from the log instead: arrivals are qmgr[...]: <qid>: from= lines (each message logs once when it enters the active queue), departures are status=(sent|bounced|expired), and net = arrivals − departures per minute. That gives you a real-time growth curve for free.
The second layer is a batch report for humans. Run pflogsumm on a 5-minute cron and it hands you the deferral and reject breakdown by reason and domain:
The Deferrals and message reject detail sections are exactly what you paste into an incident channel when someone asks "deferring to whom, and why?"
Wiring alerts that fire on the derivative
The alerting logic is where most people go wrong by paging on a bare threshold. Every rule needs two guards: a sustained window to kill flapping, and an absolute volume floor so a single deferral in a quiet minute cannot produce a 100% ratio. The idiomatic Prometheus version uses mtail to turn log lines into counters, then alerts on rates:
With no Prometheus, the Python tailer above already encodes the same conditions. The mtail program is a dozen lines of /status=deferred/ { delivery_total["deferred"]++ }-style patterns; grok_exporter or Loki with rate() LogQL queries are equally valid.
Two non-negotiables. First, break out per destination domain in the alert body. "Deferral ratio 40%" is a shrug; "Deferral ratio 40%, 92% of it to gmail.com" is a diagnosis. Second — the classic trap that has burned every mail operator once — route alerts out-of-band. You cannot email an alert about the mail server being down. Push to Slack, Telegram, or a PagerDuty webhook over plain HTTPS. If your alert path depends on SMTP, it will go silent at exactly the moment you need it.
Reading the alert: deferral vs reject playbook
The alert fires. Now match the symptom to the cause:
Deferral spike to one domain. That provider is rate-limiting or greylisting you. Check the dsn (4.7.1, 421) and the remote's text — it often literally says "unusual rate of unsolicited mail" or "IP not in whitelist." First command: qshape deferred | head. If it is all one domain, you have a reputation or volume issue with that provider, not a local fault. Slow down with smtp_destination_rate_delay, check your SPF/DKIM/DMARC alignment, and look that IP up in the provider's postmaster tools.
Deferral spike across all domains. Local problem. DNS resolution is failing, TLS is broken, the spool disk is full, or qmgr is wedged. First commands: df -h /var/spool/postfix, postfix status, dig +short gmail.com MX. When every destination defers at once, stop looking outward.
Inbound reject surge (NOQUEUE). A spam wave hitting the front door, a misfiring content filter, or an RBL that just went rogue with false positives. Run grep NOQUEUE /var/log/mail.log | tail -50 and read the reject reason. If every reject cites the same RBL, that RBL may be broken — verify before you keep bouncing legitimate senders.
Outbound 5xx surge from remotes. You are on a blocklist. The 5xx text usually contains a URL; open it. grep "status=bounced" /var/log/mail.log | grep -oE 'said: 5[0-9.]+ .*' | sort | uniq -c | sort -rn clusters the reasons fast.
Checklist: a working alerting stack in an afternoon
Confirm the log format and that rsyslog/journald is actually capturing postfix/smtp and postfix/smtpd at full detail.
Install mtail (or drop in the tail -F script) and point it at the live log.
Define the three metrics: queue net-growth, deferral ratio, reject rate vs baseline. Nothing else pages.
Set sustained-window thresholds with a volume floor — for: 3m and > 50 msg/min, never a bare number.
Add per-destination-domain labels so the alert body names the culprit.
Route delivery to Slack/Telegram/PagerDuty over HTTPS — never SMTP.
Test with a synthetic deferral: throttle a test domain with smtp_destination_concurrency_limit=1 and smtp_destination_rate_delay=30s in a transport override, or null-route it, and watch the alert fire.
Verify the alert clears when you remove the throttle — an alert that does not resolve is noise.
Put a runbook link in the alert annotation so on-call reads the playbook, not the source code, at 3am.
Run pflogsumm on a 5-minute cron for the human-readable breakdown.
After one week of real diurnal traffic, revisit thresholds — your quiet-hour floor and your peak ratio are now measured, not guessed.
Build this and the failure mode inverts. Instead of learning about a backlog from a Spamhaus listing or a customer ticket four hours late, you get a Slack ping three minutes into a 0-to-800 deferral ramp, with the offending domain named in the message. The mail log always knew. Now something is reading it.
