In our last article we talked about various Exim utilities. Most of the utilities are used to inspect the mail queue or individual emails. In this article we will look at Exim’s log files and the exigrep
utility.
exigrep
is particularly useful to get information about email deliveries. We will therefore also look at various types of errors you might see in the logs.
There are three Exim log files:
By default the logs are rotated every week. The current (not-yet-rotated) log is a plain text file. Older log files are zipped, so you will need to uncompress them using gunzip
before you can work with them.
Exim comes with its own version of grep
: exigrep
. The main advantage of exigrep
is that it returns complete entries rather than single lines. This is very useful because entries in the exim_mainlog usually contain multiple lines. So, whether you search for an Exim ID, email address, email subject or whatever else, exigrep
always includes all the information about how matching emails were processed.
exigrep
also separates entries with whitespace, which makes it much easier to read the log. And, it uses a pager, so that you get to see one page at the time. The pager works exactly like less
. You can search using /
and ?
, use gg
and G
to jump to the top or bottom of the output, and so forth.
Each entry contains a lot of information, and the entries are terse. Let’s first look at an example of an email that was delivered correctly. We have slightly simplified the log entry for readability:
# exigrep paypal.co.uk /var/log/exim_mainlog 2020-02-09 10:31:43 1j0jsN-0002hA-Li <= service@paypal.co.uk T="Notification of Payment Received" for sales@example.net 2020-02-09 10:31:43 1j0jsN-0002hA-Li => salesR=virtual_user T=dovecot_virtual_delivery 2020-02-09 10:31:43 1j0jsN-0002hA-Li Completed
Let’s break that down…
One thing to note is that the exim_mainlog contains both incoming and outgoing emails. In the above example we know it is an incoming email because of the <=
status indicator. Outgoing emails use the indicator =>
instead. In addition, there are two other status indicators you might come across:
==
the delivery has been deferred because of a temporary problem**
the delivery has failedLet's return to our example email. The second line shows that Exim delivered the email to sales@example.net. The router (R=
) used was virtual_user and the transport (T=
) was dovecot_virtual_delivery. What this means is that the email was delivered to a user on the server.
If an email is instead dispatched to a user that doesn't exist on the server Exim will look up where the email should be delivered to. Here is an example of such an email:
2020-02-09 03:43:36 1j0dVQ-0002eQ-CZ <= example@strawberry.active-ns.com U=example T="Please moderate: \"Hello World!"" for support@catalyst2.com 2020-02-09 03:43:36 1j0dVQ-0002eQ-CZ Sender identification U=example D=example.net S=wordpress@example.net 2020-02-09 03:43:36 1j0dVQ-0002eQ-CZ SMTP connection outbound 1581219816 1j0dVQ-0002eQ-CZ example.net support@catalyst2.com 2020-02-09 03:43:38 1j0dVQ-0002eQ-CZ => support@catalyst2.com R=lookuphost T=remote_smtp H=cluster3.eu.messagelabs.com [85.158.142.102] Message accepted for delivery" 2020-02-09 03:43:38 1j0dVQ-0002eQ-CZ Completed
This email was sent from the example.net website: it is a comment moderation email from the website's WordPress install. The email has one recipient: support@catalyst2.com. Because catalyst2.com doesn't live on the server Exim looked up where catalyst2.com does live (R=lookuphost
) and sent the email to the remote SMTP server. We can also see that the remote server accepted the email for delivery.
If these two example made sense then you can already debug many common issues. Let's run through some examples.
cPanel servers let users select whether incoming emails should be routed locally or remotely. This can cause delivery issues. For instance, let's imagine that the domain example.net uses G Suite for email:
# dig example.net MX +short | sort -h 1 aspmx.l.google.com. 5 alt1.aspmx.l.google.com. 5 alt2.aspmx.l.google.com. 10 alt3.aspmx.l.google.com. 10 alt4.aspmx.l.google.com.
Because mail for example.net is handled by an external server the mail exchanger should be set to "remote". If it is set to "local" the delivery will fail. Exim will try to deliver the email locally but the recipient doesn't exist on the server:
2020-02-11 17:09:46 1j1Z2g-00Faoy-Uh <= example@strawberry.active-ns.com U=example P=local T="[Examples Galore] Please moderate: \"Hello world!\"" for admin@example.net 2020-02-11 17:09:47 1j1Z2g-00Faoy-Uh ** admin@example.net R=virtual_aliases: No such person at this address. 2020-02-11 17:09:47 1j1Z2g-00Faoy-Uh Completed
Undeliverable emails may also be frozen in the mail queue:
# exigrep 1j1Z0U-00Fab5-62 /var/log/exim_mainlog 2020-02-11 17:07:30 1j1Z0U-00Fab5-62 <= <> H=st2.mx.email-filter.net [84.18.194.45] T="Spam Quarantine Report" for me@example.net 2020-02-11 17:07:30 1j1Z0U-00Fab5-62 ** me@example.net R=virtual_aliases: No Such User Here" 2020-02-11 17:07:30 1j1Z0U-00Fab5-62 Frozen (delivery error message) 2020-02-11 17:24:05 1j1Z0U-00Fab5-62 Message is frozen
Exim tries to deliver emails that are stuck in the queue at set intervals. You can check Exim's "retry configuration" for a domain using the command exim -brt
:
# exim -brt example.net Retry rule: * * F,2h,15m; G,16h,1h,1.5; F,4d,8h;
The retry configuration is rather complicated:
F,2h,15m
indicates that Exim will try to deliver the email every 15 minutes for two hours.G,16h,1h,1.5
means that for the next 16 hours Exim will try to deliver the email at increasing intervals. It will first try to deliver the email after one hour. After that, it will try again after 1 hour * 1.5, and so forth.F,4d,8h
is another fixed retry schedule. Exim will try to deliver the email every eight hours for four days.Emails that haven't been delivered by the end of that period are purged.
In the previous example we looked at an email that couldn't be delivered because the mailbox didn't exist. There are many other reasons why an email can't be delivered. Here is an incoming email that can't be delivered because the mailbox is full:
2020-02-09 11:00:56 1j0kKd-002txk-OI <= service@paypal.co.uk T="Notification of Payment Received" for sales@example.net 2020-02-09 11:00:56 1j0kKd-002txk-OI == sales@example.net R=virtual_user T=dovecot_virtual_delivery defer (-44): LMTP error after RCPT TO:<sales@example.net>: 452 4.2.2Mailbox is full / Blocks limit exceeded / Inode limit exceeded 2020-02-09 11:46:41 1j0kKd-002txk-OI == sales@example.net R=virtual_user T=dovecot_virtual_delivery defer (-52): Retry time not yet reached 2020-02-09 12:43:34 1j0kKd-002txk-OI == sales@example.net R=virtual_user T=dovecot_virtual_delivery defer (-52): Retry time not yet reached ...
Remote servers can of course also reject emails coming from your server. Such emails usually have a bounce message that explains why the email was rejected. Common issues are that the recipient's mailbox doesn't exist or is full, that the email has been identified as spam or that sending domain's SPF record doesn't allow the IP address to send emails for the domain.
On a busy server a quick search for something like exigrep "SMTP error from remote mail server" /var/log/exim_mainlog
is likely to yield plenty of bounce messages. Here are some examples:
Our system has detected an unusual rate of unsolicited mail originating from your IP address. To protect our users from spam, mail sent from your IP address has been temporarily rate limited. Please visit https://support.google.com/mail/?p=UnsolicitedRateLimitError to review our Bulk Email Senders Guidelines.
552-5.7.0 This message was blocked because its content presents a potential security issue. Please visit https://support.google.com/mail/?p=BlockedMessage to review our message content and attachment content guidelines.
450-4.2.1 The user you are trying to contact is receiving mail at a rate that prevents additional messages from being delivered. Please resend your message at a later time. If the user is able to receive mail at that time, your message will be delivered. For more information, please visit https://support.google.com/mail/?p=ReceivingRate
554 Message rejected on 2020/02/10 21:45:26 GMT, policy (3.2.2.1) - Your message looks like SPAM or has been reported as SPAM
552 5.2.2 Mailbox size limit exceeded
550 Message was blocked by server (failed SPF)
As you can see, most bounce messages are very helpful. They clearly explain what the issue is.
cPanel users can create filter rules for emails. This is, for better or worse, often used to combat spam. Unfortunately, it is very easy to create a rule that accidentally matches a perfectly legitimate email (see the Scunthorpe problem).
Here is an example of an email that was sent to /dev/null because of an email filter:
2020-02-09 06:15:34 1j0fsU-002MCC-Uo <= example@strawberry.active-ns.com T="Currency Compare \"payday loans for bad credit\"" for sales@example.net 2020-02-09 06:15:35 1j0fsU-002MCC-Uo => /dev/nullR=central_filter T=**bypassed** 2020-02-09 06:15:35 1j0fsU-002MCC-Uo Completed
The router central_filter indicates that the email was sent to /dev/null by a filter rule created by the user. In addition to user filters there are also server-wide filters. Such filters use the router system_filter instead.
We can double-check if the email was indeed purged because of a user filter. Filter rules for an individual mailbox are stored in /home/$user/etc/$domain/$mailbox/, while rules that apply to all mailboxes on an account are kept in /etc/vfilters/example.net. Here is an example of a filter rule in the latter file:
# grep -iA 3 "currency" /etc/vfilters/example.net #Spam - Currency Compare if $header_subject: contains "Currency Compare" then save "/dev/null" 660 endif