From e6f81ebb314f3a4923fb3a63436a9243eeba9e47 Mon Sep 17 00:00:00 2001 From: Miek Gieben Date: Wed, 4 Jul 2018 07:54:17 +0100 Subject: [PATCH] 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 --- .gitignore | 2 -- plugin/debug/README.md | 21 ++++++++++- plugin/debug/pcap.go | 72 +++++++++++++++++++++++++++++++++++++ plugin/debug/pcap_test.go | 74 +++++++++++++++++++++++++++++++++++++++ plugin/forward/forward.go | 3 ++ 5 files changed, 169 insertions(+), 3 deletions(-) create mode 100644 plugin/debug/pcap.go create mode 100644 plugin/debug/pcap_test.go diff --git a/.gitignore b/.gitignore index ca7623eb9..41eba47cb 100644 --- a/.gitignore +++ b/.gitignore @@ -4,8 +4,6 @@ Corefile coredns coredns.exe coredns.exe~ -debug -debug.test kubectl go-test-tmpfile* coverage.txt diff --git a/plugin/debug/README.md b/plugin/debug/README.md index 5c97e004e..0ce1808ed 100644 --- a/plugin/debug/README.md +++ b/plugin/debug/README.md @@ -10,7 +10,7 @@ Normally CoreDNS will recover from panics, using *debug* inhibits this. The main to help testing. A side effect of using *debug* is that `log.Debug` and `log.Debugf` will be printed to standard output. -Note that the *errors* plugin (if loaded) will also set a `recover` negating this setting. +Note that the *errors* plugin (if loaded) will also set a `recover` negating this setting. ## Syntax @@ -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. diff --git a/plugin/debug/pcap.go b/plugin/debug/pcap.go new file mode 100644 index 000000000..053c2d9dd --- /dev/null +++ b/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: " diff --git a/plugin/debug/pcap_test.go b/plugin/debug/pcap_test.go new file mode 100644 index 000000000..724189db7 --- /dev/null +++ b/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())) + } +} diff --git a/plugin/forward/forward.go b/plugin/forward/forward.go index 92bf14bb6..e901572f9 100644 --- a/plugin/forward/forward.go +++ b/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