Troubles when restarting amavis

[nerbrume at free.fr]

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