Mail delivery delayed 30+ secs

General Discussion
1

This is a Centos 7 VPS with Postfix, Dovecot, Procmail, etc. installed from scratch with Webmin/Virtualmin some months ago. All is up-to-date.

Mails are received by the mail server almost instantly. If the sender is local there is a delay of around 30 seconds to deliver and if the sender is external the delay is around 1 minute.

Today I made a couple of tests:

  1. Send mail from Gmail account to this server: u@gmail.com to me@mydomain.com (this belongs to ‘username’):
Jun 13 19:04:40 host postfix/smtpd[9921]: connect from mail-qt1-f170.google.com[209.85.160.170]
...
Jun 13 19:04:41 host postfix/smtpd[9921]: disconnect from mail-qt1-f170.google.com[209.85.160.170]
...
Jun 13 19:05:39 host spamd[4236]: spamd: setuid to username succeeded
Jun 13 19:05:40 host spamd[4236]: spamd: processing message [<ab158c70-7e5f-edcd-f741-e6e56298bd08@gmail.com>](mailto:ab158c70-7e5f-edcd-f741-e6e56298bd08@gmail.com) for username:1018
Jun 13 19:05:42 host spamd[4236]: spamd: clean message (-2.0/5.0) for username:1018 in 3.6 seconds, 3658 bytes.
Jun 13 19:05:42 host spamd[4236]: spamd: result: . -1 - BAYES_00,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FROM,HTML_MESSAGE,RCVD_IN_DNSWL_NONE,RCVD_IN_MSPIKE_H3,RCVD_IN_MSPIKE_WL,SPF_HELO_NONE,SPF_PASS,TVD_SPACE_RATIO scantime=3.6,size=3658,user=username,uid=1018,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=33638,mid=[<ab158c70-7e5f-edcd-f741-e6e56298bd08@gmail.com>](mailto:ab158c70-7e5f-edcd-f741-e6e56298bd08@gmail.com),bayes=0.000000,autolearn=ham autolearn_force=no
Jun 13 19:05:42 host postfix/local[9927]: 4F7D3C0055B: to=[<username@host.hostname.com>](mailto:username@host.hostname.com), orig_to=[<me@mydomain.com>](mailto:me@mydomain.com), relay=local, delay=61, delays=0.41/0.01/0/61, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME)
  1. Send local email from user2@mydomain2.com (username2) to me@mydomain.com (username):
Jun 13 19:16:31 host postfix/cleanup[13448]: 4228CC008E8: message-id=[<f32c361e-422f-5f64-191c-716a1afb1651@mydomain2.com>](mailto:f32c361e-422f-5f64-191c-716a1afb1651@mydomain2.com)
Jun 13 19:16:31 host opendkim[1178]: 4228CC008E8: DKIM-Signature field added (s=209, d=mydomain2.com)
Jun 13 19:16:31 host postfix/qmgr[20478]: 4228CC008E8: from=[<username2@mydomain2.com>](mailto:username2@mydomain2.com), size=1290, nrcpt=1 (queue active)
Jun 13 19:17:02 host spamd[4236]: spamd: setuid to username succeeded
Jun 13 19:17:02 host spamd[4236]: spamd: processing message [<f32c361e-422f-5f64-191c-716a1afb1651@mydomain2.com>](mailto:f32c361e-422f-5f64-191c-716a1afb1651@mydomain2.com) for username:1018
Jun 13 19:17:03 host spamd[4236]: spamd: clean message (-3.0/5.0) for username:1018 in 0.7 seconds, 2022 bytes.
Jun 13 19:17:03 host spamd[4236]: spamd: result: . -2 - ALL_TRUSTED,BAYES_00,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE scantime=0.7,size=2022,user=username,uid=1018,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=36684,mid=[<f32c361e-422f-5f64-191c-716a1afb1651@mydomain2.com>](mailto:f32c361e-422f-5f64-191c-716a1afb1651@mydomain2.com),bayes=0.000000,autolearn=ham autolearn_force=no
Jun 13 19:17:03 host postfix/local[13453]: 4228CC008E8: to=[<username@host.hostname.com>](mailto:username@host.hostname.com), orig_to=[<me@mydomain.com>](mailto:username@mydomain.com), relay=local, delay=32, delays=0.78/0.01/0/32, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME)

What could be cause those delays?
Thank you.

2

It looks to me like it’s spam assassin causing the delay by checking incoming and outgoing mail.

I’ve never seen anybody complain about a 30 second delay before though. I mean, who checks their email every 30 seconds?

3

It looks to me like it’s spam assassin causing the delay by checking incoming and outgoing mail.

spamassassin checks outgoing mail? It is not reflected in log file.
I turned off virus and spam filter of one of the hosted domains in Virtualmin Enabled features.
Delivery was instantly.
So spamassassin is the issue. Is it possible to reduce those delivery times?

I’ve never seen anybody complain about a 30 second delay before though. I mean, who checks their email every 30 seconds?

30 seconds if the mail is local, 1 minute from the rest of the world.
I didn’t complain for several months until…
Recently I had to receive a key by email to confirm a subscription. That key only lasted one minute so I couldn’t confirm it despite I repeated the action by “Resend key” from their website.
This is why I started complaining now

4

Mine takes 2s to go from postfix receipt to spamd processing.
Is your spamd running as a daemon, or on demand? Mine is a daemon.

Also make sure that DNS resolution is working (fast) on your machine; spamd by default does lookups.

1 Like
5

Hi creeble,

ps aux | grep spam

root     30798  0.4  1.0 304444 85856 ?        Ss   13:38   0:02 /usr/bin/spamd --pidfile /var/run/spamd.pid -d -c -m5 -H
root     30801  0.0  1.0 304444 82464 ?        S    13:38   0:00 spamd child
root     30802  0.0  1.0 304444 82496 ?        S    13:38   0:00 spamd child

In Webmin → Servers → Spamassassin Mail Filter → Can Spamassassin do DNS lookups is set to Default (Test) Other available options are Yes, No, Test by checking servers

I didn’t change DNS client from startup.
Resolution order is set 1) Host file 2) DNS 3) Local hostname
and DNS servers are 127.0.0.1; 213.136.95.11; 213.136.95.10

Should I set DNS at first place and add Gooogle Servers 8.8.8.8; 8.8.4.4 in first place too?

time dig @8.8.8.8 domain.tld
real 0m0,288s
user 0m0,006s
sys 0m0,007s

time dig domain.tld
real 0m0,054s
user 0m0,013s
sys 0m0,016s

6

The roundness of the numbers (~30 seconds and ~60 seconds) makes it seem very likely to be a DNS timeout. i.e. one of your DNS servers is not resolving and is timing out and spamassassin tries the next one.

7

That was my suspicion too.
I know that systems with systemd-resolved (Ubuntu, etc, I think newer CentOS?) all have local resolvers running, but I don’t like them. So the 127.0.0.1 resolver always makes me suspicious.
It’s not always easy to override this; depends on the distro.
But I always make a point to disable systemd-resolved and set my resolvers to Google, Quad9, Cloudflare, or whatever.

8

Hi Joe, I’m stuck here.

Networking Configuration → Hostname and DNS Client
I tested some sort of Resolution order/DNS servers but still at least around of 30s delay.

I’ve added 8.8.8.8 and 8.8.4.4 putting one of them in first place, save and Apply configuration
Data is saved at /etc/sysconfig/network-script/ifcfg-eth0

Checked those I’ve placed in the first position
time dig @8.8.8.8 domain.tld
time dig @127.0.0.1 domain.tld
…
times are less than 0.5s

Web pages load okay, there’s no such delay.

BTW, After “Apply configuration” I get a screen titled “Error” with this content: “Starting network (via systemctl): [ OK ]”

9

You don’t need to apply configuration after modifying DNS servers. It shouldn’t give an error, but you also don’t want to restart your network for no reason.

10

Does spamd run in some chroot jail? It runs as root.
Not that I’ve seen it with spamd in particular, but I have seen other things that run in chroot jails have DNS resolution problems. Generally it’s a total fail though, not a timeout. Hmm.

11

It’s up to the system package how spamd runs; we just install it and start the service. I don’t think it defaults to running in a chroot on any of our supported operating systems. So, I think it’s safe to assume that is not a factor here.

12

From the docs “SpamAssassin includes a default set of 13 servers, among which 3 are picked randomly”
By default SA, if dns_available is set to test, it checks every 600 secs retest for working DNS.
I added to /etc/mail/spamassassin/local.cf (Edit Config File in Webmin)
dns_options rotate
This way causes to SA “choose a DNS server at random from all servers listed in /etc/resolv.conf”
In my case it contains

nameserver 8.8.8.8
nameserver 127.0.0.1
nameserver 213.136.95.10
nameserver 213.136.95.11
nameserver 8.8.4.4
search …

Also I added to local.cf (and removed rotate)

dns_available test: google-public-dns-a.google.com

Delay problem still alive (SA version 3.4.0)

The average time SA takes to scan (spamd: clean message) is 2 seconds
Is there any other task apart of resolving DNS time which is fast in time dig @ns-IP ?
(I don’t know if SA resolves them that fast)

13

How to check that?

14

It’s his ISP…

15

How could it be? This is a VPS at Contabo in Germany

16

You could try removing their nameservers from resolv.conf.

But this raises the question on how it was installed?
There have been some threads recently where people using Contabo’s readymade Virtualmin template are having major issues because the template is faulty from the start… Just saying.

17

I commented those two lines of their name servers but delay persists.

It was in 2019 when I started using this Contabo VPS. I installed Webmin/Virtualmin by myself (install.sh) but I don’t remember if I asked them to install Centos 7 including Virtualmin first.
Surely I ran install.sh to include Webmin.
If I asked Contabo to include Virtualmin with the OS installation, does(did) …install.sh override the Contabo Virtualmin version?

18

If it was already installed in a faulty manner, I’m quite sure that you running install.sh wouldn’t make any difference.

But has it been this way since 2019?
What is the output of:
dig gmail.com @8.8.8.8 |grep "Query time"
Then replace 8.8.8.8 with 127.0.0.1, and try the nameservers provided by Contabo.

19

Since the time I realized there was a delivery delay, more than usual, more than a year ago, late 2019.

dig gmail.com @8.8.8.8 | grep "Query time"
Query time: 15 msec

dig gmail.com @127.0.0.1 | grep "Query time"
Query time: 354 msec

dig gmail.com @213.136.95.10 | grep "Query time" Contabo’s NS
Query time: 0 msec

dig gmail.com @213.136.95.11 | grep "Query time" Contabo’s NS
Query time: 0 msec

20

I’m stuck.
I stopped spamassassin service for a moment and nothing changed

Jun 16 20:08:23 host spamd[1540]: spamd: server killed by SIGTERM, shutting down
Jun 16 20:08:37 host postfix/smtpd[976]: connect from mail-qk1-f180.google.com[209.85.222.180]
Jun 16 20:08:38 host postfix/smtpd[976]: 338ADC008C1: client=mail-qk1-f180.google.com[209.85.222.180]
Jun 16 20:08:38 host postfix/cleanup[985]: 338ADC008C1: message-id=[<0a057d2c-dd12-9736-b4dc-223b550e3d2b@gmail.com>](mailto:0a057d2c-dd12-9736-b4dc-223b550e3d2b@gmail.com)
Jun 16 20:08:38 host opendkim[1331]: 338ADC008C1: mail-qk1-f180.google.com [209.85.222.180] not internal
Jun 16 20:08:38 host opendkim[1331]: 338ADC008C1: not authenticated
Jun 16 20:08:38 host opendkim[1331]: 338ADC008C1: no signing domain match for 'gmail.com'
Jun 16 20:08:38 host opendkim[1331]: 338ADC008C1: no signing subdomain match for 'gmail.com'
Jun 16 20:08:38 host opendkim[1331]: 338ADC008C1: DKIM verification successful
Jun 16 20:08:38 host postfix/qmgr[1750]: 338ADC008C1: from=[<U@gmail.com>](mailto:U@gmail.com), size=3476, nrcpt=1 (queue active)
Jun 16 20:08:38 host postfix/smtpd[976]: disconnect from mail-qk1-f180.google.com[209.85.222.180]
Jun 16 20:08:56 host dovecot: pop3-login: Login: user=<user>, method=PLAIN, rip=167.57.106.141, lip=173.249.47.114, mpid=1862, TLS, session=<yxvMLOrEkoinOWqN>
Jun 16 20:08:57 host dovecot: pop3(user): Disconnected: Logged out top=0/0, retr=0/0, del=0/18, size=50148
Jun 16 20:09:07 host spamc[1986]: connect to spamd on 127.0.0.1 failed, retrying (#1 of 3): Connection refused
Jun 16 20:09:07 host spamc[1986]: connect to spamd on ::1 failed, retrying (#1 of 3): No route to host
Jun 16 20:09:08 host spamc[1986]: connect to spamd on 127.0.0.1 failed, retrying (#2 of 3): Connection refused
Jun 16 20:09:08 host spamc[1986]: connect to spamd on ::1 failed, retrying (#2 of 3): No route to host
Jun 16 20:09:09 host spamc[1986]: connect to spamd on 127.0.0.1 failed, retrying (#3 of 3): Connection refused
Jun 16 20:09:09 host spamc[1986]: connect to spamd on ::1 failed, retrying (#3 of 3): No route to host
Jun 16 20:09:09 host spamc[1986]: connection attempt to spamd aborted after 3 retries
Jun 16 20:09:09 host postfix/local[987]: 338ADC008C1: to=[<username@host.domain.com>](mailto:username@host.domain.com), orig_to=[<user@domain.com>](mailto:user@domain.com), relay=local, delay=31, delays=0.27/0/0/31, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME)