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

13 files changed, 343 insertions, 103 deletions

diff --git a/middleware/cache/README.md b/middleware/cache/README.md
index c9a678983..56af0de66 100644
--- a/middleware/cache/README.md
+++ b/middleware/cache/README.md
@@ -20,7 +20,7 @@ Or if you want more control:
 
 ~~~ txt
 cache [ttl] [zones...] {
-    noerror capacity [ttl]
+    success capacity [ttl]
     denial capacity [ttl]
 }
 ~~~
diff --git a/middleware/cache/cache.go b/middleware/cache/cache.go
index 091638655..6254349c3 100644
--- a/middleware/cache/cache.go
+++ b/middleware/cache/cache.go
@@ -60,7 +60,7 @@ type ResponseWriter struct {
 // WriteMsg implements the dns.ResponseWriter interface.
 func (c *ResponseWriter) WriteMsg(res *dns.Msg) error {
 	do := false
-	mt, opt := response.Classify(res)
+	mt, opt := response.Typify(res)
 	if opt != nil {
 		do = opt.Do()
 	}
@@ -93,7 +93,7 @@ func (c *ResponseWriter) set(m *dns.Msg, key string, mt response.Type, duration
 	}
 
 	switch mt {
-	case response.Success, response.Delegation:
+	case response.NoError, response.Delegation:
 		i := newItem(m, duration)
 		c.pcache.Add(key, i)
 
diff --git a/middleware/cache/cache_test.go b/middleware/cache/cache_test.go
index d4b9752ff..7e80c66e0 100644
--- a/middleware/cache/cache_test.go
+++ b/middleware/cache/cache_test.go
@@ -94,7 +94,7 @@ func TestCache(t *testing.T) {
 		m = cacheMsg(m, tc)
 		do := tc.in.Do
 
-		mt, _ := response.Classify(m)
+		mt, _ := response.Typify(m)
 		k := key(m, mt, do)
 		crr.set(m, k, mt, c.pttl)
 
diff --git a/middleware/cache/item.go b/middleware/cache/item.go
index ffc11c39a..d2cb79520 100644
--- a/middleware/cache/item.go
+++ b/middleware/cache/item.go
@@ -87,7 +87,7 @@ func setMsgTTL(m *dns.Msg, ttl uint32) {
 }
 
 func minMsgTTL(m *dns.Msg, mt response.Type) time.Duration {
-	if mt != response.Success && mt != response.NameError && mt != response.NoData {
+	if mt != response.NoError && mt != response.NameError && mt != response.NoData {
 		return 0
 	}
 
@@ -98,7 +98,7 @@ func minMsgTTL(m *dns.Msg, mt response.Type) time.Duration {
 			if r.Header().Rrtype == dns.TypeSOA {
 				return time.Duration(r.(*dns.SOA).Minttl) * time.Second
 			}
-		case response.Success, response.Delegation:
+		case response.NoError, response.Delegation:
 			if r.Header().Ttl < uint32(minTTL.Seconds()) {
 				minTTL = time.Duration(r.Header().Ttl) * time.Second
 			}
diff --git a/middleware/dnssec/dnssec.go b/middleware/dnssec/dnssec.go
index 06c2e46bd..1433fb1a3 100644
--- a/middleware/dnssec/dnssec.go
+++ b/middleware/dnssec/dnssec.go
@@ -41,7 +41,7 @@ func New(zones []string, keys []*DNSKEY, next middleware.Handler) Dnssec {
 func (d Dnssec) Sign(state request.Request, zone string, now time.Time) *dns.Msg {
 	req := state.Req
 
-	mt, _ := response.Classify(req) // TODO(miek): need opt record here?
+	mt, _ := response.Typify(req) // TODO(miek): need opt record here?
 	if mt == response.Delegation {
 		return req
 	}
diff --git a/middleware/log/README.md b/middleware/log/README.md
index c4568de1d..c9548c9a0 100644
--- a/middleware/log/README.md
+++ b/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
+}
+~~~
diff --git a/middleware/log/log.go b/middleware/log/log.go
index 1d368765e..dba76341e 100644
--- a/middleware/log/log.go
+++ b/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
+		}
+
+		responseRecorder := dnsrecorder.New(w)
+		rc, err := l.Next.ServeDNS(ctx, responseRecorder, r)
 
-			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)
+		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
+				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
diff --git a/middleware/log/log_test.go b/middleware/log/log_test.go
index 77e3f2e3c..2f4d8c098 100644
--- a/middleware/log/log_test.go
+++ b/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)
 	}
 }
diff --git a/middleware/log/setup.go b/middleware/log/setup.go
index e14bebfe8..3354da9d8 100644
--- a/middleware/log/setup.go
+++ b/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
diff --git a/middleware/log/setup_test.go b/middleware/log/setup_test.go
index 243d6aeb6..8ae4fa03b 100644
--- a/middleware/log/setup_test.go
+++ b/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)
+			}
 		}
 	}
 
diff --git a/middleware/pkg/response/classify.go b/middleware/pkg/response/classify.go
index e22c2e0ad..0251623a0 100644
--- a/middleware/pkg/response/classify.go
+++ b/middleware/pkg/response/classify.go
@@ -1,74 +1,73 @@
 package response
 
-import "github.com/miekg/dns"
+import (
+	"fmt"
 
-// Type is the type of the message
-type Type int
+	"github.com/miekg/dns"
+)
+
+// Class holds sets of Types
+type Class int
 
 const (
-	// Success indicates a positive reply
-	Success Type = iota
-	// NameError is a NXDOMAIN in header, SOA in auth.
-	NameError
-	// NoData indicated name found, but not the type: NOERROR in header, SOA in auth.
-	NoData
-	// Delegation is a msg with a pointer to another nameserver: NOERROR in header, NS in auth, optionally fluff in additional (not checked).
-	Delegation
-	// OtherError indicated any other error: don't cache these.
-	OtherError
+	// All is a meta class encompassing all the classes.
+	All Class = iota
+	// Success is a class for a successful response.
+	Success
+	// Denial is a class for denying existence (NXDOMAIN, or a nodata: type does not exist)
+	Denial
+	// Error is a class for errors, right now defined as not Success and not Denial
+	Error
 )
 
-func (t Type) String() string {
-	switch t {
+func (c Class) String() string {
+	switch c {
+	case All:
+		return "all"
 	case Success:
-		return "NOERROR"
-	case NameError:
-		return "NXDOMAIN"
-	case NoData:
-		return "NODATA"
-	case Delegation:
-		return "DELEGATION"
-	case OtherError:
-		return "OTHERERROR"
+		return "success"
+	case Denial:
+		return "denial"
+	case Error:
+		return "error"
 	}
 	return ""
 }
 
-// Classify classifies a message, it returns the Type.
-func Classify(m *dns.Msg) (Type, *dns.OPT) {
-	opt := m.IsEdns0()
-
-	if len(m.Answer) > 0 && m.Rcode == dns.RcodeSuccess {
-		return Success, opt
-	}
-
-	soa := false
-	ns := 0
-	for _, r := range m.Ns {
-		if r.Header().Rrtype == dns.TypeSOA {
-			soa = true
-			continue
-		}
-		if r.Header().Rrtype == dns.TypeNS {
-			ns++
-		}
-	}
-
-	// Check length of different sections, and drop stuff that is just to large? TODO(miek).
-	if soa && m.Rcode == dns.RcodeSuccess {
-		return NoData, opt
-	}
-	if soa && m.Rcode == dns.RcodeNameError {
-		return NameError, opt
+// ClassFromString returns the class from the string s. If not class matches
+// the All class and an error are returned
+func ClassFromString(s string) (Class, error) {
+	switch s {
+	case "all":
+		return All, nil
+	case "success":
+		return Success, nil
+	case "denial":
+		return Denial, nil
+	case "error":
+		return Error, nil
 	}
+	return All, fmt.Errorf("invalid Class: %s", s)
+}
 
-	if ns > 0 && ns == len(m.Ns) && m.Rcode == dns.RcodeSuccess {
-		return Delegation, opt
-	}
+// Classify classifies a dns message: it returns its Class.
+func Classify(m *dns.Msg) (Class, *dns.OPT) {
+	t, o := Typify(m)
+	return classify(t), o
+}
 
-	if m.Rcode == dns.RcodeSuccess {
-		return Success, opt
+// Does need to be exported?
+func classify(t Type) Class {
+	switch t {
+	case NoError, Delegation:
+		return Success
+	case NameError, NoData:
+		return Denial
+	case OtherError:
+		fallthrough
+	default:
+		return Error
 	}
-
-	return OtherError, opt
+	// never reached
+	return All
 }
diff --git a/middleware/pkg/response/typify.go b/middleware/pkg/response/typify.go
new file mode 100644
index 000000000..6fdd0137a
--- /dev/null
+++ b/middleware/pkg/response/typify.go
@@ -0,0 +1,96 @@
+package response
+
+import (
+	"fmt"
+
+	"github.com/miekg/dns"
+)
+
+// Type is the type of the message
+type Type int
+
+const (
+	// Success indicates a positive reply
+	NoError Type = iota
+	// NameError is a NXDOMAIN in header, SOA in auth.
+	NameError
+	// NoData indicated name found, but not the type: NOERROR in header, SOA in auth.
+	NoData
+	// Delegation is a msg with a pointer to another nameserver: NOERROR in header, NS in auth, optionally fluff in additional (not checked).
+	Delegation
+	// OtherError indicated any other error: don't cache these.
+	OtherError
+)
+
+func (t Type) String() string {
+	switch t {
+	case NoError:
+		return "NOERROR"
+	case NameError:
+		return "NXDOMAIN"
+	case NoData:
+		return "NODATA"
+	case Delegation:
+		return "DELEGATION"
+	case OtherError:
+		return "OTHERERROR"
+	}
+	return ""
+}
+
+// TypeFromString returns the type from the string s. If not type matches
+// the OtherError type and an error are returned.
+func TypeFromString(s string) (Type, error) {
+	switch s {
+	case "NOERROR":
+		return NoError, nil
+	case "NXDOMAIN":
+		return NameError, nil
+	case "NODATA":
+		return NoData, nil
+	case "DELEGATION":
+		return Delegation, nil
+	case "OTHERERROR":
+		return OtherError, nil
+	}
+	return NoError, fmt.Errorf("invalid Type: %s", s)
+}
+
+// Typify classifies a message, it returns the Type.
+func Typify(m *dns.Msg) (Type, *dns.OPT) {
+	opt := m.IsEdns0()
+
+	if len(m.Answer) > 0 && m.Rcode == dns.RcodeSuccess {
+		return NoError, opt
+	}
+
+	soa := false
+	ns := 0
+	for _, r := range m.Ns {
+		if r.Header().Rrtype == dns.TypeSOA {
+			soa = true
+			continue
+		}
+		if r.Header().Rrtype == dns.TypeNS {
+			ns++
+		}
+	}
+
+	// Check length of different sections, and drop stuff that is just to large? TODO(miek).
+	if soa && m.Rcode == dns.RcodeSuccess {
+		return NoData, opt
+	}
+	if soa && m.Rcode == dns.RcodeNameError {
+		return NameError, opt
+	}
+
+	if ns > 0 && ns == len(m.Ns) && m.Rcode == dns.RcodeSuccess {
+		return Delegation, opt
+	}
+
+	if m.Rcode == dns.RcodeSuccess {
+		return NoError, opt
+	}
+
+	return OtherError, opt
+}
diff --git a/middleware/pkg/response/classify_test.go b/middleware/pkg/response/typify_test.go
index 33ac815e3..dbd11c129 100644
--- a/middleware/pkg/response/classify_test.go
+++ b/middleware/pkg/response/typify_test.go
@@ -10,7 +10,7 @@ import (
 
 func TestClassifyDelegation(t *testing.T) {
 	m := delegationMsg()
-	mt, _ := Classify(m)
+	mt, _ := Typify(m)
 	if mt != Delegation {
 		t.Errorf("message is wrongly classified, expected delegation, got %d", mt)
 	}