Bug 18921

Summary:	spamd very slow, timeouts 15 sec on each DNS request
Product:	Mageia	Reporter:	Nicolas Pomarède <npomarede>
Component:	RPM Packages	Assignee:	All Packagers <pkg-bugs>
Status:	NEW ---	QA Contact:
Severity:	major
Priority:	Normal	CC:	marja11, ngompa13, ouaurelien
Version:	Cauldron
Target Milestone:	Mageia 7
Hardware:	All
OS:	Linux
Whiteboard:	MGA7TOO
Source RPM:	spamassassin-3.4.1-1.mga5, systemd	CVE:
Status comment:

Description Nicolas Pomarède 2016-07-11 10:59:56 CEST

Hello

when sending each incoming mail to spamassassin through spamd, I noticed it took a very long time to process them. Looking at syslog traces, one can see that each mail take 15 sec to be processed, which is not normal behaviour, checking all spam rules should take 2-3 sec at most.

For example, these are the logs from spamd.log :

Tue Jun 21 07:42:03 2016 [26023] info: spamd: connection from pulsar [::1]:41247 to port 783, fd 6
Tue Jun 21 07:42:03 2016 [26023] info: spamd: setuid to npomarede succeeded
Tue Jun 21 07:42:03 2016 [26023] info: spamd: processing message <D776FA7A-2F0A-483E-BDC1-80991E4BBCE0@mail.6brent.info> for npomarede:500
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [127.0.0.1]:53 failed: Connection refused, failing over to [::1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [::1]:53 failed: Connection refused, failing over to [127.0.0.1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [127.0.0.1]:53 failed: Connection refused, failing over to [::1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [::1]:53 failed: Connection refused, failing over to [127.0.0.1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [127.0.0.1]:53 failed: Connection refused, failing over to [::1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [::1]:53 failed: Connection refused, failing over to [127.0.0.1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [127.0.0.1]:53 failed: Connection refused, failing over to [::1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [::1]:53 failed: Connection refused, failing over to [127.0.0.1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [127.0.0.1]:53 failed: Connection refused, failing over to [::1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [::1]:53 failed: Connection refused, failing over to [127.0.0.1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [127.0.0.1]:53 failed: Connection refused, failing over to [::1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [::1]:53 failed: Connection refused, failing over to [127.0.0.1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [127.0.0.1]:53 failed: Connection refused, failing over to [::1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [::1]:53 failed: Connection refused, failing over to [127.0.0.1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [127.0.0.1]:53 failed: Connection refused, failing over to [::1]:53
Tue Jun 21 07:42:03 2016 [26023] warn: dns: sendto() to [::1]:53 failed: Connection refused, failing over to [127.0.0.1]:53
Tue Jun 21 07:42:03 2016 [26023] info: dns: bad dns reply: bgread: recv() failed: Connection refused at /usr/lib/perl5/vendor_perl/5.20.1/Mail/SpamAssassin/DnsResolver.pm line 743, <GEN3720> line 90.
Tue Jun 21 07:42:03 2016 [26023] info: dns: bad dns reply: bgread: recv() failed: Connection refused at /usr/lib/perl5/vendor_perl/5.20.1/Mail/SpamAssassin/DnsResolver.pm line 743.
Tue Jun 21 07:42:06 2016 [26023] info: dns: bad dns reply: bgread: recv() failed: Connection refused at /usr/lib/perl5/vendor_perl/5.20.1/Mail/SpamAssassin/DnsResolver.pm line 743.
Tue Jun 21 07:42:09 2016 [26023] info: dns: bad dns reply: bgread: recv() failed: Connection refused at /usr/lib/perl5/vendor_perl/5.20.1/Mail/SpamAssassin/DnsResolver.pm line 743.
Tue Jun 21 07:42:12 2016 [26023] info: dns: bad dns reply: bgread: recv() failed: Connection refused at /usr/lib/perl5/vendor_perl/5.20.1/Mail/SpamAssassin/DnsResolver.pm line 743.
Tue Jun 21 07:42:18 2016 [26023] info: spamd: identified spam (11.7/5.0) for npomarede:500 in 15.0 seconds, 2940 bytes.
Tue Jun 21 07:42:18 2016 [26023] info: spamd: result: Y 11 - ADVANCE_FEE_5_NEW,BAYES_50,DEAR_BENEFICIARY,FREEMAIL_FORGED_REPLYTO,FREEMAIL_REPLYTO_END_DIGIT,HK_NAME_MR_MRS,HTML_MESSAGE,RDNS_NONE,SUBJ_ALL_CAPS,TVD_PH_BODY_META,T_SPF_HELO_TEMPERROR,T_SPF_TEMPERROR scantime=15.0,size=2940,user=npomarede,uid=500,required_score=5.0,rhost=pulsar,raddr=::1,rport=41247,mid=<D776FA7A-2F0A-483E-BDC1-80991E4BBCE0@mail.6brent.info>,bayes=0.497152,autolearn=no autolearn_force=no
Tue Jun 21 07:42:18 2016 [2035] info: prefork: child states: II

-> mail is received at 07:42:03 and process ended at 07:42:18, with lots of DNS error


As described here https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=741521 , the problem is that spamassassin uses his own DNS resolver and gets his list of DNS servers by reading /etc/resolv.conf when spamd is started

But when spamd starts at boot, network is not necessarily up yet, so /etc/resolv.conf will be empty and spamd will default to 127.0.0.1 and unless you have a local DNS resolver, this will fail.

This is similar to https://bugs.mageia.org/show_bug.cgi?id=17219 affecting dovecot : /usr/lib/systemd/system/spamd.service waits for "network.target" but it should wait for "network-online.target"

Another solution would be to restart spamd each time an interface becomes up, so if your wifi network changes, then spamd gets the new DNS servers, but I don't know if such triggers are possible ? At least, changing /usr/lib/systemd/system/spamd.service should fix the problem in most cases.


From what I see, this should also be updated in cauldron for the soon to be released mageia 6.

Comment 1 Marja Van Waes 2016-07-14 14:12:21 CEST

Assigning to maintainer

Source RPM: spamassassin-spamd-3.4.1-1.mga5 => spamassassin-3.4.1-1.mga5
CC: (none) => marja11
Assignee: bugsquad => remco

Comment 2 Nicolas Pomarède 2016-09-30 11:29:23 CEST

Ping, anyone to change /usr/lib/systemd/system/spamd.service and use "network-online.target" instead ? This should not have any negative impact.

Comment 3 Marja Van Waes 2018-04-29 09:42:48 CEST

(In reply to Nicolas Pomarède from comment #2)
> Ping, anyone to change /usr/lib/systemd/system/spamd.service and use
> "network-online.target" instead ? This should not have any negative impact.

Hi Nicolas,

Thank you for having taken the needed time to report this issue!

Did this bug get fixed? If so, please change its status to RESOLVED - FIXED

If it didn't, then we regret that we weren't able to fix it in Mageia 5. Mageia 5 has officially reached its End of Life on December 31st, 2017 https://blog.mageia.org/en/2017/11/07/mageia-5-eol-postponed/
It only continued to get important security updates since then, because we are waiting for a big Plasma5 update in Mageia 6, that'll fix many of the Mageia 5 => 6 upgrade issues.

If you haven't seen that this bug got fixed, then please check whether this bug still exists in Mageia 6. If it does, then please change the Version (near the top, at the left) to "6". If you know it exists in Cauldron, then change Version to Cauldron. If you see it in both Cauldron and Mageia 6, then please set Version to Cauldron and add MGA6TOO on the Whiteboard.

Thanks,
Marja

(In case this report needs to stay open for a supported release: Reassigning to all packagers collectively, since there is no longer a registered maintainer for spamassassin, and CC'ing Neal, because he works on systemd a lot)

Assignee: remco => pkg-bugs
CC: (none) => ngompa13
Source RPM: spamassassin-3.4.1-1.mga5 => spamassassin-3.4.1-1.mga5, systemd

Comment 4 Nicolas Pomarède 2018-05-02 20:33:35 CEST

Hi
just checked on latest cauldron version spamassassin-spamd-3.4.1-5.mga7.x86_64.rpm and the issue is still there :

This is the start of /usr/lib/systemd/system/spamd.service :

[Unit]
Description=Spamassassin daemon
After=syslog.target network.target

As can be seen, it still uses network.target instead of network-online.target which  means spamd will have bad dns timeout in case it starts too fast before network (and dns) are really up.

Bug status updated as requested.

Whiteboard: (none) => MGA6TOO
Version: 5 => Cauldron

Comment 5 Aurelien Oudelet 2020-09-10 16:07:40 CEST

Ping this bug

Whiteboard: MGA6TOO => MGA7TOO
Target Milestone: --- => Mageia 7
Severity: normal => major
CC: (none) => ouaurelien

Comment 6 Nicolas Pomarède 2020-09-10 16:15:45 CEST

This dns problem can appear or not depending on how fast the network target starts after a reboot.
I didn't see it recently, but I see that under mageia 7 spamd.service still uses :

[Unit]
Description=Spamassassin daemon
After=syslog.target network.target

I think it would be safer to use "network-online.target" instead.
Maybe it's already the case under cauldron/mageia 8, can't check at the moment.