DEV Community

Christian Anderson
Christian Anderson

Posted on

The bug that marked 9,133 emails as read

The bug report I got from myself was: "email isn't working, the filtering is wrong."

The filtering was fine. What was actually happening is that a bot had marked 9,133
of the 9,143 messages
in my personal Gmail inbox as read, a few seconds after each
one arrived, for months.

The cause is one word.

One word

The mail adapter polled the inbox every 15 seconds and fetched each new message like
this:

status, msg_data = imap.uid("fetch", uid, "(RFC822)")
Enter fullscreen mode Exit fullscreen mode

RFC822 is not a peek. Per RFC 3501, fetching it sets the \Seen flag as a side
effect
. Reading the message marks it read — that is the specification working
exactly as written.

The measurement before the fix:

total  : 9,143
SEEN   : 9,133
UNSEEN :    10
of the newest 30 messages, 29 already marked SEEN
Enter fullscreen mode Exit fullscreen mode

The fix is to ask for the identical bytes without the side effect:

status, msg_data = imap.uid("fetch", uid, "(BODY.PEEK[])")
Enter fullscreen mode Exit fullscreen mode

Same content. No flag write.

Why the filtering got the blame

This is the part I find more interesting than the flag.

The adapter had a sender allowlist, and it worked. It also had built-in filters for
automated mail — List-Unsubscribe, Precedence: bulk, Auto-Submitted. Those
worked too. Every piece of the filtering logic was correct.

But filtering happened at dispatch, after the fetch. So the sequence for a message
the bot had no interest in was:

  1. fetch it — \Seen is set
  2. decide it isn't from an allowed sender
  3. discard it

Messages the system deliberately ignored were still marked read. The more
effective the filter, the more invisible damage it did. And because the visible
symptom was "mail I care about looks already-read," every instinct pointed at the
filtering configuration — the one subsystem that was behaving perfectly.

When a symptom points at a component, check whether that component is downstream of
something with side effects. Reading is not supposed to be a write, so nobody audits
the read path.

The second bug, which arrives the moment you fix the first

Here is the trap, and it is the reason I'm writing this up.

The poller found new messages by searching for UNSEEN. That worked — because
something was setting \Seen on everything it touched. The bug was the bookkeeping.

Ship BODY.PEEK[] on its own and nothing sets \Seen any more, so UNSEEN stops
meaning "not yet processed" and starts meaning "not read by a human." The poller now
refetches a permanently growing backlog every 15 seconds, forever.

Fixing the side effect breaks the thing that was depending on the side effect.

The replacement is an explicit UID high-water mark — track the highest UID processed,
and search from there:

self._max_uid = 0                      # highest UID processed
...
typ, data = imap.uid("search", None, f"UID {self._max_uid + 1}:*")
Enter fullscreen mode Exit fullscreen mode

Two things bit me here:

UID n:* always returns at least one result. Even when nothing newer exists, IMAP
returns the highest UID in the mailbox rather than an empty set. So the search does
not filter — your own comparison does:

if uid_n <= self._max_uid:
    continue          # this line is the filter, not the search
Enter fullscreen mode Exit fullscreen mode

Seed the mark at startup, or a restart re-delivers everything. The adapter kept a
_seen_uids set, but it was capped at 2,000 entries and trimmed, so it could not
serve as the marker. The high-water mark has to be initialised from the existing
mailbox on boot.

Verify by effect, not by reading the diff

I did not declare this fixed because the code looked right. The check was:

  1. select(readonly=True)SEARCH cannot alter flags, so the watcher cannot contaminate what it measures
  2. snapshot search ALL and search UNSEEN
  3. poll until the message count rises
  4. assert the new UID is still unseen

A new message arrived and stayed unread. That is the only evidence that means
anything — the whole bug was a side effect nobody intended, and you cannot prove the
absence of a side effect by re-reading the code that caused it.

Takeaways

  • RFC822 sets \Seen. BODY.PEEK[] doesn't. If anything you write touches a mailbox you care about, check which one you're using right now.
  • Filter before you fetch where you can — anything after a fetch is too late to prevent side effects.
  • Removing a side effect breaks whatever silently depended on it. Ask what else was reading that state.
  • Prove a fix by effect. A diff that looks right is not evidence.

The wider version: my system had a component that worked correctly (the filter) and
one that had a side effect nobody thought about (the fetch), and I spent the first
stretch of debugging on the component that was fine — because that was the one the
symptom named.


More of this sort of thing — the homelab failures where the first diagnosis was wrong
— on GitHub at casareanderson.

Top comments (0)