Mail with an attachment took eight minutes to send
The problem
Staff sending a message with an attachment watched their mail client sit and then time out, while the same message without an attachment left instantly. The relay was blamed, and the relay was innocent.
The client’s mail client reported a timeout connecting to the outgoing server, which points the finger squarely at the network or the relay. Both were fine. The message never got far enough to reach either.
The evidence that settled it
Every delivery line in the mail log carries a breakdown of where the time went, split across the stages a message passes through. Reading that field showed roughly five hundred seconds sitting in the stage before the message was even queued — the point where content scanning happens, entirely on this machine.
That single number ended the argument. Nothing beyond the server could be responsible for time spent before the message was accepted.
Two causes, both local
- The spam filter had lost its cache. The shared store it uses had been moved to a Unix socket for security, and the filter was still configured to reach it over a network address. Every lookup failed and fell back to the slow path. Nothing errored loudly, because a cache miss is a legitimate state.
- The virus scanner had been paged out to swap. Roughly a gigabyte of it sat on disk rather than in memory, so scanning an attachment meant waiting for the scanner itself to be read back in. Reloading its signature database concurrently made it worse.
The fixes
- Point the filter at the socket and grant it the group membership needed to open it.
- Stop the scanner reloading its database concurrently, raise its stream and file size limits to match what the mail server actually accepts, and reduce the system’s willingness to swap.
- Raise the submission timeout so that a machine briefly under load stretches rather than drops the connection.
Why this is worth reading
Everyone involved was certain the problem was the relay, because that is what the error message named. The error message described where the client gave up waiting, not where the waiting happened. Those are different facts, and the log field that distinguishes them takes ten seconds to read once you know it exists.
The outcome
Two unrelated causes found in the local scanning chain, both fixed at the cause, with the send delay back to seconds.
