dnstap showing extra responses

[fhriley]

I'm seeing extra responses in the dnstap stream from unbound 1.13.0. I'm not sure if this is unbound actually generating extra responses or the dnstap stream duplicating the responses. Here is an example (decoded using https://github.com/dnstap/golang-dnstap/tree/master/dnstap) that I extracted from my dnstap logs. Note the extra client response. The timestamps also look strange. The timestamp of the client response is before the timestamp of the forwarder response.

message:
  type: CLIENT_QUERY
  query_time: !!timestamp 2020-12-09 23:15:19.20792
  socket_family: INET
  socket_protocol: UDP
  query_address: 192.168.1.221
  query_port: 54582
  query_message: |
    ;; opcode: QUERY, status: NOERROR, id: 2
    ;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
    
    ;; QUESTION SECTION:
    ;pubsub.pubnub.com.	IN	 A
---
type: MESSAGE
message:
  type: CLIENT_RESPONSE
  response_time: !!timestamp 2020-12-09 23:15:19.208216
  socket_family: INET
  socket_protocol: UDP
  query_address: 192.168.1.221
  query_port: 54582
  response_message: |
    ;; opcode: QUERY, status: NOERROR, id: 2
    ;; flags: qr rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0
    
    ;; QUESTION SECTION:
    ;pubsub.pubnub.com.	IN	 A
    
    ;; ANSWER SECTION:
    pubsub.pubnub.com.	18	IN	A	54.241.191.232
    pubsub.pubnub.com.	18	IN	A	54.241.191.233
---
type: MESSAGE
message:
  type: FORWARDER_QUERY
  query_time: !!timestamp 2020-12-09 23:15:19.208601
  socket_family: INET
  socket_protocol: UDP
  response_address: 1.1.1.1
  response_port: 53
  query_zone: "."
  query_message: |
    ;; opcode: QUERY, status: NOERROR, id: 57949
    ;; flags: rd cd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
    
    ;; QUESTION SECTION:
    ;pubsub.pubnub.com.	IN	 A
    
    ;; ADDITIONAL SECTION:
    
    ;; OPT PSEUDOSECTION:
    ; EDNS: version 0; flags: do; udp: 1472
---
type: MESSAGE
message:
  type: CLIENT_RESPONSE
  response_time: !!timestamp 2020-12-09 23:15:19.208623
  socket_family: INET
  socket_protocol: UDP
  query_address: 192.168.1.221
  query_port: 54582
  response_message: |
    ;; opcode: QUERY, status: NOERROR, id: 2
    ;; flags: qr rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0
    
    ;; QUESTION SECTION:
    ;pubsub.pubnub.com.	IN	 A
    
    ;; ANSWER SECTION:
    pubsub.pubnub.com.	18	IN	A	54.241.191.232
    pubsub.pubnub.com.	18	IN	A	54.241.191.233
---
type: MESSAGE
message:
  type: FORWARDER_RESPONSE
  query_time: !!timestamp 2020-12-09 23:15:19.20788
  response_time: !!timestamp 2020-12-09 23:15:19.228139
  socket_family: INET
  socket_protocol: UDP
  response_address: 1.1.1.1
  response_port: 53
  query_zone: "."
  response_message: |
    ;; opcode: QUERY, status: NOERROR, id: 57949
    ;; flags: qr rd ra cd; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1
    
    ;; QUESTION SECTION:
    ;pubsub.pubnub.com.	IN	 A
    
    ;; ANSWER SECTION:
    pubsub.pubnub.com.	93	IN	A	54.241.191.232
    pubsub.pubnub.com.	93	IN	A	54.241.191.233
    
    ;; ADDITIONAL SECTION:
    
    ;; OPT PSEUDOSECTION:
    ; EDNS: version 0; flags: do; udp: 1232```

[gthess]

Hi,
This looks like you have the prefetch: yes option and thus the "strange" timestamps you are seeing.
The client gets an immediate reply from cache and the query is resolved in order to update the cache.

Other than that the client response at response_time: !!timestamp 2020-12-09 23:15:19.208623 may seem weird.
Can you maybe share the rest of your configuration?

[eest]

@gthess I saw something similar today, where it seems we would get duplicate CLIENT_RESPONSE messages logged when only answering a single request (and only seeing a single response returned on the wire). Here is some JSON-data of the two messages:

{"type":"MESSAGE","identity":"resolver1.example.com","version":"unbound 1.19.1","message":{"type":"CLIENT_RESPONSE","response_time":"2024-04-03T08:21:11.982616Z","socket_family":"INET","socket_protocol":"UDP","query_address":"10.0.0.3","response_address":"10.0.0.2","query_port":19341,"response_port":53,"response_message":";; opcode: QUERY, status: NXDOMAIN, id: 38575\n;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1\n\n;; OPT PSEUDOSECTION:\n; EDNS: version 0; flags:; udp: 1232\n; EDE: 3 (Stale Answer): ()\n\n;; QUESTION SECTION:\n;www5.example.com.\tIN\t A\n\n;; AUTHORITY SECTION:\nexample.com.\t272\tIN\tSOA\thidden-master.example.com. hostmaster.example.com. 2024040300 28800 7200 604800 300\n"}}

{"type":"MESSAGE","identity":"resolver1.example.com","version":"unbound 1.19.1","message":{"type":"CLIENT_RESPONSE","response_time":"2024-04-03T08:21:11.982723Z","socket_family":"INET","socket_protocol":"UDP","query_address":"10.0.0.3","response_address":"10.0.0.2","query_port":19341,"response_port":53,"response_message":";; opcode: QUERY, status: NXDOMAIN, id: 38575\n;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1\n\n;; OPT PSEUDOSECTION:\n; EDNS: version 0; flags:; udp: 1232\n; EDE: 3 (Stale Answer): ()\n\n;; QUESTION SECTION:\n;www5.example.com.\tIN\t A\n\n;; AUTHORITY SECTION:\nexample.com.\t272\tIN\tSOA\thidden-master.example.com. hostmaster.example.com. 2024040300 28800 7200 604800 300\n"}}

What sticks out is that when the duplicates arrive they have EDE: 3 (Stale Answer) in them. Asking for the same thing afterwards only results in a single log entry (and no stale answer data).

For reference we are running with both

        prefetch: yes
        prefetch-key: yes

... and

        ede: yes
        ede-serve-expired: yes

[gthess]

What are the serve-expired* options you are using?

[eest]

These:

serve-expired: yes
serve-expired-ttl: 14400

[gthess]

I believe I see why. Can you verify that this happens every single time for expired (or prefetched) answers? You can set something like cache-max-ttl: 2 for easy testing with expired answers every 3 seconds for example.

[eest]

This looks in line with what I am experiencing. Interestingly I do notice that I sometimes (with cache-max-ttl: 2) seem to also get duplicates where the EDE info is not present, for example here is the result of two queries, where the first one got duplicate entries with EDE in it, and the second one is without EDE:

{"type":"MESSAGE","identity":"resolver1.example.com","version":"unbound 1.19.1","message":{"type":"CLIENT_RESPONSE","response_time":"2024-04-03T10:20:43.284279Z","socket_family":"INET","socket_protocol":"UDP","query_address":"10.0.0.3","response_address":"10.0.0.2","query_port":17387,"response_port":53,"response_message":";; opcode: QUERY, status: NXDOMAIN, id: 2841\n;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1\n\n;; OPT PSEUDOSECTION:\n; EDNS: version 0; flags:; udp: 1232\n; EDE: 3 (Stale Answer): ()\n\n;; QUESTION SECTION:\n;www5.example.com.\tIN\t A\n\n;; AUTHORITY SECTION:\nexample.com.\t30\tIN\tSOA\thidden-master.example.com. hostmaster.example.com. 2024040300 28800 7200 604800 300\n"}}
{"type":"MESSAGE","identity":"resolver1.example.com","version":"unbound 1.19.1","message":{"type":"CLIENT_RESPONSE","response_time":"2024-04-03T10:20:43.284349Z","socket_family":"INET","socket_protocol":"UDP","query_address":"10.0.0.3","response_address":"10.0.0.2","query_port":17387,"response_port":53,"response_message":";; opcode: QUERY, status: NXDOMAIN, id: 2841\n;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1\n\n;; OPT PSEUDOSECTION:\n; EDNS: version 0; flags:; udp: 1232\n; EDE: 3 (Stale Answer): ()\n\n;; QUESTION SECTION:\n;www5.example.com.\tIN\t A\n\n;; AUTHORITY SECTION:\nexample.com.\t30\tIN\tSOA\thidden-master.example.com. hostmaster.example.com. 2024040300 28800 7200 604800 300\n"}}

{"type":"MESSAGE","identity":"resolver1.example.com","version":"unbound 1.19.1","message":{"type":"CLIENT_RESPONSE","response_time":"2024-04-03T10:20:45.913856Z","socket_family":"INET","socket_protocol":"UDP","query_address":"10.0.0.3","response_address":"10.0.0.2","query_port":19017,"response_port":53,"response_message":";; opcode: QUERY, status: NXDOMAIN, id: 45319\n;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1\n\n;; OPT PSEUDOSECTION:\n; EDNS: version 0; flags:; udp: 1232\n\n;; QUESTION SECTION:\n;www5.example.com.\tIN\t A\n\n;; AUTHORITY SECTION:\nexample.com.\t0\tIN\tSOA\thidden-master.example.com. hostmaster.example.com. 2024040300 28800 7200 604800 300\n"}}
{"type":"MESSAGE","identity":"resolver1.example.com","version":"unbound 1.19.1","message":{"type":"CLIENT_RESPONSE","response_time":"2024-04-03T10:20:45.913914Z","socket_family":"INET","socket_protocol":"UDP","query_address":"10.0.0.3","response_address":"10.0.0.2","query_port":19017,"response_port":53,"response_message":";; opcode: QUERY, status: NXDOMAIN, id: 45319\n;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1\n\n;; OPT PSEUDOSECTION:\n; EDNS: version 0; flags:; udp: 1232\n\n;; QUESTION SECTION:\n;www5.example.com.\tIN\t A\n\n;; AUTHORITY SECTION:\nexample.com.\t0\tIN\tSOA\thidden-master.example.com. hostmaster.example.com. 2024040300 28800 7200 604800 300\n"}}

Follow-up requests seem to only be logged once however.

[gthess]

The second one happened to have 0 TTL at that time so not expired yet.
Thanks for verifying what I noticed, we are in the same page then. I'll look for a fix.

[gthess]

This should be fixed now and it also matches @fhriley's initial issue.

[gthess]

Hmm the new test now fails... I'll need to have a second look.

[gthess]

Nope, it works. Local testing gone wrong. But @eest, could you also verify to be sure? :)