Exim log files and exigrep

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.

Exim logs

There are three Exim log files:

• /var/log/exim_mainlog is Exim’s primary log. Every email that is processed by Exim is logged here.
• /var/log/exim_rejectlog contains information about emails that were rejected because of a policy.
• /var/log/exim_paniclog logs errors related to Exim itself.

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.

exigrep

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.

The anatomy of an Exim entry

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 => sales  R=virtual_user T=dovecot_virtual_delivery
2020-02-09 10:31:43 1j0jsN-0002hA-Li Completed

Let’s break that down…

• The first line shows a timestamp followed by an Exim ID (here 1j0jsN-0002hA-Li).
• <= service@paypal.co.uk shows that this was an incoming email from service@paypal.co.uk.
• The subject (“topic”) of the email was “Notification of Payment Received” and the email’s recipient is sales@example.net.
• The second line shows that the email was delivered to sales@example.net.
• And finally, the last line simply shows that Exim finished processing the email.

Status indicators

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 failed

Router and transport

Let'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.

Incorrect email routing

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

Retry configuration

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.

Refused incoming emails

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.2  Mailbox 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
...

Refused outgoing emails

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.

User filters

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/null  R=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