Inconsistent RPZ handling for A record returned along with CNAME

[imjosi]

Describe the bug
Inconsistent RPZ handling for CNAME records in Unbound 1.17 - RPZ is applied to A record returned along with CNAME only for first request, but not for next requests for the same record until it expires from cache. None of these requests are logged in the RPZ log.

Records in source domain:

test.dev.        60      IN      A       10.10.10.10
blockme.test.dev. 30      IN      CNAME   test.dev.

RPZ file dev.rpz:

test.dev.rpz.   120     IN      A       10.99.99.99

Unbound configuration:

server:
        module-config: "respip validator iterator"
        logfile: "/var/log/unbound/unbound.log"
        log-time-ascii: yes
        log-queries: yes
        log-replies: yes

rpz:
        name: "rpz"
        zonefile: "dev.rpz"
        rpz-log: yes
        rpz-log-name: "rpz"

To reproduce
Steps to reproduce the behavior:

1. Check if test.dev record is blocked - got correct response with RPZ IP and corresponding logfile entry

$ dig test.dev
;; ANSWER SECTION:
test.dev.               120     IN      A       10.99.99.99

Unbound log:

Oct 17 16:12:16 unbound[2190287:0] info: 127.0.0.1 test.dev. A IN
Oct 17 16:12:16 unbound[2190287:0] info: rpz: applied [rpz] test.dev. rpz-local-data 127.0.0.1@53017 test.dev. A IN
Oct 17 16:12:16 unbound[2190287:0] info: 127.0.0.1 test.dev. A IN NOERROR 0.000000 1 53

2. Check if blockme.test.dev is blocked - got correct response with RPZ IP but no entry in logfile

$ dig blockme.test.dev
;; ANSWER SECTION:
blockme.test.dev.       30      IN      CNAME   test.dev.
test.dev.               120     IN      A       10.99.99.99

Unbound log:

Oct 17 16:17:56 unbound[2190287:0] info: 127.0.0.1 blockme.test.dev. A IN
Oct 17 16:17:56 unbound[2190287:0] info: 127.0.0.1 blockme.test.dev. A IN NOERROR 0.000539 0 75

3. After few seconds check again if blockme.test.dev is blocked - got incorrect response with source domain IP and TTL and no entry in logfile

$ dig blockme.test.dev
;; ANSWER SECTION:
blockme.test.dev.       27      IN      CNAME   test.dev.
test.dev.               60      IN      A       10.10.10.10

Unbound log:

Oct 17 16:17:59 unbound[2190287:0] info: 127.0.0.1 blockme.test.dev. A IN
Oct 17 16:17:59 unbound[2190287:0] info: 127.0.0.1 blockme.test.dev. A IN NOERROR 0.000308 0 75

Expected behavior
RPZ must be always applied to A records returned along with CNAME and it must be logged.

System:

• Unbound version: 1.17.1-2+deb12u1
• OS: Debian GNU/Linux 12 (bookworm)
• unbound -V output:

Version 1.17.1

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 --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.11 19 Sep 2023
Linked modules: dns64 python subnetcache respip validator iterator
TCP Fastopen feature available

[wcawijngaards]

The fix makes it check for rpz qname actions after a CNAME is picked up from cache. Also, the rpz action is logged for actions after a CNAME, and after a CNAME from cache. That fixes the issue, in the test script.

Thank you for the detailed report! The fix commit is in the code repository.

[imjosi]

Thanks, I can confirm that this issue is fixed. I backported this fix to Debian 1.17.1 version and it worked there too.