Last updated: 28 April 2021

Our last article talked about Exim utilities. The utilities we looked at are used to inspect the mail queue or individual emails. This article looks at Exim’s log files and the exigrep utility.

exigrep is mainly used 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 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 logs may be zipped, depending on the log rotation settings. So, you may need to unzip old logs before you can work with them.

exigrep

Most entries in /var/log/maillog are made up of multiple lines. The first line typically contains information about the email itself, such as the date, sender and recipient. Subsequent lines show information about how the email was delivered. When you inspect the log you therefore want complete entries rather than individual lines. The exigrep utility does just that. You can search for an Exim ID, email address or whatever else, and it will return all the relevant information.

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.

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

Let’s break that down…

  • All three lines have a timestamp followed by an Exim ID (here 1j0jsN-0002hA-Li).
  • <= service@paypal.co.uk shows this was an incoming email from service@paypal.co.uk.
  • The subject (“topic”) is “Notification of Payment Received” and the 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

The log file lists both incoming and outgoing emails. Incoming emails have the status indicator <=. So, <= service@paypal.co.uk means that Exim received an email from service@paypal.co.uk. Outgoing emails use the indicator => instead.

In addition, there are two other 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 the email was delivered 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. It is worth noting that emails for local users are delivered by Dovecot rather than Exim.

Remote deliveries are always managed by Exim. In that case Exim looks up where the email should be delivered to. Here is an example:

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 WordPress comment moderation email). 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). It next sent the email to the remote server. The log entry also shows that the remote server accepted the email for delivery.

If these two examples 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”. Email deliveries will fail if it is set to “local” instead. Exim would pass the email to Dovecot, which in turn wouldn’t be able to deliver the email locally.

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

The above email bounced. Emails may also be frozen in the mail queue. In that case Exim tries to deliver the email at a later time:

# 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

As said, Exim tries to redeliver emails that are stuck in the queue. 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 means that Exim tries to deliver the email every 15 minutes for two hours.
  • G,16h,1h,1.5 means that for the next 16 hours Exim tries to deliver the email at increasing intervals. It first tries to deliver the email after one hour. After that, it tries again after 1 hour * 1.5, and so forth.
  • F,4d,8h is another fixed retry schedule. Exim tries to deliver the email every eight hours for four days.

Emails that haven’t been delivered by the end of the 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 <sales@example.net> 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. 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.

Here is an example of an email that was removed 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 <sales@example.net> R=central_filter T=**bypassed**
2020-02-09 06:15:35 1j0fsU-002MCC-Uo Completed

The router central_filter indicates that the email matched a filter rule created by the cPanel user. As a result, the email was sent to /dev/null. This is a special file on Unix systems that simply discards anything sent to it. So, the email was purged.

In addition to user filters there are also server-wide filters. Such filters use the router system_filter instead.

You 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/$domain. 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