У меня есть настройка почтового сервера на моем Debian Jessie VPS, которая включает postfix, amavisd-new, SpamAssassin и несколько других служб.
В целом кажется, что моя установка работает довольно хорошо и правильно обрабатывает входящую почту, однако время от времени amavisd-new зависает ('systemctl status amavis.service' показывает 'active (exited)').
Основываясь на журналах amavisd-new, я предполагаю, что это вызвано заданием обновления SpamAssassin, которое, насколько я понимаю, не может должным образом завершить работу amavisd-new; тем не менее, я не могу понять этого.
Amavisd-new находится в версии 1: 2.10.1-2 ~ deb8u1, SpamAssassin находится в версии 3.4.1-3 ~ bpo8 + 1.
Есть ли у кого-нибудь предложения, как это исправить или где поковырять?
Вот что ведет журнал amavis (с уровнем детализации 5) непосредственно перед зависанием:
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
Любая помощь высоко ценится. Заранее спасибо!
РЕДАКТИРОВАТЬ:
systemctl status amavis.service
дает следующее:
● 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.
Я просмотрел сегодняшний mail.log и нашел следующую информацию:
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
Это наводит меня на мысль, что это может быть спам, который перезапускает мой демон amavis. Но как я могу узнать, какой процесс всегда перезапускает spamd?
Куда копать глубже?
Это похоже на то, как две копии запускаются одновременно ... Можете ли вы предотвратить запуск amavisd-new systemd или чем-то еще и запустить его самостоятельно из командной строки?
См. Страницу руководства. Есть режимы отладки и режим переднего плана.
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