search

codespeaknet / sysadmin

system administration for codespeak.net services (autocrypt.org, lists.codespeak.net, ....)
MIT License
1 stars 0 forks source link

reduce delay with postfix on accepting incoming mail #9

Open hpk42 opened 5 years ago

hpk42 commented 5 years ago

Currently the "deltabot" service runs. For some reason postfix has a 5-6 seconds delay before accepting incoming mail. Here is a log excerpt for when a mail to deltabot at codespeak.net arrives:

Oct 17 14:57:31 lists postfix/smtpd[13443]: connect from mail.merlinux.eu[2a01:4f8:c17:b03::2]
Oct 17 14:57:31 lists postfix/smtpd[13443]: Anonymous TLS connection established from mail.merlinux.eu[2a01:4f8:c17:b03::2]: TLSv1.2 with cipher ADH-AES256-GCM-SHA384 (256/256 bits)
Oct 17 14:57:31 lists postfix/smtpd[13443]: E67F961AF0: client=mail.merlinux.eu[2a01:4f8:c17:b03::2]
Oct 17 14:57:31 lists postfix/cleanup[13445]: E67F961AF0: message-id=<20181017125728.GA7023@beto>
Oct 17 14:57:32 lists opendkim[2287]: E67F961AF0: s=default d=merlinux.eu SSL
Oct 17 14:57:39 lists postfix/qmgr[2667]: E67F961AF0: from=<holger@merlinux.eu>, size=3432, nrcpt=1 (queue active)
Oct 17 14:57:39 lists postfix/smtpd[13443]: disconnect from mail.merlinux.eu[2a01:4f8:c17:b03::2] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Oct 17 14:57:39 lists postfix/local[13446]: E67F961AF0: to=<deltabot@codespeak.net>, relay=local, delay=7.2, delays=7.1/0.01/0/0.01, dsn=2.0.0, status=sent (delivered to mailbox)
Oct 17 14:57:39 lists postfix/qmgr[2667]: E67F961AF0: removed

Note that qmgr delays for 7 seconds after receiving the mail.

on another mail server i get this:

Oct 17 15:04:26 hq5 postfix/smtpd[11794]: connect from mail.merlinux.eu[78.46.202.179]
Oct 17 15:04:26 hq5 postfix/smtpd[11794]: BC50D401CD: client=mail.merlinux.eu[78.46.202.179]
Oct 17 15:04:26 hq5 postfix/cleanup[11799]: BC50D401CD: message-id=<20181017130424.GC7023@beto>
Oct 17 15:04:26 hq5 opendkim[1504]: BC50D401CD: s=default d=merlinux.eu SSL
Oct 17 15:04:26 hq5 postfix/qmgr[11785]: BC50D401CD: from=<holger@merlinux.eu>, size=3421, nrcpt=1 (queue active)
Oct 17 15:04:26 hq5 postfix/smtpd[11794]: disconnect from mail.merlinux.eu[78.46.202.179] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Oct 17 15:04:27 hq5 postfix/local[11800]: BC50D401CD: to=<hpk2@hq5.merlinux.eu>, relay=local, delay=0.27, delays=0.23/0.01/0/0.04, dsn=2.0.0, status=sent (delivered to mailbox)

the last line summarizes the delays it seems -- the postfix/dovecot installations should be quite similar but something on codespeak seems to introduce this delay ...

hpk42 commented 5 years ago

maybe this is a per-connecting client thing? would be happy if someone else tries to send a mail to deltabot@codespeak.net (or bot@autocrypt.org) to gather more statistics and maybe get an idea what is holding the message up.

gfa commented 5 years ago

rspamd calls to spamhaus were timing out

Oct 17 17:22:05 lists.codespeak.net postfix/smtpd[31770]: 9CDE962C71: client=mail.zumbi.com.ar[172.104.98.54]
Oct 17 17:22:05 lists.codespeak.net postfix/cleanup[1266]: 9CDE962C71: message-id=<DB1C7F5F-A809-4718-A63F-E0E56D3A350A@zumbi.com.ar>
Oct 17 17:22:06 lists.codespeak.net opendkim[2287]: 9CDE962C71: s=mail d=zumbi.com.ar SSL
Oct 17 17:22:11 lists.codespeak.net rspamd[1141]: <423b79>; lua; rbl.lua:162: error looking up 54.98.104.172.zen.spamhaus.org: query timed out
Oct 17 17:22:11 lists.codespeak.net rspamd[1141]: <423b79>; lua; rbl.lua:162: error looking up 2.d.7.f.5.1.b.d.1.3.d.a.c.b.9.7.7.0.4.c.2.4.f.1.4.0.8.c.4.0.4.2.zen.spamhaus.org: query timed out
Oct 17 17:22:11 lists.codespeak.net postfix/qmgr[16461]: 9CDE962C71: from=<gfa@zumbi.com.ar>, size=4404, nrcpt=1 (queue active)
Oct 17 17:22:11 lists.codespeak.net postfix/smtpd[31770]: disconnect from mail.zumbi.com.ar[172.104.98.54] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Oct 17 17:22:11 lists.codespeak.net postfix/smtpd[31770]: connect from localhost.localdomain[127.0.0.1]
Oct 17 17:22:11 lists.codespeak.net postfix/smtpd[31770]: C0CF064E52: client=localhost.localdomain[127.0.0.1]
Oct 17 17:22:11 lists.codespeak.net postfix/cleanup[1266]: C0CF064E52: message-id=<153978973177.1612.2606736994769106812@lists.codespeak.net>
Oct 17 17:22:11 lists.codespeak.net postfix/qmgr[16461]: C0CF064E52: from=<bot@autocrypt.org>, size=4341, nrcpt=1 (queue active)

I've disabled spamhaus in rspamd and add a redis instance for rspamd to use, delivery time went down to 2-5 seconds.

I'll do more spamhaus tests in a few days

gfa commented 5 years ago

spamhaus is still blocking us, this work from every other machine i have access to

dig +short TXT 201.24.73.219.zen.spamhaus.org

Let's see in a few days

gfa commented 5 years ago

I asked on mailop mailling list about this. Unfortunately the archives are not public so I won't post the replies, but the bottom line is that spamhaus blocks hetzner IP ranges

Spamhaus offers to hetzner customers the same service as the public mirror subscribing here https://www.spamhaustech.com/dqs/

I'll check the terms and come back

hpk42 commented 5 years ago

On Fri, Oct 19, 2018 at 07:03 +0000, gustavo panizzo wrote:

I asked on mailop mailling list about this. Unfortunately the archives are not public so I won't post the replies, but the bottom line is that spamhaus blocks hetzner IP ranges

ups!

Spamhaus offers to hetzner customers the same service as the public mirror subscribing here https://www.spamhaustech.com/dqs/

I'll check the terms and come back

thanks! i saw that you also configured the "replies" module ... is that meant to allow bypassing checks if a message is a reply to a message that rspamd saw already? That would make a lot of sense and especially for deltachat cut out spam-checks most of the time. (FTR currently deltachat does not properly set the "in-reply-to", but it's planned https://github.com/deltachat/deltachat-core/issues/72 )

FWIW my other mail server is also hosted at hetzner and seems to be much faster but not sure if its rspamd actually contacts spamhaus (i think it does but need to do logging etc.).

gfa commented 5 years ago

Hi

the replies module stores the message-id in redis and uses it to skip checks on incoming messages

Oct 22 03:30:41 lists.codespeak.net rspamd[7195]: <b8806b>; replies; replies.lua:104: sender is authenticated
Oct 22 03:30:41 lists.codespeak.net rspamd[7195]: <b8806b>; replies; replies.lua:117: storing message-id for replies check

It still takes around 5s to deliver an email according to deltabot (and mail.log)

hpk42 commented 5 years ago

On Sun, Oct 21, 2018 at 18:59 -0700, gustavo panizzo wrote:

Hi

the replies module stores the message-id in redis and uses it to skip checks on incoming messages

Oct 22 03:30:41 lists.codespeak.net rspamd[7195]: <b8806b>; replies; replies.lua:104: sender is authenticated
Oct 22 03:30:41 lists.codespeak.net rspamd[7195]: <b8806b>; replies; replies.lua:117: storing message-id for replies check

It still takes around 5s to deliver an email according to deltabot (and mail.log)

What is the easiest way to test the pipeline with rspamd disabled?

gfa commented 5 years ago

On October 22, 2018 4:44:48 PM UTC, holger krekel notifications@github.com wrote:

On Sun, Oct 21, 2018 at 18:59 -0700, gustavo panizzo wrote:

Hi

the replies module stores the message-id in redis and uses it to skip checks on incoming messages

Oct 22 03:30:41 lists.codespeak.net rspamd[7195]: <b8806b>; replies;
replies.lua:104: sender is authenticated
Oct 22 03:30:41 lists.codespeak.net rspamd[7195]: <b8806b>; replies;
replies.lua:117: storing message-id for replies check

It still takes around 5s to deliver an email according to deltabot (and mail.log)

What is the easiest way to test the pipeline with rspamd disabled?

For a single server/domain is pretty easy, iptables rules can be used to redirect the traffic from specific server(s) to a second instance of Postfix's smtpd without milter (rspamd) -- Sent from my Android device with K-9 Mail. Please excuse my brevity.

hpk42 commented 5 years ago

On Mon, Oct 22, 2018 at 18:18 -0700, gustavo panizzo wrote:

On October 22, 2018 4:44:48 PM UTC, holger krekel notifications@github.com wrote:

On Sun, Oct 21, 2018 at 18:59 -0700, gustavo panizzo wrote:

Hi

the replies module stores the message-id in redis and uses it to skip checks on incoming messages

Oct 22 03:30:41 lists.codespeak.net rspamd[7195]: <b8806b>; replies;
replies.lua:104: sender is authenticated
Oct 22 03:30:41 lists.codespeak.net rspamd[7195]: <b8806b>; replies;
replies.lua:117: storing message-id for replies check

It still takes around 5s to deliver an email according to deltabot (and mail.log)

What is the easiest way to test the pipeline with rspamd disabled?

For a single server/domain is pretty easy, iptables rules can be used to redirect the traffic from specific server(s) to a second instance of Postfix's smtpd without milter (rspamd)

not possible to simply not send the mail through rspamd by modifying the config of the one postfix we have running? Not having rspamd runnign during 5-minutes and then switching it back on seems easier than trying to setup a second instance and fiddling with iptables ...