dnstap output not showing cache hits

[dmccombs]

• Program: dnsdist
• Issue type: Bug report

Short description

In testing the dnstap support in the recently merged PR #6170 from @zeha , I noticed that if dnsdist caching is enabled, no output is recorded for a query that hits cache.

Environment

• Operating system: Linux
• Software version: Git commit ad3e18738ccdc5d984dd3fc290a95c9fe3542fb2
• Software source: Compiled from source

Steps to reproduce

1. Enable dnsdist packet cache and dnstap output in your configuration

   pc = newPacketCache(1000, 30, 0)
   getPool(""):setCache(pc)

   rl = newFrameStreamUnixLogger("/var/run/dnsdist/dnstap.sock")
   addResponseAction(AllRule(), DnstapLogResponseAction("rdns", rl))

2. Watch output from dnstap with your preferred consumer - I use https://github.com/dnstap/golang-dnstap

   /usr/bin/dnstap -y -u /var/run/dnsdist/dnstap.sock -w /persist/dnsdist/dnstap.out

3. Query the same host multiple times to hit cache

   root@phendrana:/# dig @127.0.0.1 example.com +short
   93.184.216.34
   root@phendrana:/# dig @127.0.0.1 example.com +short
   93.184.216.34
   root@phendrana:/# dig @127.0.0.1 example.com +short
   93.184.216.34
   root@phendrana:/# dig @127.0.0.1 example.com +short
   93.184.216.34

   root@phendrana:/# dnsdist -e 'getPool(""):getCache():printStats()'
   Entries: 1/1000
   Hits: 3
   Misses: 1
   Deferred inserts: 0
   Deferred lookups: 0
   Lookup Collisions: 0
   Insert Collisions: 0
   TTL Too Shorts: 0

4. Observe that only the cache miss is shown in dnstap output.

   type: MESSAGE
   identity: "rdns"
   version: "dnsdist 0.0.HEAD.gad3e187.dirty"
   message:
   type: CLIENT_RESPONSE
   query_time: !!timestamp 2018-02-09 16:42:12.000070191
   response_time: !!timestamp 2018-02-09 16:42:12.00032351
   socket_family: INET
   socket_protocol: UDP
   query_address: 127.0.0.1
   response_address: 127.0.0.1
   query_port: 48110
   response_port: 53
   response_message: |
   ;; opcode: QUERY, status: NOERROR, id: 42416
   ;; flags: qr rd ra ad; QUERY: 1, ANSWER: 1, AUTHORITY: 2, ADDITIONAL: 1
   
   ;; QUESTION SECTION:
   ;example.com.       IN       A
   
   ;; ANSWER SECTION:
   example.com.        86400   IN      A       93.184.216.34
   
   ;; AUTHORITY SECTION:
   example.com.        86400   IN      NS      b.iana-servers.net.
   example.com.        86400   IN      NS      a.iana-servers.net.
   
   ;; ADDITIONAL SECTION:
   
   ;; OPT PSEUDOSECTION:
   ; EDNS: version 0; flags: ; udp: 1480
   ; SUBNET: 127.0.0.0/24/0
   ---

Expected behaviour

When using dnstap to log queries, I'd expect to see all queries rather than just cache misses.

Actual behaviour

Only queries that miss the cache are logged.

[pieterlexis]

You'll need to use addCacheHitResponseAction() with the same Rule and DnstapLogResponseAction(). dnsdist's has a separate hook for cache hit actions.

[dmccombs]

My mistake, thanks @pieterlexis.