Merge pull request #19 from miekg/middleware/log

Fix middleware log

core/setup/log.go

@@ -9,6 +9,7 @@ import (
 	"github.com/miekg/coredns/middleware"
 	caddylog "github.com/miekg/coredns/middleware/log"
 	"github.com/miekg/coredns/server"
+	"github.com/miekg/dns"
 )
 
 // Log sets up the logging middleware.
@@ -88,7 +89,7 @@ func logParse(c *Controller) ([]caddylog.Rule, error) {
 		if len(args) == 0 {
 			// Nothing specified; use defaults
 			rules = append(rules, caddylog.Rule{
-				PathScope:  "/",
+				NameScope:  ".",
 				OutputFile: caddylog.DefaultLogFilename,
 				Format:     caddylog.DefaultLogFormat,
 				Roller:     logRoller,
@@ -96,13 +97,13 @@ func logParse(c *Controller) ([]caddylog.Rule, error) {
 		} else if len(args) == 1 {
 			// Only an output file specified
 			rules = append(rules, caddylog.Rule{
-				PathScope:  "/",
+				NameScope:  ".",
 				OutputFile: args[0],
 				Format:     caddylog.DefaultLogFormat,
 				Roller:     logRoller,
 			})
 		} else {
-			// Path scope, output file, and maybe a format specified
+			// Name scope, output file, and maybe a format specified
 
 			format := caddylog.DefaultLogFormat
 
@@ -118,7 +119,7 @@ func logParse(c *Controller) ([]caddylog.Rule, error) {
 			}
 
 			rules = append(rules, caddylog.Rule{
-				PathScope:  args[0],
+				NameScope:  dns.Fqdn(args[0]),
 				OutputFile: args[1],
 				Format:     format,
 				Roller:     logRoller,

directives.md

+# Log
+
+log enables request logging. The request log is also known from some vernaculars as an access log.
+
+## Syntax
+
+~~~
+log
+~~~
+
+* With no arguments, an query log is written to query.log in the common log format for all requests
+    (base name = .).
+
+~~~
+log file
+~~~
+
+* file is the log file to create (or append to). The base path is assumed to be . .
+
+~~~
+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)
+
+## 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,
+CoreDNS will create it before appending to it.
+
+## Log Format
+
+You can specify a custom log format with any placeholder values. Log supports both request and response placeholders.
+
+## Log Rotation
+
+If you enable log rotation, log files will be automatically maintained when they get large or old.
+You can use rotation by opening a block on your first line, which can be any of the variations
+described above:
+
+~~~
+log ... {
+    rotate {
+    size maxsize
+    age  maxage
+    keep maxkeep
+    }
+}
+~~~
+
+* `maxsize` is the maximum size of a log file in megabytes (MB) before it gets rotated. Default is 100 MB.
+* `maxage` is the maximum age of a rotated log file in days, after which it will be deleted. Default is to never delete old files because of age.
+* `maxkeep` is the maximum number of rotated log files to keep. Default is to retain all old log files.
+
+## Examples
+
+Log all requests to a file:
+
+~~~
+log /var/log/query.log
+~~~
+
+Custom log format:
+
+~~~
+log . ../query.log "{proto} Request: {name} {type} {>id}"
+~~~
+
+With rotation:
+
+~~~
+log query.log {
+    rotate {
+        100 # Rotate after 100 MB
+        age  14  # Keep log files for 14 days
+        keep 10  # Keep at most 10 log files
+    }
+}

middleware/log/log.go

@@ -18,36 +18,36 @@ type Logger struct {
 }
 
 func (l Logger) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) {
+	state := middleware.State{W: w, Req: r}
 	for _, rule := range l.Rules {
-		/*
-			if middleware.Path(r.URL.Path).Matches(rule.PathScope) {
-				responseRecorder := middleware.NewResponseRecorder(w)
-				status, err := l.Next.ServeHTTP(responseRecorder, r)
-				if status >= 400 {
-					// 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, status)
-					} else {
-						// Default failover error handler
-						responseRecorder.WriteHeader(status)
-						fmt.Fprintf(responseRecorder, "%d %s", status, http.StatusText(status))
-					}
-					status = 0
+		if middleware.Name(state.Name()).Matches(rule.NameScope) {
+			responseRecorder := middleware.NewResponseRecorder(w)
+			rcode, err := l.Next.ServeDNS(ctx, responseRecorder, r)
+			if rcode > 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, rcode)
+				} else {
+					// Default failover error handler
+					answer := new(dns.Msg)
+					answer.SetRcode(r, rcode)
+					w.WriteMsg(answer)
 				}
-				rep := middleware.NewReplacer(r, responseRecorder, CommonLogEmptyValue)
-				rule.Log.Println(rep.Replace(rule.Format))
-				return status, err
+				rcode = 0
 			}
-		*/
-		rule = rule
+			rep := middleware.NewReplacer(r, responseRecorder, CommonLogEmptyValue)
+			rule.Log.Println(rep.Replace(rule.Format))
+			return rcode, err
+
+		}
 	}
 	return l.Next.ServeDNS(ctx, w, r)
 }
 
 // Rule configures the logging middleware.
 type Rule struct {
-	PathScope  string
+	NameScope  string
 	OutputFile string
 	Format     string
 	Log        *log.Logger
@@ -56,13 +56,13 @@ type Rule struct {
 
 const (
 	// DefaultLogFilename is the default log filename.
-	DefaultLogFilename = "access.log"
+	DefaultLogFilename = "query.log"
 	// CommonLogFormat is the common log format.
 	CommonLogFormat = `{remote} ` + CommonLogEmptyValue + ` [{when}] "{type} {name} {proto}" {rcode} {size}`
 	// CommonLogEmptyValue is the common empty log value.
 	CommonLogEmptyValue = "-"
 	// CombinedLogFormat is the combined log format.
-	CombinedLogFormat = CommonLogFormat + ` "{>Referer}" "{>User-Agent}"` // Something here as well
+	CombinedLogFormat = CommonLogFormat + ` "{>opcode}"`
 	// DefaultLogFormat is the default log format.
 	DefaultLogFormat = CommonLogFormat
 )

middleware/log/log_test.go

 package log
 
-/*
+import (
+	"bytes"
+	"log"
+	"strings"
+	"testing"
+
+	"github.com/miekg/coredns/middleware"
+	"github.com/miekg/dns"
+	"golang.org/x/net/context"
+)
+
 type erroringMiddleware struct{}
 
-func (erroringMiddleware) ServeDNS(w dns.ResponseWriter, r *dns.Msg) (int, error) {
-	return http.StatusNotFound, nil
+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{
-		PathScope: "/",
+		NameScope: ".",
 		Format:    DefaultLogFormat,
 		Log:       log.New(&f, "", 0),
 	}
@@ -21,21 +31,19 @@ func TestLoggedStatus(t *testing.T) {
 		Next:  next,
 	}
 
-	r, err := http.NewRequest("GET", "/", nil)
-	if err != nil {
-		t.Fatal(err)
-	}
+	ctx := context.TODO()
+	r := new(dns.Msg)
+	r.SetQuestion("example.org.", dns.TypeA)
 
-	rec := httptest.NewRecorder()
+	rec := middleware.NewResponseRecorder(&middleware.TestResponseWriter{})
 
-	status, err := logger.ServeHTTP(rec, r)
-	if status != 0 {
-		t.Error("Expected status to be 0 - was", status)
+	rcode, _ := logger.ServeDNS(ctx, rec, r)
+	if rcode != 0 {
+		t.Error("Expected rcode to be 0 - was", rcode)
 	}
 
 	logged := f.String()
-	if !strings.Contains(logged, "404 13") {
-		t.Error("Expected 404 to be logged. Logged string -", logged)
+	if !strings.Contains(logged, "A example.org. udp") {
+		t.Error("Expected it to be logged. Logged string -", logged)
 	}
 }
-*/

middleware/name.go

+package middleware
+
+import "strings"
+
+// Name represents a domain name.
+type Name string
+
+// Matches checks to see if other matches n.
+//
+// Name matching will probably not always be a direct
+// comparison; this method assures that names can be
+// easily and consistently matched.
+func (n Name) Matches(other string) bool {
+	return strings.HasSuffix(string(n), other)
+}

middleware/path.go

-package middleware
-
-import "strings"
-
-
-// TODO(miek): matches for names.
-
-// Path represents a URI path, maybe with pattern characters.
-type Path string
-
-// Matches checks to see if other matches p.
-//
-// Path matching will probably not always be a direct
-// comparison; this method assures that paths can be
-// easily and consistently matched.
-func (p Path) Matches(other string) bool {
-	return strings.HasPrefix(string(p), other)
-}

middleware/proxy/upstream.go

@@ -4,12 +4,10 @@ import (
 	"io"
 	"io/ioutil"
 	"net/http"
-	"path"
 	"strconv"
 	"time"
 
 	"github.com/miekg/coredns/core/parse"
-	"github.com/miekg/coredns/middleware"
 )
 
 var (
@@ -226,10 +224,13 @@ func (u *staticUpstream) Select() *UpstreamHost {
 }
 
 func (u *staticUpstream) IsAllowedPath(requestPath string) bool {
-	for _, ignoredSubPath := range u.IgnoredSubPaths {
-		if middleware.Path(path.Clean(requestPath)).Matches(path.Join(u.From(), ignoredSubPath)) {
-			return false
+	/*
+		TODO(miek): fix to use Name
+		for _, ignoredSubPath := range u.IgnoredSubPaths {
+			if middleware.Path(path.Clean(requestPath)).Matches(path.Join(u.From(), ignoredSubPath)) {
+				return false
+			}
 		}
-	}
+	*/
 	return true
 }

middleware/recorder.go

 package middleware
 
 import (
+	"net"
 	"time"
 
 	"github.com/miekg/dns"
@@ -68,3 +69,24 @@ func (r *ResponseRecorder) Hijack() {
 	r.ResponseWriter.Hijack()
 	return
 }
+
+type TestResponseWriter struct{}
+
+func (t *TestResponseWriter) LocalAddr() net.Addr {
+	ip := net.ParseIP("127.0.0.1")
+	port := 53
+	return &net.UDPAddr{IP: ip, Port: port, Zone: ""}
+}
+
+func (t *TestResponseWriter) RemoteAddr() net.Addr {
+	ip := net.ParseIP("10.240.0.1")
+	port := 40212
+	return &net.UDPAddr{IP: ip, Port: port, Zone: ""}
+}
+
+func (t *TestResponseWriter) WriteMsg(m *dns.Msg) error     { return nil }
+func (t *TestResponseWriter) Write(buf []byte) (int, error) { return len(buf), nil }
+func (t *TestResponseWriter) Close() error                  { return nil }
+func (t *TestResponseWriter) TsigStatus() error             { return nil }
+func (t *TestResponseWriter) TsigTimersOnly(bool)           { return }
+func (t *TestResponseWriter) Hijack()                       { return }

middleware/replacer.go

@@ -53,6 +53,11 @@ func NewReplacer(r *dns.Msg, rr *ResponseRecorder, emptyValue string) Replacer {
 		rep.replacements["{latency}"] = time.Since(rr.start).String()
 	}
 
+	// Header placeholders (case-insensitive)
+	// TODO(miek): syntax for flags
+	rep.replacements[headerReplacer+"id}"] = strconv.Itoa(int(r.Id))
+	rep.replacements[headerReplacer+"opcode}"] = strconv.Itoa(int(r.Opcode))
+
 	return rep
 }