amavisd clean shutdown and restart

[Janos Dohanics]

Hello,

I have a FreeBSD 12.3-STABLE r371667 server.

I have this entry in /etc/newsyslog.conf to rotate amavisd logs:

/var/log/amavisd.log  vscan:vscan  644  30  *  @T00  JC  /var/amavis/amavisd.pid

However, amavisd does not start reliably after log rotation. Some days
amavisd does restart as expected, but more often than not monit(1)
needs to restart amavisd.

Here is the log file with failed startup:

Feb 24 00:00:00 [server] newsyslog[63582]: logfile turned over
Feb 24 00:00:04 [server] /usr/local/sbin/amavisd[86845]: Net::Server: Received a SIG HUP
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[86845]: sd_notify (no socket): STOPPING=1\nSTATUS=Server rundown, notifying child processes.
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[86845]: Net::Server: 2022/02/24-00:00:05 Server closing!
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[86845]: Net::Server: Sending children hup signal
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97918]: (97918-03) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97840]: (97840-04) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97912]: (97912-03) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97873]: (97873-03) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97837]: (97837-04) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97839]: (97839-04) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97791]: (97791-05) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97824]: (97824-04) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97842]: (97842-04) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97852]: (97852-04) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97860]: (97860-03) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97853]: (97853-04) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97960]: (97960-02) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97857]: (97857-03) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97816]: (97816-05) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97838]: (97838-04) SA rundown_child (0)
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97842]: (97842-04) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220223T235044-97842-29XbXCbQ
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97857]: (97857-03) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20220223T235319-97857-Mo9niBLX
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97842]: (97842-04) rmdir_recursively: /var/amavis/tmp/amavis-20220223T235044-97842-29XbXCbQ, excl=
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97857]: (97857-03) rmdir_recursively: /var/amavis/tmp/amavis-20220223T235319-97857-Mo9niBLX, excl=
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97842]: (97842-04) rmdir_recursively: /var/amavis/tmp/amavis-20220223T235044-97842-29XbXCbQ/parts, excl=
Feb 24 00:00:05 [server] /usr/local/sbin/amavisd[97857]: (97857-03) rmdir_recursively: /var/amavis/tmp/amavis-20220223T235319-97857-Mo9niBLX/parts, excl=
...
Nothing until monit(1) starts amavisd a minute later
...
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: logging initialized, log level 4, logfile: /var/log/amavisd.log
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: sd_notify (no socket): STATUS=Config files have been read, modules loaded.
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: Valid PID file /var/amavis/amavisd.pid (younger than sys uptime 1 22:13:49)
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: No such process [86845], supposedly the current amavisd master process
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: starting. /usr/local/sbin/amavisd at [server] amavisd-new-2.12.2 (20211013), Unicode aware
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: perl=5.032001, user=, EUID: 110 (110);  group=, EGID: 110 110 (110 110)
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: INFO: no optional modules: utf8_heavy.pl unicore::lib::Nt::De.pl unicore::Heavy.pl Unix::Getrusage
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: 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 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: SpamControl: init_pre_chroot on SpamAssassin done
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: socket module IO::Socket::IP, protocol families available: INET, INET6
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: 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 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: sd_notify (no socket): STATUS=Transferring control to Net::Server.
Feb 24 00:00:59 [server] /usr/local/sbin/amavisd[63625]: _WARN: Pid_file "/var/amavis/amavisd.pid" already exists.  Overwriting!

During normal startup, there is a log entry like this:

Feb 20 00:00:04 [server] /usr/local/sbin/amavisd[58849]: (!)Net::Server: 2022/02/20-00:00:04 Re-exec server during HUP

Would you please give me an explanation and suggest a remedy? Why on
some days does amavisd restart normally but not on other days?

A while ago I posted this question on the FreeBSD list but got no
replies.

-- 
Janos Dohanics