EYThe LogEmre Yakut
← all entries
Servers · Protocol · Debugging · deep

The watchman said “all clear”, because it was counting the wrong stage

There was a mail loop on the server and my monitoring script had been reporting “bounces = 0” for a month. The number was correct. What it measured was wrong.

118.321reddedilen denemegözcü “bounce = 0” diyordu. çünkü yanlış aşamayı sayıyordu.DATA aşamasında sayılan red: 0gerçek: RCPT aşamasında reddediliyordukök neden: 4 takılı mail + bozuk adres listesibir aydır sürüyordu, bugün başlamamıştı

A shared server hosts dozens of projects. To watch its mail traffic I had written my own monitoring script: it runs every half hour and reports restricted accounts, queue length and bounce counts.

For weeks it wrote “clean run”. Then sending stopped for one account, and looking for the reason produced this number: 118,321 rejected attempts. It had been running for a month.

Why the watchman did not see it

My script worked correctly. What it counted was wrong.

An SMTP session proceeds in stages:

MAIL FROM: <sender@…>       → 250 OK
RCPT TO:   <recipient@…>     → 550 User unknown   ← it ended here
DATA                                                   ← never reached

If the recipient address is invalid, the server rejects it at the RCPT stage. The message is never transferred, never accepted, and therefore produces no bounce.

A bounce is an accepted message that could not be delivered. That is what I was measuring. The problem was one step earlier.

which is why “0” was not reassurance

When a metric reads zero there are two possibilities: it really is zero, or it is counting the wrong thing.

The only way to distinguish them is to trigger the metric deliberately and watch the counter move. I had never done that — the counter had been zero since the day it was born and I took that as good news.

I fixed the script: rejections at the RCPT stage are now counted too. On the first run the number jumped from zero to six figures. The reality had not changed — visibility had.

The root cause

With visibility, the real work began. The chain:

  1. An application sends bulk mail to a notification list.
  2. A few addresses on the list are malformed — bad format, no such domain.
  3. Sending fails; the application treats it as a temporary error and retries.
  4. Because it is permanent, every retry fails identically.
  5. Four messages stuck in the queue spin forever.

Step three is the real bug. A 550 is a permanent rejection; retrying can never help. Temporary errors (4xx) are retried, permanent ones (5xx) are not. The application did not distinguish them.

I cleared the four stuck messages and the loop stopped.

Other blind spots found the same week

The incident raised a suspicion: what else is being measured wrongly? I went looking.

An alert mailbox nobody had opened for a month

Firewall alerts were being sent to an email address. Nobody had opened that mailbox in fifteen months: 129,954 alerts, 686 MB.

The alerts worked. Nobody looked. That is no different from having no alerts at all — worse, in fact, because it manufactures a false confidence that “we have monitoring”.

System mail going nowhere

The system account’s mail was being forwarded to an external address by a forwarding file and caught by a filter there. So the server’s own critical notifications had been disappearing for a month. It was moved back to a local mailbox.

A bug in my own formula

On one run I found the time filter in my bounce-rate calculation was wrong — it looked at a wider window than the last 30 minutes. After fixing it I saw a genuine zero for the first time.

And on the same day I recorded that four separate “alarms” had been my own measurement errors. The watchman is itself a system that needs auditing.

One discipline: every finding gets written down

All of these runs are recorded in a repository:

watch 02:17: FINDING — alerts piling into a mailbox unread for 15 months
watch 00:40: clean run — four false alarms were my own measurement errors
CORRECTION: the loop did not start today, it has been running at least a month

The third line matters. My first diagnosis was “it started today”; the logs showed otherwise and I recorded the correction too. Writing down that a diagnosis was wrong is as valuable as writing the right one — it stops you jumping to the same wrong diagnosis next time.

What I learned

Monitoring systems give confidence. And that confidence rests on the assumption that the system is measuring the right thing.

Now I ask every new metric one question: how do I make this number go up? If I cannot trigger it deliberately and watch the counter move, I do not trust it.

An alarm system that has never fired is either a perfect system or is not connected. The only way to tell is to try it.

I got the same answer when I asked the same question of my room measurement tool.

ServersProtocolDebugging