plugin/dnstap: tap deferred error responses (#8549)

When the plugin chain returns an error rcode without writing a response
(it falls off the end, or returns SERVFAIL/REFUSED/FORMERR/NOTIMP), the
server generates and sends the error to the client after dnstap's ServeDNS
returns, so ResponseWriter.WriteMsg is never called and no CLIENT_RESPONSE
dnstap message is emitted. dnstap consumers then see a CLIENT_QUERY with no
matching CLIENT_RESPONSE.

Synthesize the deferred response and tap it as a CLIENT_RESPONSE, mirroring
the deferred-response handling already added to plugin/log.

Fixes #6532

Signed-off-by: Saleh <root@lr0.org>

plugin/dnstap/handler.go

@@ -91,7 +91,22 @@ func (h *Dnstap) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg)
 	// forwarder. Otherwise, the tap messages will come out out of order.
 	h.tapQuery(ctx, w, r, rw.queryTime)
 
-	return plugin.NextOrFailure(h.Name(), h.Next, ctx, rw, r)
+	rcode, err := plugin.NextOrFailure(h.Name(), h.Next, ctx, rw, r)
+
+	// When the plugin chain returns an error rcode without having written a
+	// response (e.g. it falls off the end, or returns SERVFAIL/REFUSED/FORMERR/
+	// NOTIMP), the server generates and sends the error response to the client
+	// after ServeDNS returns, so ResponseWriter.WriteMsg is never called and no
+	// CLIENT_RESPONSE is tapped. Synthesize the deferred response so dnstap
+	// consumers see a CLIENT_RESPONSE matching what the client receives, rather
+	// than a CLIENT_QUERY with no matching response (#6532).
+	if !rw.written && !plugin.ClientWrite(rcode) {
+		deferred := new(dns.Msg)
+		deferred.SetRcode(r, rcode)
+		rw.tapResponse(deferred)
+	}
+
+	return rcode, err
 }
 
 // Name implements the plugin.Plugin interface.

plugin/dnstap/handler_test.go

@@ -177,3 +177,57 @@ func TestNilIoAndListener(t *testing.T) {
 		t.Errorf("Expected io to receive message")
 	}
 }
+
+// collectTapper records every dnstap payload it receives so a test can inspect
+// the sequence and contents of the emitted messages.
+type collectTapper struct {
+	msgs []*tap.Dnstap
+}
+
+func (c *collectTapper) Dnstap(e *tap.Dnstap) { c.msgs = append(c.msgs, e) }
+
+func TestDnstapDeferredError(t *testing.T) {
+	// When the plugin chain returns an error rcode without writing a response,
+	// the server generates and sends the error to the client after dnstap's
+	// ServeDNS returns, so ResponseWriter.WriteMsg is never called. dnstap must
+	// still emit a CLIENT_RESPONSE reflecting that deferred error, otherwise a
+	// dnstap stream shows a CLIENT_QUERY with no matching CLIENT_RESPONSE (#6532).
+	q := test.Case{Qname: "example.org.", Qtype: dns.TypeA}.Msg()
+
+	c := &collectTapper{}
+	h := Dnstap{
+		Next: test.HandlerFunc(func(_ context.Context, _ dns.ResponseWriter, _ *dns.Msg) (int, error) {
+			// Return an error rcode WITHOUT calling WriteMsg, deferring the
+			// response to the server (as e.g. an unmatched plugin/auto does).
+			return dns.RcodeServerFailure, nil
+		}),
+		io:                c,
+		IncludeRawMessage: true,
+	}
+
+	rcode, err := h.ServeDNS(context.TODO(), &test.ResponseWriter{}, q)
+	if err != nil {
+		t.Fatalf("ServeDNS returned error: %v", err)
+	}
+	if rcode != dns.RcodeServerFailure {
+		t.Fatalf("expected rcode SERVFAIL, got %d", rcode)
+	}
+
+	if len(c.msgs) != 2 {
+		t.Fatalf("expected 2 dnstap messages (CLIENT_QUERY + CLIENT_RESPONSE), got %d", len(c.msgs))
+	}
+	if got := c.msgs[0].GetMessage().GetType(); got != tap.Message_CLIENT_QUERY {
+		t.Errorf("first message: expected CLIENT_QUERY, got %v", got)
+	}
+	respMsg := c.msgs[1].GetMessage()
+	if got := respMsg.GetType(); got != tap.Message_CLIENT_RESPONSE {
+		t.Fatalf("second message: expected CLIENT_RESPONSE, got %v", got)
+	}
+	unpacked := new(dns.Msg)
+	if err := unpacked.Unpack(respMsg.GetResponseMessage()); err != nil {
+		t.Fatalf("failed to unpack tapped CLIENT_RESPONSE: %v", err)
+	}
+	if unpacked.Rcode != dns.RcodeServerFailure {
+		t.Errorf("expected SERVFAIL in tapped response, got %s", dns.RcodeToString[unpacked.Rcode])
+	}
+}

plugin/dnstap/writer.go

@@ -16,6 +16,7 @@ type ResponseWriter struct {
 	queryTime time.Time
 	query     *dns.Msg
 	ctx       context.Context
+	written   bool // whether WriteMsg was called, i.e. a response was written to the client
 	dns.ResponseWriter
 	*Dnstap
 }
@@ -26,7 +27,14 @@ func (w *ResponseWriter) WriteMsg(resp *dns.Msg) error {
 	if err != nil {
 		return err
 	}
+	w.written = true
+	w.tapResponse(resp)
+	return nil
+}
 
+// tapResponse sends a CLIENT_RESPONSE dnstap message for resp. It does not
+// write anything back to the client; the caller is responsible for that.
+func (w *ResponseWriter) tapResponse(resp *dns.Msg) {
 	r := new(tap.Message)
 	msg.SetQueryTime(r, w.queryTime)
 	msg.SetResponseTime(r, time.Now())
@@ -40,5 +48,4 @@ func (w *ResponseWriter) WriteMsg(resp *dns.Msg) error {
 	msg.SetType(r, tap.Message_CLIENT_RESPONSE)
 	state := request.Request{W: w.ResponseWriter, Req: w.query}
 	w.TapMessageWithMetadata(w.ctx, r, state)
-	return nil
 }