Hello,

I'm using spamassassin and amavisd-new on a Debian 9. (and some other software that might be relevant : Postfix, dovecot, shorewall) Spamassassin is set to restart amavis upon any DB update, at around 4h20 (am). (This is Debian default config, I don't know why it really need to be done). Since approx. 5 months, amavis would sometime crash upon this restart, with the following error (in /var/log/syslog. A bit more context added at the end of this mail):


Feb 11 04:23:15 myserver amavis[23850]: (!)Net::Server: 2018/02/11-04:23:15 Can't connect to TCP port 10024 on 127.0.0.1 [Address already in use]\n at line 68 in file /usr/share/perl5/Net/Server/Proto/TCP.pm

(amavis is indeed configured to listen on 10024)

This crash is very rare, I would say about once a month, if not less.
I typically never managed to trigger it when restarting amavis manually.
However when it happens, it is quite bothersome : all incoming e-mail gets rejected, including the alerts that warns me about the amavis failure to restart...

When Spamassassin restarts amavis, it calls "/etc/init.d/amavis restart" which in turn calls sequentially "stop" then "start", using start-stop-daemon, with a PID file. I've tried to set a delay (20s) between the stop and start, without much luck.

I can post my amavis and/or spamassassin config, but nothing changed since at least 1 or 2 years, so I don't think the culprit is there. From my admin notes, the only thing that might have changed on this machine (and that could be relevant) is it's ipv6 connectivity.

Any idea of what might be going on ?
Any idea of where I might be looking for clues ? Any debug option I could enable ?

Thanks for reading !

N


P.S. : the error, from /var/log/syslog, with a bit more context (real server name is redacted). As you can see everything else seems to be ok... :

Feb 11 04:22:36 myserver systemd[1]: Reloading Perl-based spam filter using text analysis. Feb 11 04:22:36 myserver systemd[1]: Reloaded Perl-based spam filter using text analysis. Feb 11 04:22:37 myserver systemd[1]: Stopping LSB: Starts amavisd-new mailfilter... Feb 11 04:22:39 myserver spamd[2957]: spamd: server hit by SIGHUP, restarting Feb 11 04:22:41 myserver spamd[2957]: spamd: child [2979] killed successfully: interrupted, signal 2 (0002) Feb 11 04:22:41 myserver spamd[2957]: spamd: child [2978] killed successfully: interrupted, signal 2 (0002) Feb 11 04:22:44 myserver spamd[2957]: spamd: server socket closed, type IO::Socket::IP Feb 11 04:22:44 myserver spamd[2957]: spamd: server socket closed, type IO::Socket::IP Feb 11 04:22:47 myserver spamd.pid --create-prefs --max-children 5 --helper-home-dir: spamd: restarting using '/usr/sbin/spamd -d --pidfile=/var/run/spamd.pid --create-prefs --max-children 5 --helper-home-dir'
Feb 11 04:22:47 myserver spamd[2957]: logger: removing stderr method
Feb 11 04:22:55 myserver amavis[23809]: Stopping amavisd: amavisd-new.
Feb 11 04:22:55 myserver systemd[1]: Stopped LSB: Starts amavisd-new mailfilter. Feb 11 04:22:55 myserver systemd[1]: Starting LSB: Starts amavisd-new mailfilter... Feb 11 04:22:56 myserver spamd[23816]: zoom: able to use 347/347 'body_0' compiled rules (100%) Feb 11 04:23:05 myserver spamd[23816]: spamd: server started on IO::Socket::IP [::1]:783, IO::Socket::IP [127.0.0.1]:783 (running version 3.4.1)
Feb 11 04:23:05 myserver spamd[23816]: spamd: server pid: 23816
Feb 11 04:23:05 myserver spamd[23816]: spamd: server successfully spawned child process, pid 23846 Feb 11 04:23:05 myserver spamd[23816]: spamd: server successfully spawned child process, pid 23847
Feb 11 04:23:05 myserver spamd[23816]: prefork: child states: IS
Feb 11 04:23:05 myserver spamd[23816]: prefork: child states: II
Feb 11 04:23:05 myserver amavis[23834]: starting. /usr/sbin/amavisd-new at myserver.mydomain.com amavisd-new-2.10.1 (20141025), Unicode aware, LC_ALL="C", LANG="fr_FR.UTF-8"
Feb 11 04:23:15 myserver amavis[23827]: Starting amavisd: amavisd-new.
Feb 11 04:23:15 myserver systemd[1]: Started LSB: Starts amavisd-new mailfilter. Feb 11 04:23:15 myserver amavis[23850]: (!)Net::Server: 2018/02/11-04:23:15 Can't connect to TCP port 10024 on 127.0.0.1 [Address already in use]\n at line 68 in file /usr/share/perl5/Net/Server/Proto/TCP.pm

to be compared with a "normal" (here, triggered manually) restart :

Feb 9 05:00:02 myserver systemd[1]: Stopping LSB: Starts amavisd-new mailfilter...
Feb  9 05:00:16 myserver amavis[6488]: Stopping amavisd: amavisd-new.
Feb 9 05:00:16 myserver systemd[1]: Stopped LSB: Starts amavisd-new mailfilter. Feb 9 05:00:16 myserver systemd[1]: Starting LSB: Starts amavisd-new mailfilter... Feb 9 05:00:33 myserver amavis[8917]: starting. /usr/sbin/amavisd-new at myserver.mydomain.com amavisd-new-2.10.1 (20141025), Unicode aware, LC_ALL="C", LANG="fr_FR.UTF-8"
Feb  9 05:00:46 myserver amavis[8703]: Starting amavisd: amavisd-new.
Feb 9 05:00:46 myserver systemd[1]: Started LSB: Starts amavisd-new mailfilter. Feb 9 05:00:46 myserver amavis[11922]: Net::Server: Group Not Defined. Defaulting to EGID '129 129' Feb 9 05:00:46 myserver amavis[11922]: Net::Server: User Not Defined. Defaulting to EUID '119'
Feb  9 05:00:46 myserver amavis[11922]: Module Amavis::Conf        2.404
(...)
(... more module loading ...)
(...)
Feb 9 05:00:48 laborit amavis[11922]: Using primary internal av scanner code for ClamAV-clamd Feb 9 05:00:48 laborit amavis[11922]: Found secondary av scanner ClamAV-clamscan at /usr/bin/clamscan Feb 9 05:00:48 laborit amavis[11922]: Deleting db files __db.002,nanny.db,__db.003,__db.001,snmp.db in /var/lib/amavis/db Feb 9 05:00:48 laborit amavis[11922]: Creating db in /var/lib/amavis/db/; BerkeleyDB 0.55, libdb 5.3

Reply via email to