Freshclam 0.103.11 hangs indefinitely when downloading custom signatures

[giosh94mhz]

Description

From time to time I found that signatures updates are "stale" but freshclam service is correctly running. Digging into the issue I discovered that freshclam is polling the same file for more than a week, so some timeout/failover should be implemented.

Version

ClamAV 0.103.11/27080/Thu Nov 2 07:40:15 2023

(after manual fix: ClamAV 0.103.11/27089/Fri Nov 10 08:39:24 2023 )

Logs and data

From the clamav-freshclam logs I see the following:

$ systemctl status --lines 2 clamav-freshclam
● clamav-freshclam.service - ClamAV virus database updater
   Loaded: loaded (/usr/lib/systemd/system/clamav-freshclam.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2023-10-27 00:33:41 BST; 2 weeks 0 days ago
     Docs: man:freshclam(1)
           man:freshclam.conf(5)
           https://docs.clamav.net/
 Main PID: 2310152 (freshclam)
    Tasks: 1 (limit: 24511)
   Memory: 1.3M
   CGroup: /system.slice/clamav-freshclam.service
           └─2310152 /usr/bin/freshclam -d --foreground=true

nov 02 13:24:09 my.server.test freshclam[2310152]: bytecode.cld database is up-to-date (version: 334, sigs: 91, f-level: 90, builder: anvilleg)
nov 02 13:24:09 my.server.test freshclam[2310152]: badmacro.ndb is up-to-date (version: custom database)

...but today is the 10th November, so nothing happened in more than a week.

Those custom database are from the well-known public DBs, mirrored from my server. The issue happens -- if I inspected well my code -- when the server updates the files.

On the repository server, these are the last access logs:

192.168.1.2 custom.repo.test - 276 [02/Nov/2023:14:24:09 +0100] "GET /esg/cvd-extra/badmacro.ndb HTTP/1.1" 304 - "-" "ClamAV/0.103.11 (OS: linux-gnu, ARCH: x86_64, CPU: x86_64, UUID: edited)"
192.168.1.2 custom.repo.test - 78644550 [02/Nov/2023:14:24:09 +0100] "GET /esg/cvd-extra/blurl.ndb HTTP/1.1" 200 298908 "-" "ClamAV/0.103.11 (OS: linux-gnu, ARCH: x86_64, CPU: x86_64, UUID: edited)"

...as you can see, after the logged badmacro.ndb should have theoretically downloaded blurl.ndb but no log to journald.

Now, inspecting the freshclam /proc status I found that the process is blocked polling the same file since 7 days.

$ ls -la  /proc/2310152/fd/3 
l-wx------. 1 root root 64 10 nov 08.52 /proc/2310152/fd/3 -> /var/lib/clamav/tmp.9e2ad7b756/clamav-29510508be95e9cfcc4a5faafea5b34f.tmp

$ stat /var/lib/clamav/tmp.9e2ad7b756/clamav-29510508be95e9cfcc4a5faafea5b34f.tmp 
  File: /var/lib/clamav/tmp.9e2ad7b756/clamav-29510508be95e9cfcc4a5faafea5b34f.tmp
  Size: 32768           Blocks: 64         IO Block: 4096   regular file
Device: fb00h/64256d    Inode: 265472      Links: 1
Access: (0644/-rw-r--r--)  Uid: (  994/clamupdate)   Gid: (  991/clamupdate)
Context: system_u:object_r:antivirus_db_t:s0
Access: 2023-11-02 13:24:09.260266285 +0000
Modify: 2023-11-02 13:24:52.463170880 +0000
Change: 2023-11-02 13:24:52.463170880 +0000
 Birth: 2023-11-02 13:24:09.260266285 +0000

Finally, running strace on the process itself, I see it's stuck in an infinite polling:

$ strace -p 2310152 
strace: Process 2310152 attached
restart_syscall(<... resuming interrupted read ...>) = 0
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7feb72100d40}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7feb72100d40}, NULL, 8) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7feb72100d40}, NULL, 8) = 0
poll([{fd=4, events=POLLIN}], 1, 1000)  = 0 (Timeout)
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7feb72100d40}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7feb72100d40}, NULL, 8) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7feb72100d40}, NULL, 8) = 0
poll([{fd=4, events=POLLIN}], 1, 1000)  = 0 (Timeout)
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7feb72100d40}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7feb72100d40}, NULL, 8) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7feb72100d40}, NULL, 8) = 0
poll([{fd=4, events=POLLIN}], 1, 1000^Cstrace: Process 2310152 detached
 <detached ...>

How to reproduce the problem

Not quite sure how to reproduce reliably, but maybe defining a DatabaseCustomURL https://custom.repo.tesy/cvd-extra/file.ndb and changing it while downloading should trigger the issue.

Quick fix for the issue

Reloading the deamon restore normal downloads, but since it's not reliable I'm forced to create a watchdog script to avoid this issue for now.