Re: amavisd clean shutdown and restart

On Thu, 24 Feb 2022 08:44:15 +0100
Damian <[email protected]> wrote:

> > Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97857]: (97857-03)
> > rmdir_recursively: /var/amavis/tmp/amavis-20220223T235319-97857-Mo9niBLX/parts,
> > excl=
> > 
> > # cat /var/log/amavisd.log | head -n 5
> > Feb 24 00:00:00 [server] newsyslog[63582]: logfile turned over
> > Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: logging
> > initialized, log level 4, logfile: /var/log/amavisd.log
> 
> Please check if you can reproduce the problem with syslog instead of
> a logfile. Besides, what are the processes doing between 00:05 and
> 00:59? Are they in uninterruptible sleep, what does strace say (or
> whatever BSD has to offer)? Are there still temporary directories
> which have been logged with rmdir_recursively?

I did not want to make all the changes you have suggested all at once.

A few minutes before log rotation I have:

- reloaded postfix so it sends nothing to amavisd

- stopped monit so it would not interfere

Here is the amavisd log file... amavisd restarted just fine:

# bzcat /var/log/amavisd.log.0.bz2 | tail -n 55
Feb 24 23:50:28 [server] /usr/local/sbin/amavisd[74284]: (74284-19) SMTP session over, timer stopped
Feb 24 23:50:28 [server] /usr/local/sbin/amavisd[74284]: (74284-19) load: 0 %, total idle 8330.935 s, busy 3.060 s
Feb 25 00:00:00 [server] newsyslog[39265]: logfile turned over
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[63629]: Net::Server: Received a SIG HUP
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[63629]: sd_notify (no socket): STOPPING=1\nSTATUS=Server rundown, notifying child processes.
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[63629]: Net::Server: 2022/02/25-00:00:04 Server closing!
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[63629]: Net::Server: Sending children hup signal
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74244]: (74244-19) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[75222]: (75222-01) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74270]: (74270-19) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74267]: (74267-19) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[75215]: (75215-01) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74254]: (74254-19) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[75276]: SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74355]: (74355-18) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74377]: (74377-17) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74265]: (74265-19) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74232]: (74232-19) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[75233]: (75233-01) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74244]: (74244-19) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T223040-74244-KO0iyqML
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74270]: (74270-19) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T221928-74270-vqh6VK4L
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74233]: (74233-19) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74267]: (74267-19) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T213000-74267-dYawBCEA
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74254]: (74254-19) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T225929-74254-hzOO_xxK
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[75272]: SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74228]: (74228-19) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74284]: (74284-19) SA rundown_child (0)
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74355]: (74355-18) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T215116-74355-ilBWXUdL
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[63629]: sd_notify (no socket): RELOADING=1\nSTATUS=Reloading server, about to re-exec the program.
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74265]: (74265-19) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T213700-74265-JJoEpSwb
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74232]: (74232-19) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T212636-74232-BLmEVNgr
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74244]: (74244-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T223040-74244-KO0iyqML, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74270]: (74270-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T221928-74270-vqh6VK4L, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74233]: (74233-19) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T212642-74233-Iuaa2qAL
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74267]: (74267-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T213000-74267-dYawBCEA, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74254]: (74254-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T225929-74254-hzOO_xxK, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74355]: (74355-18) rmdir_recursively: /var/amavis/tmp/amavis-20220224T215116-74355-ilBWXUdL, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74228]: (74228-19) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T221349-74228-iKZ5b0_3
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74284]: (74284-19) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220224T221933-74284-chi8jgni
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74265]: (74265-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T213700-74265-JJoEpSwb, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74232]: (74232-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T212636-74232-BLmEVNgr, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74233]: (74233-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T212642-74233-Iuaa2qAL, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74244]: (74244-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T223040-74244-KO0iyqML/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74267]: (74267-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T213000-74267-dYawBCEA/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74254]: (74254-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T225929-74254-hzOO_xxK/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74228]: (74228-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T221349-74228-iKZ5b0_3, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74284]: (74284-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T221933-74284-chi8jgni, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74355]: (74355-18) rmdir_recursively: /var/amavis/tmp/amavis-20220224T215116-74355-ilBWXUdL/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74265]: (74265-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T213700-74265-JJoEpSwb/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74270]: (74270-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T221928-74270-vqh6VK4L/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74232]: (74232-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T212636-74232-BLmEVNgr/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74233]: (74233-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T212642-74233-Iuaa2qAL/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74284]: (74284-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T221933-74284-chi8jgni/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[74228]: (74228-19) rmdir_recursively: /var/amavis/tmp/amavis-20220224T221349-74228-iKZ5b0_3/parts, excl=
Feb 25 00:00:04 [server] /usr/local/sbin/amavisd[63629]: (!)Net::Server: 2022/02/25-00:00:04 Re-exec server during HUP

# cat /var/log/amavisd.log | head -n 25
Feb 25 00:00:00 [server] newsyslog[39265]: logfile turned over
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: logging initialized, log level 4, logfile: /var/log/amavisd.log
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: sd_notify (no socket): STATUS=Config files have been read, modules loaded.
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: starting. (warm) /usr/local/sbin/amavisd at [server] amavisd-new-2.12.2 (20211013), Unicode aware
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: perl=5.032001, user=110, EUID: 110 (110);  group=, EGID: 110 110 (110 110)
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: warm restart on HUP [63629]: '/usr/local/sbin/amavisd', sockets: 10|*|/var/amavis/amavisd.sock|UNIX|*; 4|127.0.0.1|10024|TCP|ipv4; 6|::1|10024|TCP|ipv6; 7|127.0.0.1|10026|TCP|ipv4; 8|::1|10026|TCP|ipv6
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: INFO: no optional modules: utf8_heavy.pl unicore::lib::Nt::De.pl unicore::Heavy.pl Unix::Getrusage
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: INFO: SA version: 3.4.5, 3.004005, no optional modules: Razor2::Client::Agent Image::Info Image::Info::GIF Image::Info::JPEG Image::Info::PNG Image::Info::BMP Image::Info::TIFF
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: SpamControl: init_pre_chroot on SpamAssassin done
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: socket module IO::Socket::IP, protocol families available: INET, INET6
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: will bind to /var/amavis/amavisd.sock|unix, 127.0.0.1:10024/tcp, [::1]:10024/tcp, 127.0.0.1:10026/tcp, [::1]:10026/tcp
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: sd_notify (no socket): STATUS=Transferring control to Net::Server.
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: _WARN: Pid_file created by this same process. Doing nothing.
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: _WARN: Pid_file created by this same process. Doing nothing.
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: sd_notify (no socket): STATUS=Preparing to re-bind sockets.
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: Net::Server: 2022/02/25-00:00:06 Amavis (type Net::Server::PreForkSimple) starting! pid(63629)
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: sd_notify (no socket): STATUS=Warm restart, re-binding sockets.
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: Net::Server: Binding open file descriptors
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: Net::Server: Binding to UNIX socket file "/var/amavis/amavisd.sock"
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: Net::Server: Binding to TCP port 10024 on host ::1 with IPv6
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: Net::Server: Binding to TCP port 10026 on host 127.0.0.1 with IPv4
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: Net::Server: Binding to TCP port 10026 on host ::1 with IPv6
Feb 25 00:00:06 [server] /usr/local/sbin/amavisd[63629]: sd_notify (no socket): STATUS=Sockets bound, checking user and group.

No files in /var/amavis/tmp a few seconds after amavisd restart:

# ls -al /var/amavis/tmp
total 8
drwxr-x---  2 vscan  vscan  1024 Feb 25 00:00 .
drwxr-x---  6 vscan  vscan   512 Feb 24 00:00 ..

I suppose all this doesn't help much, and that's what's frustrating,
because on some days amavisd restarts fine without changing postfix
configuration.

-- 
Janos Dohanics