Сервер зависает на перезагрузке, когда моллюск работает

Вкратце

Перезагрузка обычно занимает менее чем 1 минуту, но если clamav-daemon работает, перезагрузка займет 30 минут точно.

Обзор

У меня есть "облачный" почтовый сервер Ubuntu 15.10: постфикс, голубятня, mysql, получил доступ через SSH. Это работало в течение многих недель и перезагрузок через менее чем 1 минуту. Все было хорошо, пока я не установил Amavis, через Кв. Ubuntu - получают пакеты установки - теперь, перезагрузка занимает точно 30 минут, каждый раз.

При выполнении все работает. Я проверил журналы и никакие явные проблемы. Clamav работает, почта отправляет и получает, и использование ЦП колеблется между 0% и 0,5%.

Моя теория

Я сузил проблему к clamav-daemon путем исключения. Единственной новой установкой был Amavis, который добавил новых демонов. Если я останавливаю их всех (amavis, clamav-daemon, и clamav-freshclam), затем перезагрузка мгновенна. Если я останавливаюсь просто clamav-daemon, перезагрузка мгновенна. Но если я поддерживаю его в рабочем состоянии и останавливаю все другие, перезагрузка составляет 30 минут снова.

Это абсолютно повторяемо, и ожидание является всегда точно 30 минутами. Это заставляет меня думать, что Clamav ожидает ввода данных пользователем с 30-минутным тайм-аутом.

Я вижу, что процессы для Clamav работают с"--foreground=true". Это заставляет меня думать, что Amavis намеренно делает это для получения вывода, но не ожидает подсказку во время перезагрузки.

От htop:

Мои журналы

Примечание: /etc/init.d/sendsigs имеет report_unkillable позволенный поймать неубиваемые процессы, и /etc/default/apport включен. Входит в систему /var/crash не имейте ничего недавнего.

(Перезапущенный около 14:51, и сервер не был SSH готовый до 15:23 - 30 минут спустя, без промежуточных ошибок.)

/var/log/clamav/clamav.log

...
14:52:45 2016 -> --- Stopped at Fri 14:52:45 2016
15:23:04 2016 -> +++ Started at Fri 15:23:04 2016
15:23:04 2016 -> Received 1 file descriptor(s) from systemd.
15:23:04 2016 -> clamd daemon 0.98.7 (OS: linux-gnu, ARCH: x86_64, CPU: x86_64)
15:23:04 2016 -> Running as user clamav (UID 119, GID 127)
...

/var/log/mail.log

...
14:51:15 mail amavis[1578]: Using primary internal av scanner code for ClamAV-clamd
14:51:15 mail amavis[1578]: Found secondary av scanner ClamAV-clamscan at /usr/bin/clamscan
14:51:15 mail amavis[1578]: Deleting db files __db.001,nanny.db,__db.003,snmp.db,__db.002 in /var/lib/amavis/db
14:51:15 mail amavis[1578]: Creating db in /var/lib/amavis/db/; BerkeleyDB 0.55, libdb 5.3
15:23:05 mail postgrey[820]: Process Backgrounded
15:23:05 mail postgrey[820]: 2016/02/12-15:23:05 postgrey (type Net::Server::Multiplex) starting! pid(820)
15:23:05 mail postgrey[820]: Resolved [localhost]:10023 to [::1]:10023, IPv6
15:23:05 mail postgrey[820]: Resolved [localhost]:10023 to [127.0.0.1]:10023, IPv4
...

/var/log/syslog

...
14:52:18 mail systemd[1]: Stopping ClamAV virus database updater...
14:52:18 mail freshclam[760]: Update process terminated
14:52:18 mail systemd[1]: Stopped ClamAV virus database updater.
14:52:42 mail systemd[1]: Stopped Setup Virtual Console.
14:52:42 mail systemd[1]: Stopping LVM2 PV scan on device 202:2...
14:52:42 mail systemd[1]: Deactivating swap /dev/disk/by-uuid/758b48d5-df40-4ca8-af0d-a482044d21dd...
14:52:42 mail systemd[1]: Stopping Authenticate and Authorize Users to Run Privileged Tasks...
14:52:42 mail systemd[1]: Stopping User Manager for UID 1000...
14:52:42 mail systemd[1907]: Reached target Shutdown.
14:52:42 mail swapoff[2140]: swapoff: /dev/mapper/ubuntu-swap: swapoff failed: Cannot allocate memory
14:52:42 mail systemd[1907]: Starting Exit the Session...
14:52:42 mail systemd[1907]: Stopped target Default.
14:52:42 mail systemd[1]: Stopping Session 1 of user gavannon.
14:52:42 mail systemd[1907]: Stopped target Basic System.
14:52:42 mail systemd[1907]: Stopped target Sockets.
14:52:42 mail systemd[1]: Stopped target Graphical Interface.
14:52:42 mail systemd[1907]: Stopped target Paths.
14:52:42 mail systemd[1907]: Stopped target Timers.
14:52:42 mail systemd[1]: Removed slice system-ifup.slice.
14:52:42 mail systemd[1]: Removed slice system-systemd\x2dfsck.slice.
14:52:42 mail systemd[1]: Stopped target Timers.
14:52:42 mail systemd[1]: Stopping Accounts Service...
14:52:42 mail systemd[1]: Stopped target Multi-User System.
14:52:42 mail systemd[1]: Stopped Set Cloud Password.
14:52:42 mail systemd[1]: Stopping LSB: Record successful boot for GRUB...
14:52:42 mail systemd[1]: Stopping LSB: Starts amavisd-new mailfilter...
14:52:42 mail systemd[1]: Stopping OpenBSD Secure Shell server...
14:52:42 mail systemd[1]: Stopped target Login Prompts.
14:52:42 mail systemd[1]: Stopping Getty on tty1...
14:52:42 mail systemd[1]: Stopping LSB: XenServer Virtual Machine daemon providing host integration services...
14:52:42 mail rsyslogd: [origin software="rsyslogd" swVersion="8.12.0" x-pid="729" x-info="http://www.rsyslog.com"] exiting on signal 15.

(Something must be happening here, because the next line isn't for 30 minutes)

15:23:04 mail rsyslogd: [origin software="rsyslogd" swVersion="8.12.0" x-pid="770" x-info="http://www.rsyslog.com"] start
15:23:04 mail rsyslogd-2222: command 'KLogPermitNonKernelFacility' is currently not permitted - did you already set it via a RainerScript command (v6+ $
15:23:04 mail rsyslogd: rsyslogd's groupid changed to 109

Последняя вещь, которая происходит в 14:52, регистрируется, закрывается (rsyslogd говорит exiting). Следующая строка является журналом, запускающим снова на начальной загрузке, но это 30 минут спустя!