0

I have a mail server setup running on my Debian Jessie VPS which includes postfix, amavisd-new, SpamAssassin and a few other services.

All in all it seems my setup works pretty well and handles incoming mails correctly, however from time to time amavisd-new freezes ('systemctl status amavis.service' shows 'active (exited)').

Based on the amavisd-new logs I suppose it is caused by SpamAssassin's update job, which from my understanding fails to shut down amavisd-new properly; still, I can't make any sense of it.

Amavisd-new is in version 1:2.10.1-2~deb8u1, SpamAssassin is in version 3.4.1-3~bpo8+1.

Does anybody have a suggestion how to correct this or where to dig deeper?

Here is what amavis logs (with verbosity level set to 5) right before the freeze:

Aug 27 06:58:00 server.example.com /usr/sbin/amavisd-new[2476]: Net::Server: 2016/08/27-06:57:57 Server closing!
Aug 27 06:58:01 server.example.com /usr/sbin/amavisd-new[2476]: Net::Server: Kill TERM pid 2496
Aug 27 06:58:01 server.example.com /usr/sbin/amavisd-new[2476]: Net::Server: Kill TERM pid 2495
Aug 27 06:58:05 server.example.com /usr/sbin/amavisd-new[2495]: child_goes_idle (child finishing)
Aug 27 06:58:08 server.example.com /usr/sbin/amavisd-new[2495]: child_goes_idle: disconnected none (child finishing)
Aug 27 06:58:06 server.example.com /usr/sbin/amavisd-new[2496]: (02496-01) child_goes_idle (child finishing)
Aug 27 06:58:10 server.example.com /usr/sbin/amavisd-new[2496]: (02496-01) child_goes_idle: disconnected none (child finishing)
Aug 27 06:58:10 server.example.com /usr/sbin/amavisd-new[2496]: (02496-01) SA rundown_child (0)
Aug 27 06:58:10 server.example.com /usr/sbin/amavisd-new[2495]: SA rundown_child (0)
Aug 27 06:58:13 server.example.com /usr/sbin/amavisd-new[13635]: logging initialized, log level 5, logfile: /var/log/amavis.log
Aug 27 06:58:13 server.example.com /usr/sbin/amavisd-new[13635]: starting. /usr/sbin/amavisd-new at server.example.com amavisd-new-2.10.1 (20141025), Unicode aware, LC_ALL="C", LANG="de_DE.UTF-8"
Aug 27 06:58:13 server.example.com /usr/sbin/amavisd-new[13635]: perl=5.020002, user=, EUID: 119 (119);  group=, EGID: 126 126 (126 126)
Aug 27 06:58:17 server.example.com /usr/sbin/amavisd-new[13635]: INFO: no optional modules: unicore::lib::Perl::SpacePer.pl unicore::lib::Nt::De.pl Unix::Getrusage
Aug 27 06:58:17 server.example.com /usr/sbin/amavisd-new[13635]: SpamControl: attempting to load scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
Aug 27 06:58:17 server.example.com /usr/sbin/amavisd-new[13635]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[2496]: (02496-01) SpamControl: rundown_child on SpamAssassin done
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[2495]: SpamControl: rundown_child on SpamAssassin done
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[2496]: (02496-01) child_finish_hook: invoking DESTROY methods
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[2495]: child_finish_hook: invoking DESTROY methods
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13635]: INFO: SA version: 3.4.1, 3.004001, no optional modules: Net::CIDR::Lite Encode::Detect Image::Info Image::Info::GIF Image::Info::JPEG Image::Info::PNG Image::Info::BMP Image::Info::TIFF
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13635]: SpamControl: init_pre_chroot on SpamAssassin done
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13635]: socket module IO::Socket::IP, protocol families available: INET, INET6
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13635]: bind to /var/lib/amavis/amavisd.sock|unix, 127.0.0.1:10024/tcp, [::1]:10024/tcp
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13643]: Net::Server: Process Backgrounded
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13643]: Net::Server: 2016/08/27-06:58:24 Amavis (type Net::Server::PreForkSimple) starting! pid(13643)
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13643]: Net::Server: Binding to UNIX socket file "/var/lib/amavis/amavisd.sock"
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13643]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13643]: (!)Net::Server: 2016/08/27-06:58:24 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
Aug 27 06:58:24 server.example.com /usr/sbin/amavisd-new[13643]: Net::Server: 2016/08/27-06:58:24 Server closing!
Aug 27 06:58:26 server.example.com /usr/sbin/amavisd-new[2496]: (02496-01) TempDir::DESTROY called
Aug 27 06:58:32 server.example.com /usr/sbin/amavisd-new[2495]: Amavis::DB::SNMP DESTROY called
Aug 27 06:58:32 server.example.com /usr/sbin/amavisd-new[2496]: (02496-01) Amavis::DB::SNMP DESTROY called

Any help is highly appreciated. Thanks in advance!

EDIT:

systemctl status amavis.service gives the following:

● amavis.service - LSB: Starts amavisd-new mailfilter
   Loaded: loaded (/etc/init.d/amavis; generated; vendor preset: enabled)
   Active: active (exited) since Do 2016-12-01 07:06:25 CET; 5h 41min ago
     Docs: man:systemd-sysv-generator(8)
  Process: 6971 ExecStop=/etc/init.d/amavis stop (code=exited, status=0/SUCCESS)
  Process: 6981 ExecStart=/etc/init.d/amavis start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/amavis.service

Dez 01 07:06:03 server systemd[1]: Starting LSB: Starts amavisd-new mailfilter...
Dez 01 07:06:14 server amavis[6987]: starting. /usr/sbin/amavisd-new at server.example.com amavisd-new-2.10.1 (20141025), Unicode aware, LC_AL
Dez 01 07:06:25 server amavis[7000]: (!)Net::Server: 2016/12/01-07:06:25 Can't connect to TCP port 10024 on 127.0.0.1 [Address already in use]\
Dez 01 07:06:27 server amavis[6981]: Starting amavisd: amavisd-new.
Dez 01 07:06:25 server systemd[1]: Started LSB: Starts amavisd-new mailfilter.

I scanned today's mail.log and found the following info:

Dec  1 07:05:55 server spamd[14187]: spamd: server hit by SIGHUP, restarting
Dec  1 07:05:56 server spamd[14187]: spamd: child [14196] killed successfully: interrupted, signal 2 (0002)
Dec  1 07:05:56 server spamd[14187]: spamd: child [14197] killed successfully: interrupted, signal 2 (0002)
Dec  1 07:06:02 server spamd[14187]: spamd: server socket closed, type IO::Socket::IP
Dec  1 07:06:03 server spamd[14187]: spamd: server socket closed, type IO::Socket::IP
Dec  1 07:06:13 server spamd[14187]: logger: removing stderr method
Dec  1 07:06:14 server amavis[6987]: starting. /usr/sbin/amavisd-new at server.example.com amavisd-new-2.10.1 (20141025), Unicode aware, LC_ALL="C", LANG="de_DE.UTF-8"
Dec  1 07:06:15 server spamd[6995]: zoom: able to use 342/342 'body_0' compiled rules (100%)
Dec  1 07:06:25 server amavis[7000]: (!)Net::Server: 2016/12/01-07:06:25 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
Dec  1 07:06:32 server spamd[6995]: spamd: server started on IO::Socket::IP [127.0.0.1]:783, IO::Socket::IP [::1]:783 (running version 3.4.0)
Dec  1 07:06:34 server spamd[6995]: spamd: server pid: 6995
Dec  1 07:06:34 server spamd[6995]: spamd: server successfully spawned child process, pid 7005
Dec  1 07:06:34 server spamd[6995]: spamd: server successfully spawned child process, pid 7006
Dec  1 07:06:34 server spamd[6995]: prefork: child states: II

This leads me to the idea that it might be spamd itself which restarts my amavis daemon. But how can I find out, what process always restarts spamd?

randomnickname
  • 513
  • 2
  • 11
  • 1
    I haven't used any of that sofware in years but it seems to pretty clearly indicate to me that one copy is being stopped and another being started. Whatever is doing that.. The new one shouldn't be started until the first has finished exiting. Whatever script is doing that needs that bug fixed. –  Aug 27 '16 at 07:15

1 Answers1

0

Where to dig deeper?

It's like two copies are starting at the same time... can you prevent systemd or whatever from starting amavisd-new and run it yourself from the command line?

See the man page. There's are debug modes and a foreground mode.

http://manpages.ubuntu.com/manpages/trusty/man8/amavisd-new.8.html

       debug  Runs amavisd-new in debug mode

       debug-sa
              Runs amavisd-new in spamassassin debug mode

       foreground
              Does not fork to background
Ryan Babchishin
  • 6,260
  • 2
  • 17
  • 37
  • To me it doesn't seem that a running amavisd-new process causes the problem, but another process (current guess: spamd) that either tries to start a second daemon or restarts amavisd-new in a problematic way. Running amavisd-new in debug mode therefore doesn't give any new insights. What I already did was adding log entries in amavisd-new's and spamassassin's crons (which both try to restart amavisd-new after updates) so that they log the process' state before and after the restart. However, this didn't provide any insight (either stayed active or exited before already). – randomnickname Dec 01 '16 at 12:32