On Sun, Jun 22, 2025 at 06:17:17PM +0200, Vincent Lefevre wrote: > Note that the /var/log/apt/term.log file here just contains > > Log started: 2025-06-21 13:25:21 > [...] > Setting up sa-compile (4.0.1-4) ... > Running sa-compile (may take a long time) > Warning: The unit file, source configuration file or drop-ins of > spamd.service changed on disk. Run 'systemctl daemon-reload' to reload units. > Setting up spamd (4.0.1-4) ... > Processing triggers for man-db (2.13.1-1) ... > Log ended: 2025-06-21 13:25:54
The issue here turns out to be in the sa-compile postinst. It invokes sa-compile and may also run `invoke-rc.d spamd reload`. This would trigger the warning about changed spamd.service, because although the content is identical, the file has actually been replaced as part of the upgrade process. This can be resolved by calling `systemctl daemon-reload` in the sa-compile postinst, as in https://salsa.debian.org/noahm/spamassassin/-/commit/c8204d9bb1a443d936e94fdbbcd52f679d89df55 However, this seems unrelated. Even after reloading the systemd configuration, systemd still ends up deciding to SIGKILL the spamd processes. > Why is there an error *after* it is killed by SIGTERM? > > There might be a race condition, which could explain why this is not > always visible. I agree that there may be a race condition. With further testing, I've encountered logs containing a regexp compilation failure, but it was with a different rule than what you originally reported. I suspect that this is caused by the process being interrupted at a different time. (Note that the logs below are truncated, because otherwise the "replacetags: regexp compilation failed" line is 161111 bytes long.) Jun 22 16:16:29 satest-trixie systemd[1]: Reloading spamd.service - Perl-based spam filter using text analysis... Jun 22 16:16:29 satest-trixie spamd[5088]: spamd: server hit by SIGHUP, restarting Jun 22 16:16:29 satest-trixie systemd[1]: Reloaded spamd.service - Perl-based spam filter using text analysis. Jun 22 16:16:29 satest-trixie spamd[5088]: spamd: child [5096] killed successfully: interrupted, signal 2 (0002) Jun 22 16:16:29 satest-trixie spamd[5088]: spamd: child [5097] killed successfully: interrupted, signal 2 (0002) Jun 22 16:16:29 satest-trixie spamd[5088]: spamd: server socket closed, type IO::Socket::IP Jun 22 16:16:29 satest-trixie spamd[5088]: spamd: server socket closed, type IO::Socket::IP Jun 22 16:16:29 satest-trixie spamd[5088]: spamd: restarting using '/usr/bin/perl -T -w -I /etc/perl -I /usr/lib/x86_64-linu> Jun 22 16:16:30 satest-trixie systemd[1]: Stopping spamd.service - Perl-based spam filter using text analysis... Jun 22 16:16:30 satest-trixie spamd[5088]: spamd: server killed by SIGTERM, shutting down Jun 22 16:16:30 satest-trixie spamd[5088]: replacetags: regexp compilation failed for __PAY_ME: '(?aa)(?i)(?:^|\\s)(?:(?:[pP> Jun 22 16:16:31 satest-trixie spamd[5088]: zoom: able to use 399/399 'body_0' compiled rules (100%) Jun 22 16:16:32 satest-trixie spamd[5088]: spamd: server started on IO::Socket::IP [::1]:783, IO::Socket::IP [127.0.0.1]:783> Jun 22 16:16:32 satest-trixie spamd[5088]: spamd: server pid: 5088 Jun 22 16:16:32 satest-trixie spamd[5088]: spamd: server successfully spawned child process, pid 6319 Jun 22 16:16:32 satest-trixie spamd[5088]: spamd: server successfully spawned child process, pid 6320 Jun 22 16:16:32 satest-trixie spamd[5088]: prefork: child states: II Jun 22 16:18:00 satest-trixie systemd[1]: spamd.service: State 'stop-sigterm' timed out. Killing. Jun 22 16:18:00 satest-trixie systemd[1]: spamd.service: Killing process 5088 (perl) with signal SIGKILL. Jun 22 16:18:00 satest-trixie systemd[1]: spamd.service: Killing process 6319 (spamd child) with signal SIGKILL. Jun 22 16:18:00 satest-trixie systemd[1]: spamd.service: Killing process 6320 (spamd child) with signal SIGKILL. Jun 22 16:18:00 satest-trixie systemd[1]: spamd.service: Main process exited, code=killed, status=9/KILL Jun 22 16:18:00 satest-trixie systemd[1]: spamd.service: Failed with result 'timeout'. Jun 22 16:18:00 satest-trixie systemd[1]: Stopped spamd.service - Perl-based spam filter using text analysis. Jun 22 16:18:00 satest-trixie systemd[1]: spamd.service: Consumed 3.887s CPU time, 139.3M memory peak. Jun 22 16:18:00 satest-trixie systemd[1]: Started spamd.service - Perl-based spam filter using text analysis. > Also, I don't understand the "spamd: server started on..." why the > goal is to kill it (for the upgrade?) as seen at > > Jun 21 13:25:30 qaa systemd[1]: Stopping spamd.service - Perl-based spam > filter using text analysis... > > and > > Jun 21 13:25:50 qaa systemd[1]: spamd.service: State 'stop-sigterm' timed > out. Killing. > > No issues with "systemctl start spamassassin-maintenance.service". > But the upgrade case may be different. It seems likely that the sa-comple postinst and spamd postinst are racing with each other here. I'm really surprised that this hasn't come up before... noah
