logging: unify pkg/log and plugin/log (#2245)

Default to using pkg/log for all logging and use a fixed time prefix
which is RFC3339Millli (doesn't exist in time, so we just extended
RFC3339), i.e. Nano might be pushing it.

Logs go from:

2018/10/30 19:14:55 [INFO] CoreDNS-1.2.5
2018/10/30 19:14:55 [INFO] linux/amd64, go1.11,

to:

2018-10-30T19:10:07.547Z [INFO] CoreDNS-1.2.5
2018-10-30T19:10:07.547Z [INFO] linux/amd64, go1.11,

Which includes the timezone - which oddly the std log package doesn't
natively do.

Signed-off-by: Miek Gieben <miek@miek.nl>

plugin/log/README.md

@@ -7,9 +7,10 @@
 ## Description
 
 By just using *log* you dump all queries (and parts for the reply) on standard output. Options exist
-to tweak the output a little.
+to tweak the output a little. The date/time prefix on log lines is RFC3339 formatted with
+milliseconds.
 
-Note that for busy servers this will incur a performance hit.
+Note that for busy servers logging will incur a performance hit.
 
 ## Syntax
 
@@ -59,7 +60,6 @@ The following place holders are supported:
 * `{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, for IPv6 addresses these are enclosed in brackets: `[::1]`
 * `{size}`: request size in bytes
 * `{port}`: client's port
@@ -76,9 +76,15 @@ The following place holders are supported:
 The default Common Log Format is:
 
 ~~~ txt
-`{remote}:{port} - [{when}] {>id} "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {>rflags} {rsize} {duration}`
+`{remote}:{port} - {>id} "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {>rflags} {rsize} {duration}`
 ~~~
 
+Each of these logs will be outputted with `log.Infof`, so a typical example looks like this:
+
+~~~ txt
+2018-10-30T19:10:07.547Z [INFO] [::1]:50759 - 29008 "A IN example.org. udp 41 false 4096" NOERROR qr,rd,ra,ad 68 0.037990251s
+~~~~
+
 ## Examples
 
 Log all requests to stdout

plugin/log/log.go

@@ -3,12 +3,12 @@ package log
 
 import (
 	"context"
-	"log"
 	"time"
 
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/metrics/vars"
 	"github.com/coredns/coredns/plugin/pkg/dnstest"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/pkg/rcode"
 	"github.com/coredns/coredns/plugin/pkg/replacer"
 	"github.com/coredns/coredns/plugin/pkg/response"
@@ -58,7 +58,7 @@ func (l Logger) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg)
 		// and we shouldn't have an empty rule.Class.
 		if rule.Class[response.All] || rule.Class[class] {
 			rep := replacer.New(r, rrw, CommonLogEmptyValue)
-			rule.Log.Println(rep.Replace(rule.Format))
+			clog.Infof(rep.Replace(rule.Format))
 		}
 
 		return rc, err
@@ -75,12 +75,11 @@ type Rule struct {
 	NameScope string
 	Class     map[response.Class]bool
 	Format    string
-	Log       *log.Logger
 }
 
 const (
 	// CommonLogFormat is the common log format.
-	CommonLogFormat = `{remote}:{port} ` + CommonLogEmptyValue + ` [{when}] {>id} "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {>rflags} {rsize} {duration}`
+	CommonLogFormat = `{remote}:{port} ` + CommonLogEmptyValue + ` {>id} "{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.

plugin/log/log_test.go

@@ -18,14 +18,15 @@ import (
 func init() { clog.Discard() }
 
 func TestLoggedStatus(t *testing.T) {
-	var f bytes.Buffer
 	rule := Rule{
 		NameScope: ".",
 		Format:    DefaultLogFormat,
-		Log:       log.New(&f, "", 0),
 		Class:     map[response.Class]bool{response.All: true},
 	}
 
+	var f bytes.Buffer
+	log.SetOutput(&f)
+
 	logger := Logger{
 		Rules: []Rule{rule},
 		Next:  test.ErrorHandler(),
@@ -49,14 +50,15 @@ func TestLoggedStatus(t *testing.T) {
 }
 
 func TestLoggedClassDenial(t *testing.T) {
-	var f bytes.Buffer
 	rule := Rule{
 		NameScope: ".",
 		Format:    DefaultLogFormat,
-		Log:       log.New(&f, "", 0),
 		Class:     map[response.Class]bool{response.Denial: true},
 	}
 
+	var f bytes.Buffer
+	log.SetOutput(&f)
+
 	logger := Logger{
 		Rules: []Rule{rule},
 		Next:  test.ErrorHandler(),
@@ -77,14 +79,15 @@ func TestLoggedClassDenial(t *testing.T) {
 }
 
 func TestLoggedClassError(t *testing.T) {
-	var f bytes.Buffer
 	rule := Rule{
 		NameScope: ".",
 		Format:    DefaultLogFormat,
-		Log:       log.New(&f, "", 0),
 		Class:     map[response.Class]bool{response.Error: true},
 	}
 
+	var f bytes.Buffer
+	log.SetOutput(&f)
+
 	logger := Logger{
 		Rules: []Rule{rule},
 		Next:  test.ErrorHandler(),

plugin/log/setup.go

@@ -1,9 +1,6 @@
 package log
 
 import (
-	"log"
-	"os"
-
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/pkg/response"
@@ -25,15 +22,6 @@ func setup(c *caddy.Controller) error {
 		return plugin.Error("log", err)
 	}
 
-	// Open the log files for writing when the server starts
-	c.OnStartup(func() error {
-		for i := 0; i < len(rules); i++ {
-			rules[i].Log = log.New(os.Stdout, "", 0)
-		}
-
-		return nil
-	})
-
 	dnsserver.GetConfig(c).AddPlugin(func(next plugin.Handler) plugin.Handler {
 		return Logger{Next: next, Rules: rules, ErrorFunc: dnsserver.DefaultErrorFunc}
 	})