February | 2016 | Roland's Linux Blog

With smtpd_proxy_filter you can inspect email messages before postfix accepts them. There are many information on the internet that explain the advantages and disadvantages about this setting.

Here is how the log messages should look like in case you have problems with the configuration. I am using postfix with amavis configured as a proxy filter. So actually amavis decides whether to accept email or not. The following amavis configuration items have to be set:

$final_spam_destiny = D_PASS;
$sa_kill_level_deflt = 6.9;

In this example we accept spam even if it is tagged by spamassassin as above a threshold of 6.9. If you set D_REJECT instead of D_PASS, the email will be rejected with an error code by postfix. We will see later how this looks like in the log files. First lets take a look at the log files if amavis accepts spam (D_PASS).

Feb 28 12:24:16 mailserver postfix/smtpd[14432]: connect from unknown[1.2.3.4]

Feb 28 12:24:16 mailserver postfix/smtpd[14432]: NOQUEUE: client=unknown[1.2.3.4]

First the client MTA connects to our mailserver. Notice the identical process ids and the remote ip addresses which will play a vital part in the subsequent identification of log messages.

Feb 28 12:24:16 mailserver amavis[13915]: (13915-15) ESMTP :10024 /var/lib/amavis/tmp/amavis-20160228T073711-13915-1YTlNWlj: <test@remote.example> -> <test@local.example> Received: from mailserver.local.example ([127.0.0.1]) by localhost (mailserver.local.example [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <test@local.example>; Sun, 28 Feb 2016 12:24:16 +0100 (CET)

The mail is immediately transferred to the proxy application, in this case amavis. The client connection to our smtpd service is still open. So the smtpd service has 2 connections open: the one to the MTA client, and the one to amavis. This log line is a bit tricky to find in the maillog file because there is no direct reference to the previous smtpd log entries. Nevertheless we see that the smtpd service uses ESMTP to communicate with amavis, and we see sender and recipient information. We also see that amavis is accepting the ESMTP mesage from localhost (127.0.0.1) because amavis and smtpd are running on the same host. Amavis is accepting the mail message on port 10024.

Feb 28 12:24:17 mailserver amavis[13915]: (13915-15) Checking: vJWxdMp5DNHC [1.2.3.4] <test@remote.example> -> <test@local.example>

Feb 28 12:24:17 mailserver amavis[13915]: (13915-15) p001 1 Content-Type: text/html, size: 27487 B, name:

In these 2 lines amavis is logging more information about the email. Notice that the id 13915-15 is identical to the previous amavis log line.

The id vJWxdMp5DNHC is an internal mail_id generated by amavis that is not shared with postfix. Also it will not be used in all of amavis log entries.You will find this mail_id in the “Received”-header that amavis adds to the email. Here is a description taken from the amavisd-new perl script:

# generate a reasonably unique (long-term) id based on collected entropy.
# The result is a pair of a (mostly public) mail_id, and a secret id,
# where mail_id == b64(md5(secret_bin)). The secret id could be used to
# authorize releasing quarantined mail. Both the mail_id and secret id are
# strings of characters [A-Za-z0-9-_], with an additional restriction
# for mail_id which must begin and end with an alphanumeric character.
# The number of bits in a mail_id is configurable through $mail_id_size_bits
# and defaults to 72, yielding a 12-character base64url-encoded string.
# The number of bits must be an integral multiple of 24, so that no base64
# trailing padding characters '=' are needed (RFC 4648).

By default amavis also adds this id to the email headers if the email is not being rejected:

Received: from mail.local.example ([127.0.0.1])
 by localhost (mailserver [127.0.0.1]) (amavisd-new, port 10024)
 with ESMTP id vJWxdMp5DNHC for <test@local.example>;
 Sun, 28 Feb 2016 12:24:18 +0100 (CET)

Back to the postfix / amavis logfile:

Feb 28 12:24:18 mailserver amavis[13915]: (13915-15) spam-tag, <test@remote.example> -> <test@local.example>, Yes, score=15.524 tagged_above=2 required=5 tests=[BAYES_99=3.5, CK_HELO_DYNAMIC_SPLIT_IP=0.001, HK_NAME_DRUGS=0.552, HTML_FONT_LOW_CONTRAST=0.001, HTML_MESSAGE=0.001, MIME_HTML_ONLY=0.723, MISSING_MID=0.497, RCVD_IN_BRBL_LASTEXT=1.449, RDNS_NONE=0.793, TVD_RCVD_IP=0.001, URIBL_BLACK=1.725, URIBL_DBL_SPAM=1.7, URIBL_JP_SURBL=1.25, URIBL_SBL=1.623, URIBL_SBL_A=0.1, URIBL_WS_SURBL=1.608] autolearn=no autolearn_force=no

Again amavis logs the id 13915-15. It tags the email as spam using spamassassin.

Feb 28 12:24:18 mailserver postfix/smtpd[14438]: connect from localhost[127.0.0.1]

Feb 28 12:24:18 mailserver postfix/smtpd[14438]: 5419B66: client=localhost[127.0.0.1], orig_client=unknown[1.2.3.4]

Amavis transfers the message back to a different smtpd process on the local mailserver (process id 14438). Again these lines are hard to find because as a reference we only get the ip address of the original MTA client (1.2.3.4). But for any further references, smtpd finally assigns the id 5419B66 to the email. This id can be used to find the email in the log files or in the postfix mail queue.

Feb 28 12:24:18 mailserver postfix/cleanup[14439]: 5419B66: message-id=<5de199bf16c44d40@remote.example>

Feb 28 12:24:18 mailserver postfix/qmgr[1491]: 5419B66: from=<test@remote.example>, size=31190, nrcpt=1 (queue active)

Searching for the id, we find that the email has been transferred from smtpd to the cleanup service and from there to the queue manager. It is now in the active queue. Notice that the message size changed to 31190 because of the additional spam tagging.

The cleanup process logs the message id from the email header (if the “Message-ID:”-header exists). This is not the postfix message id, nor the amavis internal mail_id. It is simply taken from the email headers and may be missing. In this case cleanup will write “message-id=<>” or add a new “Message-ID:”-header by itself depending on the postfix setting “always_add_missing_headers”.

If it exists, it is probably generated and added by the MUA (e.g. Thunderbird).

Feb 28 12:24:18 mailserver amavis[13915]: (13915-15) vJWxdMp5DNHC FWD from <test@remote.example> -> <test@local.example>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 5419B66

Feb 28 12:24:18 mailserver postfix/smtpd[14438]: disconnect from localhost[127.0.0.1]

This is the handshake between amavis (the amavis id from previous log entries: 13915-15) and the second smtpd process (process id 14438). smtpd sends the message id back to amavis. It has successfully handed the message over to the cleanup service so it closes the amavis connection on port 10025.

Now we can associate the amavis id 13915-15, the amavis mail_id vJWxdMp5DNHC and the postfix message id 5419B66 for any previous or later log entries.

Feb 28 12:24:18 mailserver amavis[13915]: (13915-15) Passed SPAM {RelayedTaggedInbound}, [1.2.3.4]:61081 [127.0.0.1] <test@remote.example> -> <test@local.example>, Message-Id=<5de199bf16c44d40@remote.example>, mail_id: vJWxdMp5DNHC, Hits: 15.524, size: 30251, queued_as: 5419B66, 1944 ms

Feb 28 12:24:18 mailserver amavis[13915]: (13915-15) TIMING-SA total 1180 ms - parse: 3.8 (0.3%), extract_message_metadata: 81 (6.9%), get_uri_detail_list: 2.2 (0.2%), tests_pri_-1000: 4.2 (0.4%), tests_pri_-950: 1.06 (0.1%), tests_pri_-900: 0.96 (0.1%), tests_pri_-400: 35 (3.0%), check_bayes: 34 (2.9%), b_tokenize: 9 (0.7%), b_tok_get_all: 14 (1.2%), b_comp_prob: 7 (0.6%), b_tok_touch_all: 0.40 (0.0%), b_finish: 0.67 (0.1%), tests_pri_0: 364 (30.8%), check_dkim_signature: 1.17 (0.1%), check_dkim_adsp: 176 (14.9%), check_spf: 19 (1.6%), poll_dns_idle: 622 (52.7%), check_pyzor: 0.17 (0.0%), tests_pri_500: 674 (57.1%), get_report: 1.80 (0.2%)

After amavis has transferred the message to smtpd, there is now enough time to do some more logging. We can see that the message was not rejected but passed, and it was tagged as a spam message that was delivered from the outside to one of our local recipients (RelayedTaggedInbound). It can do so because it knows the ip address from the original MTA client (orig_to) which was transferred by the first smtpd process, and this is not an ip address from the amavis @mynetworks configuration entry.

Furthermore amavis knows about all local domains by the @local_domains_acl parameter.

@local_domains_acl = ( ".local.example" );

The ip address of the client MTA was sent from the first smtpd process to amavis in the XFORWARD header of the ESMTP session. This header looks like this:

 XFORWARD NAME=mx.remote.example ADDR=1.2.3.4 PORT=32010 HELO=mx.remote.example IDENT=[UNAVAILABLE] PROTO=ESMTP SOURCE=REMOTE..

Combining both information (sender ip from outside and recipient domain name from the internal network) amavis logs the email as inbound.

Feb 28 12:24:18 mailserver postfix/smtpd[14432]: proxy-accept: END-OF-MESSAGE: 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 5419B66; from=<test@remote.example> to=<test@local.example> proto=ESMTP helo=<mx.remote.example>

Back to the original smtpd process (process id 14432). Having received the acknowledgement from the amavis process, it can safely inform the client that the message has been successfully accepted. At this point the local mailserver is responsible for the email. For further investigation purposes, the client MTA receives the message id from our mailserver and a positive return code (250). For the client MTA the message has been successfully delivered. Notice that this only happened after amavis checked the email for spam or viruses.

Feb 28 12:24:18 mailserver postfix/qmgr[1491]: 5419B66: removed

Feb 28 12:24:18 mailserver postfix/smtpd[14432]: disconnect from unknown[1.2.3.4]

You might see some further log entries about message delivery from the local or virtual postfix services which I do not show here. But if the local or virtual services succeed, the queue manager will remove the message from its queue.

And finally the client MTA closes his connection to our first postfix smtpd process (process id 14432). Again, the only way to identify this log entry are the smtpd process id and the client ip address.

In the whole process there was no smtp client process involved! This is a short diagram of the message flow:

client MTA  -> smtpd-1 (port 25) -> amavis (port 10024) -> smtpd-2 (port 10025) -> cleanup -> qmgr -> local/virtual

The final email will have 3 headers added to it, and an optional “Message-Id:”-header, with a total of up to 3 different mail ids:

The first “Received:”-header (the one at the bottom) added by the first smtpd process without any mail id
The second “Received:”-header added by amavis with its own internal id
The third “Received:”-header added by the second smptd process with the local postfix mail id
The optional “Message-ID:”-header added by the remote MUA or our local cleanup process

Received: from localhost (localhost [127.0.0.1])
	by mail.local.example (Postfix) with ESMTP id 5419B66
	for <test@local.example>; Sun, 28 Feb 2016 12:24:18 +0100 (CET)
Received: from mail.local.example ([127.0.0.1])
	by localhost (mailserver [127.0.0.1]) (amavisd-new, port 10024)
	with ESMTP id vJWxdMp5DNHC for <test@local.example>;
	Sun, 28 Feb 2016 12:24:18 +0100 (CET)
Received: from mx.remote.example (mx.remote.example [1.2.3.4])
	(using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits))
	(No client certificate requested)
	by mail.local.example (Postfix) with ESMTPS
	for <test@local.example>; Sun, 28 Feb 2016 12:24:18 +0100 (CET)
Message-ID: <5de199bf16c44d40@remote.example>

Wow, this was a lot of work for postfix and amavis, but it was worth it. We have another spam message in our inbox.

—

So lets see what happens if we change the amavis configuration to reject spam.

$final_spam_destiny = D_REJECT;
$sa_kill_level_deflt = 6.9;

Here we tell amavis to reject all email messages which are tagged by spamassassin above a threshold of 6.9. Having amavis working as a proxy filter, postfix does not even accept the email from the sending MTA. The advantage is that we are saving disk space by not delivering spam email to the mail inboxes. And we are sending a clear signal to spam senders: Your spam email did not work, don’t even try another one.

On the other hand this setting is dangerous, because there might be false positives which are tagged as spam by mistake and therefore will not be delivered to the recipient inbox. Also if you are receiving emails at a high rate, postfix might not be able to wait for amavis before it accepts or rejects an SMTP connection. Amavis might just be too time consuming. In this case you have to configure amavis as a content filter. Email then gets inspected by amavis after it has been accepted by postfix with a 2xx status code.

Ok, now we reject spam above a threshold of 6.9. The log entries are the same as the ones above including the “Checking …” and “Content-Type …” entries. Here is the first different log entry:

Feb 28 13:18:10 mailserver amavis[13915]: (13915-15) Blocked SPAM {RejectedInbound}, [1.2.3.4]:49282 [127.0.0.1] <test@remote.example> -> <test@local.example>, mail_id: vJWxdMp5DNHC, Hits: 997.65, size: 2170, 705 ms

Amavis rejects the email and tags it as spam. As it does not forward the message to another smtpd process, amavis has no chance to add spam headers to the email. Instead it notifies the first smtpd process within the still open ESMTP session by the following reply:

554 5.7.0 Reject, id=13915-15 - spam..

Notice that amavis does not forward the email to the second smtpd process. Therefore we do not see the “queued as” entries and there is no second smtpd server entry.

Feb 28 13:18:10 mailserver postfix/smtpd[14438]: proxy-reject: END-OF-MESSAGE: 554 5.7.0 Reject, id=13915-15 - spam; from=<test@remote.example> to=<test@local.example> proto=ESMTP helo=<mx.remote.example>

Feb 28 13:18:10 mailserver postfix/smtpd[14438]: disconnect from unknown [1.2.3.4]

Instead the first smptd process rejects the email with a return code of 554, which means that there is a permanent failure and the sending MTA should not try to deliver the same message again (https://www.iana.org/assignments/smtp-enhanced-status-codes/smtp-enhanced-status-codes.xhtml). Postfix does not generate the reply to the sending MTA itself, but simply takes the response from the amavis ESMTP session (see above) and includes it in its own SMTP session.

Also notice that because our local postfix MTA did not accept the message, there is no postfix message id for the email. Instead postfix includes the amavis id 13915-15 in the SMTP reply. Meaning that the sending MTA knows the process id 13915 of our amavis process. But at least the sender has some sort of hint in case he wants to complain and we need to investigate. If you don’t want to disclose your amavis process id, you can customise this response with the amavis configuration setting %smtp_reason_by_ccat (explained here:
https://sourceforge.net/p/amavis/mailman/amavis-user/thread/F896BF2D9FA09A81FBAAD4EA@bort.lsit.ucsb.edu/ ).

Finally the remote MTA disconnects and hopefully does not send any further spam messages.

Roland's Linux Blog

Computer related stuff including Linux

Monthly Archives: February 2016

KRDC RDP connection to Windows Server: blank screen

Logfile analysis of the postfix proxy filter

Postfix help on the command line