mw/logs: add rflags to logging (#845)

Add the DNS message response flags as {rflags} to the default logging
Also complete the replacer testing that is was commented out.
And (unrelated) Switch erratic and whoami to ease testing.

Note: {flags} could and should be added as well - but we can leave that
as a beginners bug.

core/dnsserver/zdirectives.go

@@ -35,8 +35,8 @@ var directives = []string{
 	"secondary",
 	"etcd",
 	"proxy",
-	"whoami",
 	"erratic",
+	"whoami",
 	"startup",
 	"shutdown",
 }

middleware.cfg

@@ -43,7 +43,7 @@
 200:secondary:secondary
 210:etcd:etcd
 220:proxy:proxy
-230:whoami:whoami
-240:erratic:erratic
+230:erratic:erratic
+240:whoami:whoami
 500:startup:github.com/mholt/caddy/startupshutdown
 510:shutdown:github.com/mholt/caddy/startupshutdown

middleware/log/README.md

@@ -55,26 +55,28 @@ response placeholders.
 
 The following place holders are supported:
 
-* `{type}`: qtype of the request.
-* `{name}`: qname of the request.
-* `{class}`: qclass of the request.
-* `{proto}`: protocol used (tcp or udp).
-* `{when}`: time of the query.
-* `{remote}`: client's IP address.
-* `{size}`: request size in bytes.
-* `{port}`: client's port.
-* `{duration}`: response duration.
-* `{>bufsize}`: the EDNS0 buffer size advertised.
-* `{>do}`: is the EDNS0 DO (DNSSEC OK) bit set.
+* `{type}`: qtype of the request
+* `{name}`: qname of the request
+* `{class}`: qclass of the request
+* `{proto}`: protocol used (tcp or udp)
+* `{when}`: time of the query
+* `{remote}`: client's IP address
+* `{size}`: request size in bytes
+* `{port}`: client's port
+* `{duration}`: response duration
+* `{rcode}`: response RCODE
+* `{rsize}`: response size
+* `{>rflags}`: response flags, each set flag will be displayed, e.g. "aa, tc". This includes the qr
+  bit as well.
+* `{>bufsize}`: the EDNS0 buffer size advertised in the query
+* `{>do}`: is the EDNS0 DO (DNSSEC OK) bit set in the query
 * `{>id}`: query ID
-* `{>opcode}`: query OPCODE.
-* `{rcode}`: response RCODE.
-* `{rsize}`: response size.
+* `{>opcode}`: query OPCODE
 
 The default Common Log Format is:
 
 ~~~ txt
-`{remote} - [{when}] "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {rsize} {duration}`
+`{remote} - [{when}] "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {>rflags} {rsize} {duration}`
 ~~~
 
 ## Examples

middleware/log/log.go

@@ -78,10 +78,10 @@ type Rule struct {
 }
 
 const (
-	// DefaultLogFilename is the default output name.
+	// DefaultLogFilename is the default output name. This is the only supported value.
 	DefaultLogFilename = "stdout"
 	// CommonLogFormat is the common log format.
-	CommonLogFormat = `{remote} ` + CommonLogEmptyValue + ` [{when}] "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {rsize} {duration}`
+	CommonLogFormat = `{remote} ` + CommonLogEmptyValue + ` [{when}] "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {>rflags} {rsize} {duration}`
 	// CommonLogEmptyValue is the common empty log value.
 	CommonLogEmptyValue = "-"
 	// CombinedLogFormat is the combined log format.

middleware/pkg/replacer/replacer.go

@@ -56,6 +56,9 @@ func New(r *dns.Msg, rr *dnsrecorder.Recorder, emptyValue string) Replacer {
 		rep.replacements["{rcode}"] = rcode
 		rep.replacements["{rsize}"] = strconv.Itoa(rr.Len)
 		rep.replacements["{duration}"] = time.Since(rr.Start).String()
+		if rr.Msg != nil {
+			rep.replacements[headerReplacer+"rflags}"] = flagsToString(rr.Msg.MsgHdr)
+		}
 	}
 
 	// Header placeholders (case-insensitive)
@@ -110,6 +113,48 @@ func boolToString(b bool) string {
 	return "false"
 }
 
+// flagsToString checks all header flags and returns those
+// that are set as a string separated with commas
+func flagsToString(h dns.MsgHdr) string {
+	flags := make([]string, 7)
+	i := 0
+
+	if h.Response {
+		flags[i] = "qr"
+		i++
+	}
+
+	if h.Authoritative {
+		flags[i] = "aa"
+		i++
+	}
+	if h.Truncated {
+		flags[i] = "tc"
+		i++
+	}
+	if h.RecursionDesired {
+		flags[i] = "rd"
+		i++
+	}
+	if h.RecursionAvailable {
+		flags[i] = "ra"
+		i++
+	}
+	if h.Zero {
+		flags[i] = "z"
+		i++
+	}
+	if h.AuthenticatedData {
+		flags[i] = "ad"
+		i++
+	}
+	if h.CheckingDisabled {
+		flags[i] = "cd"
+		i++
+	}
+	return strings.Join(flags[:i], ",")
+}
+
 const (
 	timeFormat     = "02/Jan/2006:15:04:05 -0700"
 	headerReplacer = "{>"

middleware/pkg/replacer/replacer_test.go

@@ -1,28 +1,34 @@
 package replacer
 
-/*
-func TestNewReplacer(t *testing.T) {
-	w := httptest.NewRecorder()
-	recordRequest := NewResponseRecorder(w)
-	reader := strings.NewReader(`{"username": "dennis"}`)
+import (
+	"testing"
 
-	request, err := http.NewRequest("POST", "http://localhost", reader)
-	if err != nil {
-		t.Fatal("Request Formation Failed\n")
-	}
-	replaceValues := NewReplacer(request, recordRequest, "")
+	"github.com/coredns/coredns/middleware/pkg/dnsrecorder"
+	"github.com/coredns/coredns/middleware/test"
+
+	"github.com/miekg/dns"
+)
+
+func TestNewReplacer(t *testing.T) {
+	w := dnsrecorder.New(&test.ResponseWriter{})
+
+	r := new(dns.Msg)
+	r.SetQuestion("example.org.", dns.TypeHINFO)
+	r.MsgHdr.AuthenticatedData = true
+
+	replaceValues := New(r, w, "")
 
 	switch v := replaceValues.(type) {
 	case replacer:
 
-		if v.replacements["{host}"] != "localhost" {
-			t.Error("Expected host to be localhost")
+		if v.replacements["{type}"] != "HINFO" {
+			t.Errorf("Expected type to be HINFO, got %q", v.replacements["{type}"])
 		}
-		if v.replacements["{method}"] != "POST" {
-			t.Error("Expected request method  to be POST")
+		if v.replacements["{name}"] != "example.org." {
+			t.Errorf("Expected request name to be example.org., got %q", v.replacements["{name}"])
 		}
-		if v.replacements["{status}"] != "200" {
-			t.Error("Expected status to be 200")
+		if v.replacements["{size}"] != "29" { // size of request
+			t.Errorf("Expected size to be 29, got %q", v.replacements["{size}"])
 		}
 
 	default:
@@ -30,90 +36,26 @@ func TestNewReplacer(t *testing.T) {
 	}
 }
 
-func TestReplace(t *testing.T) {
-	w := httptest.NewRecorder()
-	recordRequest := NewResponseRecorder(w)
-	reader := strings.NewReader(`{"username": "dennis"}`)
-
-	request, err := http.NewRequest("POST", "http://localhost", reader)
-	if err != nil {
-		t.Fatal("Request Formation Failed\n")
-	}
-	request.Header.Set("Custom", "foobarbaz")
-	request.Header.Set("ShorterVal", "1")
-	repl := NewReplacer(request, recordRequest, "-")
-
-	if expected, actual := "This host is localhost.", repl.Replace("This host is {host}."); expected != actual {
-		t.Errorf("{host} replacement: expected '%s', got '%s'", expected, actual)
-	}
-	if expected, actual := "This request method is POST.", repl.Replace("This request method is {method}."); expected != actual {
-		t.Errorf("{method} replacement: expected '%s', got '%s'", expected, actual)
-	}
-	if expected, actual := "The response status is 200.", repl.Replace("The response status is {status}."); expected != actual {
-		t.Errorf("{status} replacement: expected '%s', got '%s'", expected, actual)
-	}
-	if expected, actual := "The Custom header is foobarbaz.", repl.Replace("The Custom header is {>Custom}."); expected != actual {
-		t.Errorf("{>Custom} replacement: expected '%s', got '%s'", expected, actual)
-	}
-
-	// Test header case-insensitivity
-	if expected, actual := "The cUsToM header is foobarbaz...", repl.Replace("The cUsToM header is {>cUsToM}..."); expected != actual {
-		t.Errorf("{>cUsToM} replacement: expected '%s', got '%s'", expected, actual)
-	}
-
-	// Test non-existent header/value
-	if expected, actual := "The Non-Existent header is -.", repl.Replace("The Non-Existent header is {>Non-Existent}."); expected != actual {
-		t.Errorf("{>Non-Existent} replacement: expected '%s', got '%s'", expected, actual)
-	}
-
-	// Test bad placeholder
-	if expected, actual := "Bad {host placeholder...", repl.Replace("Bad {host placeholder..."); expected != actual {
-		t.Errorf("bad placeholder: expected '%s', got '%s'", expected, actual)
-	}
-
-	// Test bad header placeholder
-	if expected, actual := "Bad {>Custom placeholder", repl.Replace("Bad {>Custom placeholder"); expected != actual {
-		t.Errorf("bad header placeholder: expected '%s', got '%s'", expected, actual)
-	}
-
-	// Test bad header placeholder with valid one later
-	if expected, actual := "Bad -", repl.Replace("Bad {>Custom placeholder {>ShorterVal}"); expected != actual {
-		t.Errorf("bad header placeholders: expected '%s', got '%s'", expected, actual)
-	}
-
-	// Test shorter header value with multiple placeholders
-	if expected, actual := "Short value 1 then foobarbaz.", repl.Replace("Short value {>ShorterVal} then {>Custom}."); expected != actual {
-		t.Errorf("short value: expected '%s', got '%s'", expected, actual)
-	}
-}
-
 func TestSet(t *testing.T) {
-	w := httptest.NewRecorder()
-	recordRequest := NewResponseRecorder(w)
-	reader := strings.NewReader(`{"username": "dennis"}`)
+	w := dnsrecorder.New(&test.ResponseWriter{})
 
-	request, err := http.NewRequest("POST", "http://localhost", reader)
-	if err != nil {
-		t.Fatalf("Request Formation Failed \n")
-	}
-	repl := NewReplacer(request, recordRequest, "")
+	r := new(dns.Msg)
+	r.SetQuestion("example.org.", dns.TypeHINFO)
+	r.MsgHdr.AuthenticatedData = true
 
-	repl.Set("host", "getcaddy.com")
-	repl.Set("method", "GET")
-	repl.Set("status", "201")
-	repl.Set("variable", "value")
+	repl := New(r, w, "")
 
-	if repl.Replace("This host is {host}") != "This host is getcaddy.com" {
-		t.Error("Expected host replacement failed")
+	repl.Set("name", "coredns.io.")
+	repl.Set("type", "A")
+	repl.Set("size", "20")
+
+	if repl.Replace("This name is {name}") != "This name is coredns.io." {
+		t.Error("Expected name replacement failed")
 	}
-	if repl.Replace("This request method is {method}") != "This request method is GET" {
-		t.Error("Expected method replacement failed")
+	if repl.Replace("This type is {type}") != "This type is A" {
+		t.Error("Expected type replacement failed")
 	}
-	if repl.Replace("The response status is {status}") != "The response status is 201" {
-		t.Error("Expected status replacement failed")
-	}
-	if repl.Replace("The value of variable is {variable}") != "The value of variable is value" {
-		t.Error("Expected variable replacement failed")
+	if repl.Replace("The request size is {size}") != "The request size is 20" {
+		t.Error("Expected size replacement failed")
 	}
 }
-*/