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
