Cache entries fail to be removed from Redis `cachedb` backend with `unbound-control flush* +c`

[gjherbiet]

Describe the bug
When calling unbound-control flush* +c to remove cache entries from both the first-level cache and the cachedb second-level cache, the operation fails:

info: cachedb msg remove example.com A IN
debug: redis_store 9AB54C417C77A0529023C6E81D124446753F76329B01977285F8AB0D1223440E (4 bytes) with ttl 0
error: redis: set resulted in an error: ERR invalid expire time in setex
debug: redis_store set completed

To reproduce
Steps to reproduce the behavior with Redis cachedb backend enabled:

1. Query for a ressource record:
   % dig @127.0.0.1 example.com A
2. Observe Redis key being created with proper TTL in the logs:
   debug: redis_store 9AB54C417C77A0529023C6E81D124446753F76329B01977285F8AB0D1223440E (259 bytes) with ttl 300
3. Flush record from both cache levels:
   % unbound-control flush_type +c example.com A
4. Observe the error from the logs:

debug: redis_store 9AB54C417C77A0529023C6E81D124446753F76329B01977285F8AB0D1223440E (4 bytes) with ttl 0
error: redis: set resulted in an error: ERR invalid expire time in setex

5. Query for the same ressource record:
   % dig @127.0.0.1 example.com A
6. Observe the key still exists from the logs:

debug: redis_lookup of 9AB54C417C77A0529023C6E81D124446753F76329B01977285F8AB0D1223440E
debug: redis_lookup found 259 bytes

7. Additionally, observe the key still exists in Redis with a non-null TTL:

% redis-cli GET 9AB54C417C77A0529023C6E81D124446753F76329B01977285F8AB0D1223440E
"\x00\x00\x81\x80\x00\x01\x00\a\x00\x00\x00\x01\aexample\x03com\x00\x00\x01\x00\x01\xc0\x0c\x00\x01\x00\x01\x00\x00\x01,\x00\x04\x17\xd7\x00\x8a\xc0\x0c\x00\x01\x00\x01\x00\x00\x01,\x00\x04`\a\x80\xaf\xc0\x0c\x00\x01\x00\x01\x00\x00\x01,\x00\x04`\a\x80\xc6\xc0\x0c\x00\x01\x00\x01\x00\x00\x01,\x00\x04\x17\xc0\xe4P\xc0\x0c\x00\x01\x00\x01\x00\x00\x01,\x00\x04\x17\xc0\xe4T\xc0\x0c\x00\x01\x00\x01\x00\x00\x01,\x00\x04\x17\xd7\x00\x88\xc0\x0c\x00.\x00\x01\x00\x00\x01,\x00_\x00\x01\r\x02\x00\x00\x01,g\xf2\x1c|g\xd6\xc2\xc5<\x88\aexample\x03com\x00\xc82{6\xff\x8c\n\xd0\x8b\xbe\x86\xcf E WG\xbc\x81\r\xff\x8fLK\xe6\x15\xc2\xf9r\x17\xbf\xad\xe0\xf8\"\xa9\xb5K\x99\xd6\xb5\x14E\x93\xdc\x96\x89\xd2\xcae\x7f\x9d\x0bO\xcd<\xa8J(\x01C\b\x14\xf7\x00\x00)\x04\xd0\x00\x00\x80\x00\x00\x00\x00\x00\x00\x00g\xddD\xdf\x00\x00\x00\x00g\xddF\x0b"
% redis-cli TTL 9AB54C417C77A0529023C6E81D124446753F76329B01977285F8AB0D1223440E
(integer) 244

Expected behavior
After executing step 3. the key(s) shall no longer exist in the Redis database.

System:

• Unbound version: 1.22.0
• OS: Debian 12
• Redis 7.2.7 / KeyDB 6.3.4
• unbound -V output:

Version 1.22.0

Configure line: --build=x86_64-linux-gnu --prefix=/usr --includedir=${prefix}/include --mandir=${prefix}/share/man --infodir=${prefix}/share/info --sysconfdir=/etc --localstatedir=/var --disable-option-checking --disable-silent-rules --libdir=${prefix}/lib/x86_64-linux-gnu --runstatedir=/run --disable-maintainer-mode --disable-dependency-tracking --with-pythonmodule --with-pyunbound --enable-subnet --enable-dnstap --enable-systemd --enable-cachedb --with-libhiredis --with-libnghttp2 --with-chroot-dir= --with-dnstap-socket-path=/run/dnstap.sock --disable-rpath --with-pidfile=/run/unbound.pid --with-libevent --enable-tfo-client --with-rootkey-file=/usr/share/dns/root.key --enable-tfo-server
Linked libs: libevent 2.1.12-stable (it uses epoll), OpenSSL 3.0.15 3 Sep 2024
Linked modules: dns64 python cachedb subnetcache respip validator iterator
TCP Fastopen feature available

BSD licensed, see LICENSE in source package for details.
Report bugs to unbound-bugs@nlnetlabs.nl or https://github.com/NLnetLabs/unbound/issues

Additional information

The issue comes from the fact that the following commands are refused by Redis:

> SETEX mykey 0 "value"
(error) ERR invalid expire time in 'setex' command
> SET mykey "value" EX 0
(error) ERR invalid expire time in 'set' command

However using the EXPIRE command works:

> EXPIRE mykey 0
(integer) 1
> GET mykey
(nil)

To fix this either:

• 1 can be passed instead of 0 in cachedb_msg_remove_qinfo on cachedb/cachedb.c:1034: key(s) will then expire in the next second
• additional logic can be added to cachedb/redis.c:373 so that, when ttl==0, the EXPIRE command is invoked instead of SET/SETEX.

As the fix is specific to the Redis backend and may have less side effects, the second option is preferable.

Note that SETEX is deprecated and shall be replaced by SET key value EX seconds).

This issue occurred with both Redis 7.2.7 and KeyDB 6.3.4 backends for the cachedb module.

[wcawijngaards]

The commit implements the EXPIRE command when the ttl==0. It also moves to use the SET key value EX seconds instead of SETEX, and thus needs redis >= 2.6.2. It no longer uses the deprecated SETEX command. This implements the fixes, but it has not been tested, hopefully it works, since it has the new commands. If you want, the change can be tried out using the source from the code repository, or by applying the change commit to the source.

[gjherbiet]

I will test the changes and let you know. Thanks.

[gjherbiet]

The fix does work in the sense that the entries are properly removed from the Redis database, however the logs are still showing an error message:

info: cachedb msg remove example.com. A IN
debug: redis_store expire 9AB54C417C77A0529023C6E81D124446753F76329B01977285F8AB0D1223440E (4 bytes)
debug: redis_store set completed
error: redis_store: unexpected type of reply (3)

This is probably due to the EXPIRE command replying with an integer value of 1:

> EXPIRE mykey 0
(integer) 1

So the test case in cachedb/redis.c:396 should be elaborated a bit to cover this case.

[wcawijngaards]

That makes sense, I have adjusted the code to expect the integer reply for the EXPIRE command. That should remove the error message, and the functionality should be unchanged.