Clamav unofficial sigs cron

[AndrewSav]

Description

Note

TLDR: one of the test still failed even after my last round of making them less flaky and worked after re-run. That was caused by a race in our code around Clamav unofficial sigs integration. This also indicated a real issue: if cronjob executing these fails the failure goes to undeliverable email that no one sees. This PR is to fix these.

@diroots since you worked in ajacent area, do you mind having a look?

default.bats checks rspamd's counters after the fixtures: 9 messages scanned, 7 with action "no action". In the overlay's CI they once came out wrong (run 39000469943, attempt 2). The retry passed, and the inputs were identical to a passing run. The failure showed only status : 1, output : (empty), because the tests piped rspamc stat through grep, so the actual counts were lost.

The extra message is mail that cron sends itself. setup.sh installs the clamav-unofficial-sigs cron entry at a random minute, chosen afresh at each container start. The entry has no MAILTO and no output redirect. Whenever the job prints anything, cron mails it to clamav@<FQDN> through sendmail. non_smtpd_milters then hands that mail to rspamd, which counts it as one more message with "no action". Reproduced locally: a run whose counters read scanned 10 / no action 8 had, in rspamd's /history, one row beyond the fixtures: from clamav@mail.domain.tld, subject Cron <clamav@mail> [ -x /usr....

That run was on rspamd 4.1.5, so this is not new with 4.2.2. The expected rate is about one run in sixty: the window between rspamd starting and the counters being read is under a minute, so it crosses at most one minute boundary, and the cron minute matches it with probability 1/59.

Looking at what the job prints turned up two real faults, both described below: the hourly job cannot write its own state, and it cannot reload clamd.

• What is the current behavior (you can also link to an open issue here) ?

  The update at startup runs as root, while cron runs the hourly update as clamav. The hourly run cannot write the state files the startup run created. It cannot reload clamd either, because s6-svc -2 /services/clamd is root-only. It reports both failures only in its output, and cron mails that output to an address nobody reads, passing through rspamd on the way.

• What is the new behavior (if this is a feature change) ?

  Both updates run as clamav. clamd is reloaded through its socket, once it has finished starting. The hourly job's output goes to syslog: shell errors at mail.err, the script's own errors and alerts at mail.warning. Both appear in docker logs, and cron sends no mail. With DISABLE_CLAMAV=true the updater is not installed at all.

Run the clamav-unofficial-sigs update as clamav

rootfs/services/_parent/run runs the startup update as root. cron runs the hourly one as clamav, the script's default cron_user. The startup run leaves configs/*.txt owned by root, mode 0644, on the /var/mail volume. Every hourly run then fails to write current-dbs.txt, previous-dbs.txt and db-changes.txt, and prints a Permission denied line for each.

Once a source's update interval has passed, the hourly run also cannot record the new last-<source>-update.txt. The stored time never advances, so from then on that source is fetched on every hourly run instead of once per interval. Measured for Sanesecurity, whose interval is 2 h: with its stamp backdated, two consecutive cron runs both ran the Sanesecurity update, and the stamp stayed where it was. The other sources store their stamps the same way.

The reload had the same split. os.conf sets clamd_reload_opt="s6-svc -2 /services/clamd", and s6's control fifo is root-only. As clamav:

s6-svc: warning: unable to control /services/clamd: Permission denied

with exit code 111. The script only checks the reload's output for the word ERROR, so it treats this as a success. Since that setting arrived in #46, an hourly update can never have reloaded clamd.

Where clamd runs, the effect is a delay rather than signatures never being loaded. clamd's SelfCheck re-reads changed databases on its own. With SelfCheck shortened to 20 s, touching one database file was picked up at the next check:

SelfCheck: Database modification detected. Forcing reload.
Reading databases from /var/lib/clamav
Database correctly reloaded (3834176 signatures)

This image sets SelfCheck 3600, so new signatures from the hourly update arrive up to an hour late instead of straight away.

The changes:

• The startup update runs through s6-setuidgid clamav, the same way encryption.sh drops to zeyple.
• clamd_reload_opt="clamdscan --reload", the default in the script's own master.conf, which upstream's Debian config does not override either. It talks to clamd's LocalSocket (mode 666), so it works as clamav. A failed reload now prints ERROR and triggers the script's fallback, kill -USR2 on clamd's pid, which also works as clamav because clamd runs as clamav (except while clamd is starting, see below).
• clamdscan was not installed, so the Dockerfile adds it. It is one package (59 KB download, 222 KB installed), and its dependencies (clamav-base, libclamav12) are already in the image.
• setup.sh re-owns the updater's state for clamav, so volumes that already hold root-owned files keep working. user.conf is the administrator's file and keeps its owner.
• fixtures_default now waits for the startup update to finish. It used to check the update's pid file about 0.1 s after docker run, before the update had started, so it never actually waited.

Log the clamav-unofficial-sigs cron output instead of mailing it

cron mails a job's output to the job's user. Here that is clamav, which postfix completes to clamav@<FQDN> (myorigin). The FQDN is not in mydestination and normally is not one of the virtual domains, so postfix tries to relay the mail. In the test container that fails, and the bounce is dropped:

postfix/smtp: 8720D68F2A: to=<clamav@mail.domain.tld>, orig_to=<clamav>, relay=none, dsn=5.4.4,
              status=bounced (Host or domain name not found ... name=mail.domain.tld ...)
postfix/smtp: 2A30969036: to=<clamav@mail.domain.tld>, relay=none, dsn=5.4.4, status=bounced (...)

With no terminal, which is how cron runs it, the script silences its progress messages but still prints its errors and alerts, and the shell's own errors appear on stderr. Observed causes of output:

• Permission denied lines on every hourly run, from the previous section.
• ERROR: Only one instance can run at the same time. when cron's minute comes round while the startup update still holds the pid file. The script prints this and exits immediately, so the mail goes out at once. This is the trigger that fits CI's window.
• Two ALERTs about a newer clamav-unofficial-sigs (v8.0.0, config v100), from the script's version check every 12 hours.

The cron entry now runs /usr/local/bin/clamav-unofficial-sigs-cron.sh, set through the script's own cron_script_full_path option, so --install-cron still generates the file. The wrapper:

• sends the script's stderr to logger -p mail.err and its stdout to logger -p mail.warning, tagged clamav-unofficial-sigs. rsyslog already copies mail.* to docker logs and mail.log, warnings to mail.warn and errors to mail.err, which are the places the README sends people to.
• drops the lines of =/*/-/+ the script frames its messages with.
• skips the run with a mail.info line when another update is already running. The startup update and the hourly one are independent, so that overlap is expected and should not read as an error. It would otherwise put : ERROR: into mail.log, which the log test checks for.

Expected volume, measured with the first section applied: an hour with nothing due prints nothing, and an hour with every source due prints nothing either. The version check prints the two ALERTs (two lines once framing is dropped) every 12 hours, for as long as the bundled script is outdated. mail.err stays empty unless something is actually broken.

What still does not surface are the script's WARNINGs, which it silences under cron. Two of them fail every time their source is due and remain only in its own log, /var/log/clamav-unofficial-sigs/clamav-unofficial-sigs.log: urlhaus.ndb never updates, and Yara's bank_rule.yar returns 404 upstream. Both concern the bundled script's version.

Skip the clamav-unofficial-sigs updater when ClamAV is disabled

With DISABLE_CLAMAV=true, _parent/run already skips the startup update, but setup.sh still installed the hourly cron entry whenever a sigs user.conf existed. The ldap2 suite runs exactly this configuration. Measured with it:

• On master, every hourly run printed ERROR: working directory (work_dir) not writable /var/lib/clamav-unofficial-sigs and downloaded nothing. Without the root startup run, nothing hands the work directory to clamav. cron mailed that error every hour.
• With the earlier commits alone, the updater worked: it downloaded about 70 signature files for a clamd that was not running. Then, whenever it found updates, it failed to reload, and correctly logged that it had. clamdscan could not reach the socket, there was no pid file for the kill -USR2 fallback, and the restart fallback's s6-svc is root-only.

There is nothing for the updater to do without ClamAV, so setup.sh now skips it entirely and says so at startup ([INFO] clamav-unofficial-sigs is disabled (ClamAV is disabled)).

Wait for clamd to finish starting before reloading it

Found while testing the 8.0.0 upgrade (#93), and older than this PR. _parent/run starts freshclam, which starts clamd, and runs the startup update at the same time. The update can finish while clamd is still loading its databases, and then neither way of reloading works:

• clamdscan --reload fails, because clamd creates its socket only after loading and compiling the databases: ERROR: Could not connect to clamd on LocalSocket /var/run/clamav/clamd.ctl: No such file or directory, exit 2. (clamd/server-th.c line 1517). While it loads, /proc/<pid>/status shows SIGUSR2 in SigIgn.

The script then logs ClamAV databases reloading, though nothing reloaded. Master loses the same reload, silently: its s6-svc -2 sends the same SIGUSR2 and prints nothing. Reproduced on master: clamd kept 3801371 signatures until reloaded by hand, then had 3834389.

SelfCheck does not make up for it. clamd records the state it compares against after its initial load (clamd.c line 679), so a database installed while that load was reading the directory is never flagged as changed. Shown with a marker database installed during the load and SelfCheck set to 30 s: three checks in a row reported Database status OK, and the marker was only detected after a reload. Such a database waits for the next freshclam update or the next hourly update that installs something.

It needs a TTY. Without one the script sleeps 60–600 s before downloading, so clamd has long finished starting. The suites run with -t, and the reload was lost in 2 of the 4 fresh starts inspected. The sample docker-compose file sets no TTY. Outside startup, a reload that arrives while clamd is already reloading is merged into it, but there the next SelfCheck does catch whatever that reload missed, so that case is left alone.

clamd_reload_opt now runs clamav-unofficial-sigs-reload.sh, which waits for clamd to answer (clamdscan --ping, up to 300 s) and then runs clamdscan --reload. It does this for every reload, so it also covers an hourly update that coincides with clamd restarting, which is the same window as startup. The wait is silent: each failed ping prints an ERROR, which the script would take for a failed reload. --wait and --ping have no effect combined with --reload itself, so it has to be a separate step.

Show the full rspamd stats when a counter test fails

The counter tests used rspamc stat | grep -i '...'. A wrong count and a failing rspamc looked the same in the output, output : (empty), because rspamc prints its errors to stdout and grep swallowed them. They now use assert_output --partial, which prints the whole rspamc stat output on failure.

Remove the test containers' volumes with them

mysql:8, postgres and redis keep their data in anonymous volumes. The init targets remove the previous container with docker rm -f, which leaves its volume behind, so every suite run leaked one database's data. While working on this, repeated local runs left dozens of these behind and, together with the image builds, filled a 38 GB disk. All removals now use docker rm -fv, which removes a container's own anonymous volumes and never bind mounts or named volumes. make clean is untouched.

Not in this PR

The bundled clamav-unofficial-sigs is 7.2.5, released 2021-03-20. 8.0.0, released 2026-07-02, is the only release since. According to its release notes it fixes urlhaus (a missing work directory and a cleanup pass that deleted urlhaus.ndb after every install) and removes bank_rule.yar. Upgrading means a new script and a config migration, so it is better done separately. The reload change here is still needed with 8.0.0: its new socket fallback runs only when the reload output contains ERROR (line 1413), the same check as 7.2.5, and the s6-svc failure prints no ERROR.

Type of change

• Bug fix (non-breaking change which fixes an issue)
• Test (adding missing tests or correcting existing ones)

Status

• Ready

Todo List

• Implementation
• Tests
• Documentation

How has this been tested ?

The full bats suite, one suite at a time and not as root: git submodule update --init --recursive, make build, then make default, make reverse TEST_DNS=9.9.9.9, make ldap, make ldap2 TEST_DNS=9.9.9.9, make sieve, make ecdsa, make traefik_acmev1, make traefik_acmev2, make traefik_v3.

• default — 134 tests (128 + 6 new)
• reverse — 81 tests
• ldap — 66 tests
• ldap2 — 30 tests (29 + 1 new)
• sieve — 2 tests
• ecdsa — 4 tests
• traefik_acmev1 — 11 tests
• traefik_acmev2 — 12 tests
• traefik_v3 — 9 tests

349 tests, 0 failures, on the overlay this branch builds on (rspamd 4.1.5). default also passed twice, 133/133, on an overlay built with rspamd 4.2.2 (AndrewSav/debian-mail-overlay f828c42). That was before the last two commitx, which only changes the DISABLE_CLAMAV=true case. The second commit, which changes who runs the update but not yet where its output goes, was built and tested on its own as well: default 130/130.

Repeated clean runs cannot show the flake is gone, because before this change about sixty runs in a row would pass on average. The six new tests in default.bats run the cron job on purpose instead, exactly as its cron file says, as its cron user and with no terminal:

• cron job runs cleanly as its cron user: prints nothing and leaves nothing in mail.err. On master it prints the three Permission denied lines.
• cron user can reload clamd: the configured reload, run as the cron user, makes clamd log Database correctly reloaded. On master: Permission denied, exit 111.
• cron job is quiet while another update runs: with the update lock held, it prints nothing and logs no error. On master it prints the Only one instance ERROR and exits 1.
• cron job stderr goes to mail.err: with a state file made unwritable, the Permission denied lands in mail.err and nothing is printed. On master it is printed, which means mailed.
• cron job stdout goes to mail.warning: with the log file made unwritable, the script's Logging Disabled warning lands in mail.warn and not in mail.err. On master it is printed.
• cron user's reload waits for clamd to start: clamd is restarted, and the configured reload is run as the cron user while clamd is still loading. It must succeed, print no ERROR, and be followed by Database correctly reloaded. Before the last commit: ERROR: Could not connect to clamd on LocalSocket /var/run/clamav/clamd.ctl: No such file or directory, exit 2.

The last two deliberately break the job, so they run after the log tests and do not disturb them.

ldap2.bats gains one test, no cron task when ClamAV is disabled: the suite mounts a sigs user.conf with DISABLE_CLAMAV=true, and the cron file must not exist. On master it exists.