middleware/log: allows logging based on response classes (#325)

Add the ability to add a class of responses to be logged; success,
denial or error. The default is to log everything (all).

Fixes #258

middleware/log/README.md

@@ -1,34 +1,53 @@
 # log
 
-`log` enables request logging. The request log is also known in some vernacular as an access log.
+`log` enables query logging.
 
 ## Syntax
 
-~~~
+~~~ txt
 log
 ~~~
 
 * With no arguments, a query log entry is written to query.log in the common log format for all requests
     (base name = .).
 
-~~~
+~~~ txt
 log file
 ~~~
 
-* file is the log file to create (or append to). The base path is assumed to be . .
+* file is the log file to create (or append to). The base name is assumed to be '.' .
 
-~~~
-log name file [format]
+~~~ txt
+log [name] [file] [format]
 ~~~
 
 * `name` is the base name to match in order to be logged
 * `file` is the log file to create (or append to)
 * `format` is the log format to use (default is Common Log Format)
 
+You can further specify the class of responses that get logged:
+
+~~~ txt
+log [name] [file] [format] {
+    class [success|denial|error|all]
+}
+~~~
+
+Here *success*, *denial* and *error* denotes the class of responses that should be logged. The
+classes have the following meaning:
+
+* `success`: successful response
+* `denial`: either NXDOMAIN or NODATA (name exists, type does not)
+* `error`: SERVFAIL, NOTIMP, REFUSED, etc. Any that indicated the remove server is not willing to
+    resolve the request.
+* `all`: the default is nothing is specified.
+
+If no class is specified it defaults to *all*.
+
 ## Log File
 
-The log file can be any filename. It could also be stdout or stderr to write the log to the console,
-or syslog to write to the system log (except on Windows). If the log file does not exist beforehand,
+The log file can be any filename. It could also be *stdout* or *stderr* to write the log to the console,
+or *syslog* to write to the system log (except on Windows). If the log file does not exist beforehand,
 CoreDNS will create it before appending to it.
 
 ## Log Format
@@ -53,6 +72,11 @@ The following place holders are supported:
 * `{>id}`: query ID
 * `{>opcode}`: query OPCODE
 
+The default Common Log Format is:
+
+~~~ txt
+`{remote} - [{when}] "{type} {class} {name} {proto} {>do} {>bufsize}" {rcode} {size} {duration}`
+~~~
 
 ## Examples
 
@@ -67,3 +91,11 @@ Custom log format:
 ~~~
 log . ../query.log "{proto} Request: {name} {type} {>id}"
 ~~~
+
+Only log denials for example.org (and below to a file)
+
+~~~
+log example.org example-query-log {
+    class denial
+}
+~~~

middleware/log/log.go

@@ -10,6 +10,7 @@ import (
 	"github.com/miekg/coredns/middleware/pkg/dnsrecorder"
 	"github.com/miekg/coredns/middleware/pkg/rcode"
 	"github.com/miekg/coredns/middleware/pkg/replacer"
+	"github.com/miekg/coredns/middleware/pkg/response"
 	"github.com/miekg/coredns/request"
 
 	"github.com/miekg/dns"
@@ -27,30 +28,38 @@ type Logger struct {
 func (l Logger) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) {
 	state := request.Request{W: w, Req: r}
 	for _, rule := range l.Rules {
-		if middleware.Name(rule.NameScope).Matches(state.Name()) {
-			responseRecorder := dnsrecorder.New(w)
-			rc, err := l.Next.ServeDNS(ctx, responseRecorder, r)
+		if !middleware.Name(rule.NameScope).Matches(state.Name()) {
+			continue
+		}
 
-			if rc > 0 {
-				// There was an error up the chain, but no response has been written yet.
-				// The error must be handled here so the log entry will record the response size.
-				if l.ErrorFunc != nil {
-					l.ErrorFunc(responseRecorder, r, rc)
-				} else {
-					answer := new(dns.Msg)
-					answer.SetRcode(r, rc)
-					state.SizeAndDo(answer)
+		responseRecorder := dnsrecorder.New(w)
+		rc, err := l.Next.ServeDNS(ctx, responseRecorder, r)
 
-					metrics.Report(state, metrics.Dropped, rcode.ToString(rc), answer.Len(), time.Now())
-					w.WriteMsg(answer)
-				}
-				rc = 0
+		if rc > 0 {
+			// There was an error up the chain, but no response has been written yet.
+			// The error must be handled here so the log entry will record the response size.
+			if l.ErrorFunc != nil {
+				l.ErrorFunc(responseRecorder, r, rc)
+			} else {
+				answer := new(dns.Msg)
+				answer.SetRcode(r, rc)
+				state.SizeAndDo(answer)
+
+				metrics.Report(state, metrics.Dropped, rcode.ToString(rc), answer.Len(), time.Now())
+
+				w.WriteMsg(answer)
 			}
+			rc = 0
+		}
+
+		class, _ := response.Classify(responseRecorder.Msg)
+		if rule.Class == response.All || rule.Class == class {
 			rep := replacer.New(r, responseRecorder, CommonLogEmptyValue)
 			rule.Log.Println(rep.Replace(rule.Format))
-			return rc, err
-
 		}
+
+		return rc, err
+
 	}
 	return l.Next.ServeDNS(ctx, w, r)
 }
@@ -58,6 +67,7 @@ func (l Logger) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg)
 // Rule configures the logging middleware.
 type Rule struct {
 	NameScope  string
+	Class      response.Class
 	OutputFile string
 	Format     string
 	Log        *log.Logger

middleware/log/log_test.go

@@ -7,21 +7,15 @@ import (
 	"testing"
 
 	"github.com/miekg/coredns/middleware/pkg/dnsrecorder"
+	"github.com/miekg/coredns/middleware/pkg/response"
 	"github.com/miekg/coredns/middleware/test"
 
 	"github.com/miekg/dns"
 	"golang.org/x/net/context"
 )
 
-type erroringMiddleware struct{}
-
-func (erroringMiddleware) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) {
-	return dns.RcodeServerFailure, nil
-}
-
 func TestLoggedStatus(t *testing.T) {
 	var f bytes.Buffer
-	var next erroringMiddleware
 	rule := Rule{
 		NameScope: ".",
 		Format:    DefaultLogFormat,
@@ -30,7 +24,7 @@ func TestLoggedStatus(t *testing.T) {
 
 	logger := Logger{
 		Rules: []Rule{rule},
-		Next:  next,
+		Next:  test.ErrorHandler(),
 	}
 
 	ctx := context.TODO()
@@ -41,11 +35,67 @@ func TestLoggedStatus(t *testing.T) {
 
 	rcode, _ := logger.ServeDNS(ctx, rec, r)
 	if rcode != 0 {
-		t.Error("Expected rcode to be 0 - was", rcode)
+		t.Errorf("Expected rcode to be 0 - was: %d", rcode)
 	}
 
 	logged := f.String()
 	if !strings.Contains(logged, "A IN example.org. udp false 512") {
-		t.Error("Expected it to be logged. Logged string -", logged)
+		t.Errorf("Expected it to be logged. Logged string: %s", logged)
+	}
+}
+
+func TestLoggedClassDenial(t *testing.T) {
+	var f bytes.Buffer
+	rule := Rule{
+		NameScope: ".",
+		Format:    DefaultLogFormat,
+		Log:       log.New(&f, "", 0),
+		Class:     response.Denial,
+	}
+
+	logger := Logger{
+		Rules: []Rule{rule},
+		Next:  test.ErrorHandler(),
+	}
+
+	ctx := context.TODO()
+	r := new(dns.Msg)
+	r.SetQuestion("example.org.", dns.TypeA)
+
+	rec := dnsrecorder.New(&test.ResponseWriter{})
+
+	logger.ServeDNS(ctx, rec, r)
+
+	logged := f.String()
+	if len(logged) != 0 {
+		t.Errorf("Expected it not to be logged, but got string: %s", logged)
+	}
+}
+
+func TestLoggedClassError(t *testing.T) {
+	var f bytes.Buffer
+	rule := Rule{
+		NameScope: ".",
+		Format:    DefaultLogFormat,
+		Log:       log.New(&f, "", 0),
+		Class:     response.Error,
+	}
+
+	logger := Logger{
+		Rules: []Rule{rule},
+		Next:  test.ErrorHandler(),
+	}
+
+	ctx := context.TODO()
+	r := new(dns.Msg)
+	r.SetQuestion("example.org.", dns.TypeA)
+
+	rec := dnsrecorder.New(&test.ResponseWriter{})
+
+	logger.ServeDNS(ctx, rec, r)
+
+	logged := f.String()
+	if !strings.Contains(logged, "SERVFAIL") {
+		t.Errorf("Expected it to be logged. Logged string: %s", logged)
 	}
 }

middleware/log/setup.go

@@ -7,6 +7,7 @@ import (
 
 	"github.com/miekg/coredns/core/dnsserver"
 	"github.com/miekg/coredns/middleware"
+	"github.com/miekg/coredns/middleware/pkg/response"
 
 	"github.com/hashicorp/go-syslog"
 	"github.com/mholt/caddy"
@@ -105,6 +106,26 @@ func logParse(c *caddy.Controller) ([]Rule, error) {
 				Format:     format,
 			})
 		}
+
+		// Class refinements in an extra block.
+		for c.NextBlock() {
+			switch c.Val() {
+			// class followed by all, denial, error or success.
+			case "class":
+				classes := c.RemainingArgs()
+				if len(classes) == 0 {
+					return nil, c.ArgErr()
+				}
+				cls, err := response.ClassFromString(classes[0])
+				if err != nil {
+					return nil, err
+				}
+				// update class and the last added Rule (bit icky)
+				rules[len(rules)-1].Class = cls
+			default:
+				return nil, c.ArgErr()
+			}
+		}
 	}
 
 	return rules, nil

middleware/log/setup_test.go

@@ -3,6 +3,8 @@ package log
 import (
 	"testing"
 
+	"github.com/miekg/coredns/middleware/pkg/response"
+
 	"github.com/mholt/caddy"
 )
 
@@ -43,7 +45,7 @@ func TestLogParse(t *testing.T) {
 			Format:     CombinedLogFormat,
 		}}},
 		{`log example.org. log.txt
-		  log example.net accesslog.txt {combined}`, false, []Rule{{
+			  log example.net accesslog.txt {combined}`, false, []Rule{{
 			NameScope:  "example.org.",
 			OutputFile: "log.txt",
 			Format:     DefaultLogFormat,
@@ -53,7 +55,7 @@ func TestLogParse(t *testing.T) {
 			Format:     CombinedLogFormat,
 		}}},
 		{`log example.org stdout {host}
-		  log example.org log.txt {when}`, false, []Rule{{
+			  log example.org log.txt {when}`, false, []Rule{{
 			NameScope:  "example.org.",
 			OutputFile: "stdout",
 			Format:     "{host}",
@@ -62,6 +64,31 @@ func TestLogParse(t *testing.T) {
 			OutputFile: "log.txt",
 			Format:     "{when}",
 		}}},
+
+		{`log example.org log.txt {
+				class all
+			}`, false, []Rule{{
+			NameScope:  "example.org.",
+			OutputFile: "log.txt",
+			Format:     CommonLogFormat,
+			Class:      response.All,
+		}}},
+		{`log example.org log.txt {
+			class denial
+		}`, false, []Rule{{
+			NameScope:  "example.org.",
+			OutputFile: "log.txt",
+			Format:     CommonLogFormat,
+			Class:      response.Denial,
+		}}},
+		{`log {
+			class denial
+		}`, false, []Rule{{
+			NameScope:  ".",
+			OutputFile: DefaultLogFilename,
+			Format:     CommonLogFormat,
+			Class:      response.Denial,
+		}}},
 	}
 	for i, test := range tests {
 		c := caddy.NewTestController("dns", test.inputLogRules)
@@ -92,6 +119,11 @@ func TestLogParse(t *testing.T) {
 				t.Errorf("Test %d expected %dth LogRule Format to be  %s  , but got %s",
 					i, j, test.expectedLogRules[j].Format, actualLogRule.Format)
 			}
+
+			if actualLogRule.Class != test.expectedLogRules[j].Class {
+				t.Errorf("Test %d expected %dth LogRule Class to be  %s  , but got %s",
+					i, j, test.expectedLogRules[j].Class, actualLogRule.Class)
+			}
 		}
 	}