Cache doesn't work as well as expected

[candrews]

Describe the bug

The cache doesn't appear to be working.

Scanning the same files twice in rapid succession results in cache negatives logged for the second scan, which shouldn't happen.

The time taken by the second scan is also not very much shorter than the first run, further indicating that the cache isn't being used.

How to reproduce the problem

I'm doing a simple test to see if the cache is working and it doesn't seem to do anything.

Please note that this issue was previously discussed in the mailing list in the thread archived at https://www.mail-archive.com/clamav-users@lists.clamav.net/msg49233.html

Per the default clamd.conf:

# This option allows you to disable the caching feature of the engine. By
# default, the engine will store an MD5 in a cache of any files that are
# not flagged as virus or that hit limits checks. Disabling the cache will
# have a negative performance impact on large scans.
# Default: no
#DisableCache yes

Therefore, I expect scanning the same files twice should result in the second scan immediately passing and the debug log saying that all files saying the cache check is positive.

I ran clamdscan --config-file=/etc/clamd.d/scan.conf --stdout --verbose --multiscan --allmatch . in a directory created by running git clone https://github.com/Cisco-Talos/clamav.git

Then, I ran the same command a second time.

Here's the clamd.log output created by the second time:
clamd-second-time.log

Note that there are many instances of negative cache checks, for example:

LibClamAV debug: cache_check: 6cefd05b85c11562eff41d8ec4484e67 is negative

and indications that the cache wasn't used:

LibClamAV debug: cli_magic_scan: returning 0  at line 4162 (no post, no cache)

Since the same files were scanned seconds apart, every file should be a cache hit.

$ clamconf -n
Checking configuration files in /etc

Config file: clamd.d/scan.conf
------------------------------
LogSyslog = "yes"
TCPSocket = "3310"
TCPAddr = "127.0.0.1"
Debug = "yes"
User = "clamscan"
MaxScanSize = "524288000"

freshclam.conf not found

mail/clamav-milter.conf not found

Software settings
-----------------
Version: 0.103.8
Optional features supported: MEMPOOL IPv6 AUTOIT_EA06 BZIP2 LIBXML2 PCRE2 ICONV JSON 

Database information
--------------------
Database directory: /var/lib/clamav
main.cvd: version 62, sigs: 6647427, built on Thu Sep 16 08:32:42 2021
daily.cld: version 26857, sigs: 2027569, built on Tue Mar 28 03:23:39 2023
bytecode.cvd: version 334, sigs: 91, built on Wed Feb 22 16:33:21 2023
Total number of signatures: 8675087

Platform information
--------------------
uname: Linux 6.2.7-200.fc37.x86_64 #1 SMP PREEMPT_DYNAMIC Fri Mar 17 16:16:00 UTC 2023 x86_64
OS: linux-gnu, ARCH: x86_64, CPU: x86_64
zlib version: 1.2.12 (1.2.12), compile flags: a9
platform id: 0x0a21818108000000020c0201

Build information
-----------------
GNU C: 12.2.1 20221121 (Red Hat 12.2.1-4) (12.2.1)
CPPFLAGS: -I/usr/include/libprelude
CFLAGS: -O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1  -m64  -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection  -D_LARGEFILE_SOURCE -D_LARGEFILE64_SOURCE -D_FILE_OFFSET_BITS=64
CXXFLAGS: -O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1  -m64  -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection
LDFLAGS: -Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -Wl,--build-id=sha1 -specs=/usr/lib/rpm/redhat/redhat-package-notes  -lprelude
Configure: '--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu' '--program-prefix=' '--disable-dependency-tracking' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--localstatedir=/var' '--sharedstatedir=/var/lib' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--enable-milter' '--disable-clamav' '--disable-static' '--disable-zlib-vcheck' '--disable-unrar' '--enable-id-check' '--enable-dns' '--with-dbdir=/var/lib/clamav' '--with-group=clamupdate' '--with-user=clamupdate' '--disable-rpath' '--disable-silent-rules' '--enable-clamdtop' '--enable-prelude' 'build_alias=x86_64-redhat-linux-gnu' 'host_alias=x86_64-redhat-linux-gnu' 'CXX=g++' 'CXXFLAGS=-O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1  -m64  -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection' 'LDFLAGS=-Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -Wl,--build-id=sha1 -specs=/usr/lib/rpm/redhat/redhat-package-notes' 'CC=gcc' 'CFLAGS=-O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1  -m64  -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection' 'LT_SYS_LIBRARY_PATH=/usr/lib64:' 'PKG_CONFIG_PATH=:/usr/lib64/pkgconfig:/usr/share/pkgconfig'
sizeof(void*) = 8
Engine flevel: 129, dconf: 129

[candrews]

The cache seems to have a size limit as it seems that items are being evicted from it.

If I can a small number of files twice, then the cache works as expected.

If I scan a large number of files twice, then all files are reported as being added to the cache in the first run (as expected), but in the second run, some of them are cache misses ("is negative" is logged).

• What is the size of the cache?
• Is there a way to tell how utilized the cache is? (I don't see this information in clamdtop nor do I see any source code that indicates the info is reported)
• Can logging be added when an item is evicted? I think this change would be made in cacheset_add which can found at

  clamav/libclamav/cache.c

  Line 372 in e4fe665

  static inline const char *cacheset_add(struct cache_set *cs, unsigned char *md5, size_t size, uint32_t recursion_level)

• Can the size of the cache be made configurable?

[candrews]

Discussion in Discord: https://discord.com/channels/636023333074370595/636023333074370597/1090748549165240441

[val-ms]

Fixed by #882