Add debug.Hexdump (#1902)

Allow plugins to dump messages in text pcap to the log. The forward
plugin does this when a reply does not much the query.

If the debug plugin isn't loaded Hexdump and Hexdumpf are noop.

Signed-off-by: Miek Gieben <miek@miek.nl>

.gitignore

@@ -4,8 +4,6 @@ Corefile
 coredns
 coredns.exe
 coredns.exe~
-debug
-debug.test
 kubectl
 go-test-tmpfile*
 coverage.txt

plugin/debug/README.md

@@ -18,6 +18,21 @@ Note that the *errors* plugin (if loaded) will also set a `recover` negating thi
 debug
 ~~~
 
+Some plugin will debug log DNS messages. This is done in the following format:
+
+~~~
+debug: 000000 00 0a 01 00 00 01 00 00 00 00 00 01 07 65 78 61
+debug: 000010 6d 70 6c 65 05 6c 6f 63 61 6c 00 00 01 00 01 00
+debug: 000020 00 29 10 00 00 00 80 00 00 00
+debug: 00002a
+~~~
+
+Using `text2pcap` (part of Wireshark) this can be converted back to binary, with the following
+command line: `text2pcap -i 17 -u 53,53`. Where 17 is the protocol (UDP) and 53 are the ports. These
+ports allow wireshark to detect these packets as DNS messages.
+
+Each plugin can decide to dump messages to aid in debugging.
+
 ## Examples
 
 Disable the ability to recover from crashes and show debug logging:
@@ -27,3 +42,7 @@ Disable the ability to recover from crashes and show debug logging:
     debug
 }
 ~~~
+
+## Also See
+
+https://www.wireshark.org/docs/man-pages/text2pcap.html.

plugin/debug/pcap.go

@@ -0,0 +1,72 @@
+package debug
+
+import (
+	"bytes"
+	"fmt"
+
+	"github.com/coredns/coredns/plugin/pkg/log"
+
+	"github.com/miekg/dns"
+)
+
+// Hexdump converts the dns message m to a hex dump Whireshark can import.
+// See https://www.wireshark.org/docs/man-pages/text2pcap.html.
+// This output looks like this:
+//
+// 00000 dc bd 01 00 00 01 00 00 00 00 00 01 07 65 78 61
+// 000010 6d 70 6c 65 05 6c 6f 63 61 6c 00 00 01 00 01 00
+// 000020 00 29 10 00 00 00 80 00 00 00
+// 00002a
+//
+// Hexdump will use log.Debug to write the dump to the log, each line
+// is prefixed with 'debug: ' so the data can be easily extracted.
+//
+// msg will prefix the pcap dump.
+func Hexdump(m *dns.Msg, v ...interface{}) {
+	if !log.D {
+		return
+	}
+
+	buf, _ := m.Pack()
+	if len(buf) == 0 {
+		return
+	}
+
+	out := "\n" + string(hexdump(buf))
+	v = append(v, out)
+	log.Debug(v...)
+}
+
+// Hexdumpf dumps a DNS message as Hexdump, but allows a format string.
+func Hexdumpf(m *dns.Msg, format string, v ...interface{}) {
+	if !log.D {
+		return
+	}
+
+	buf, _ := m.Pack()
+	if len(buf) == 0 {
+		return
+	}
+
+	format += "\n%s"
+	v = append(v, hexdump(buf))
+	log.Debugf(format, v...)
+}
+
+func hexdump(data []byte) []byte {
+	b := new(bytes.Buffer)
+
+	newline := ""
+	for i := 0; i < len(data); i++ {
+		if i%16 == 0 {
+			fmt.Fprintf(b, "%s%s%06x", newline, prefix, i)
+			newline = "\n"
+		}
+		fmt.Fprintf(b, " %02x", data[i])
+	}
+	fmt.Fprintf(b, "\n%s%06x", prefix, len(data))
+
+	return b.Bytes()
+}
+
+const prefix = "debug: "

plugin/debug/pcap_test.go

@@ -0,0 +1,74 @@
+package debug
+
+import (
+	"bytes"
+	"fmt"
+	golog "log"
+	"strings"
+	"testing"
+
+	"github.com/coredns/coredns/plugin/pkg/log"
+
+	"github.com/miekg/dns"
+)
+
+func msg() *dns.Msg {
+	m := new(dns.Msg)
+	m.SetQuestion("example.local.", dns.TypeA)
+	m.SetEdns0(4096, true)
+	m.Id = 10
+
+	return m
+}
+
+func ExampleLogHexdump() {
+	buf, _ := msg().Pack()
+	h := hexdump(buf)
+	fmt.Println(string(h))
+
+	// Output:
+	// debug: 000000 00 0a 01 00 00 01 00 00 00 00 00 01 07 65 78 61
+	// debug: 000010 6d 70 6c 65 05 6c 6f 63 61 6c 00 00 01 00 01 00
+	// debug: 000020 00 29 10 00 00 00 80 00 00 00
+	// debug: 00002a
+}
+
+func TestHexdump(t *testing.T) {
+	var f bytes.Buffer
+	golog.SetOutput(&f)
+	log.D = true
+
+	str := "Hi There!"
+	Hexdump(msg(), str)
+	logged := f.String()
+
+	if !strings.Contains(logged, "[DEBUG] "+str) {
+		t.Errorf("The string %s, is not contained in the logged output: %s", str, logged)
+	}
+}
+
+func TestHexdumpf(t *testing.T) {
+	var f bytes.Buffer
+	golog.SetOutput(&f)
+	log.D = true
+
+	str := "Hi There!"
+	Hexdumpf(msg(), "%s %d", str, 10)
+	logged := f.String()
+
+	if !strings.Contains(logged, "[DEBUG] "+fmt.Sprintf("%s %d", str, 10)) {
+		t.Errorf("The string %s %d, is not contained in the logged output: %s", str, 10, logged)
+	}
+}
+
+func TestNoDebug(t *testing.T) {
+	var f bytes.Buffer
+	golog.SetOutput(&f)
+	log.D = false
+
+	str := "Hi There!"
+	Hexdumpf(msg(), "%s %d", str, 10)
+	if len(f.Bytes()) != 0 {
+		t.Errorf("Expected no output, got %d bytes", len(f.Bytes()))
+	}
+}

plugin/forward/forward.go

@@ -11,6 +11,7 @@ import (
 	"time"
 
 	"github.com/coredns/coredns/plugin"
+	"github.com/coredns/coredns/plugin/debug"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
@@ -131,6 +132,8 @@ func (f *Forward) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg
 
 		// Check if the reply is correct; if not return FormErr.
 		if !state.Match(ret) {
+			debug.Hexdumpf(ret, "Wrong reply for id: %d, %s/%d", state.QName(), state.QType())
+
 			formerr := state.ErrorMessage(dns.RcodeFormatError)
 			w.WriteMsg(formerr)
 			return 0, nil