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>

7 files changed, 45 insertions, 49 deletions

diff --git a/coremain/run.go b/coremain/run.go
index 033f60077..63ac6f354 100644
--- a/coremain/run.go
+++ b/coremain/run.go
@@ -62,7 +62,7 @@ func Run() {
 	}
 
 	log.SetOutput(os.Stdout)
-	log.SetFlags(log.LstdFlags)
+	log.SetFlags(0) // Set to 0 because we're doing our own time, with timezone
 
 	if version {
 		showVersion()
diff --git a/plugin/log/README.md b/plugin/log/README.md
index 65cca19c8..8ecc39680 100644
--- a/plugin/log/README.md
+++ b/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
diff --git a/plugin/log/log.go b/plugin/log/log.go
index f52a70344..685c55191 100644
--- a/plugin/log/log.go
+++ b/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.
diff --git a/plugin/log/log_test.go b/plugin/log/log_test.go
index d1ff8d36d..6d74f23ad 100644
--- a/plugin/log/log_test.go
+++ b/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(),
diff --git a/plugin/log/setup.go b/plugin/log/setup.go
index 1f9501d68..c3c1af4ca 100644
--- a/plugin/log/setup.go
+++ b/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}
 	})
diff --git a/plugin/pkg/log/log.go b/plugin/pkg/log/log.go
index f05dce03a..2c8971e1d 100644
--- a/plugin/pkg/log/log.go
+++ b/plugin/pkg/log/log.go
@@ -1,11 +1,11 @@
 // Package log implements a small wrapper around the std lib log package.
-// It implements log levels by prefixing the logs with [INFO], [DEBUG],
-// [WARNING] or [ERROR].
+// It implements log levels by prefixing the logs with the current time
+// with in RFC3339Milli and [INFO], [DEBUG], [WARNING] or [ERROR].
 // Debug logging is available and enabled if the *debug* plugin is used.
 //
 // log.Info("this is some logging"), will log on the Info level.
 //
-// log.Debug("this is debug output"), will log in the Debug level.
+// log.Debug("this is debug output"), will log in the Debug level, etc.
 package log
 
 import (
@@ -13,19 +13,24 @@ import (
 	"io/ioutil"
 	golog "log"
 	"os"
+	"time"
 )
 
 // D controls whether we should output debug logs. If true, we do.
 var D bool
 
+// RFC3339Milli doesn't exist, invent it here.
+func clock() string { return time.Now().Format("2006-01-02T15:04:05.999Z07:00") }
+
 // logf calls log.Printf prefixed with level.
 func logf(level, format string, v ...interface{}) {
-	s := level + fmt.Sprintf(format, v...)
-	golog.Print(s)
+	golog.Print(clock(), level, fmt.Sprintf(format, v...))
 }
 
 // log calls log.Print prefixed with level.
-func log(level string, v ...interface{}) { s := level + fmt.Sprint(v...); golog.Print(s) }
+func log(level string, v ...interface{}) {
+	golog.Print(clock(), level, fmt.Sprint(v...))
+}
 
 // Debug is equivalent to log.Print(), but prefixed with "[DEBUG] ". It only outputs something
 // if D is true.
@@ -75,9 +80,9 @@ func Fatalf(format string, v ...interface{}) { logf(fatal, format, v...); os.Exi
 func Discard() { golog.SetOutput(ioutil.Discard) }
 
 const (
-	debug   = "[DEBUG] "
-	err     = "[ERROR] "
-	fatal   = "[FATAL] "
-	info    = "[INFO] "
-	warning = "[WARNING] "
+	debug   = " [DEBUG] "
+	err     = " [ERROR] "
+	fatal   = " [FATAL] "
+	info    = " [INFO] "
+	warning = " [WARNING] "
 )
diff --git a/plugin/pkg/replacer/replacer.go b/plugin/pkg/replacer/replacer.go
index b9e1fcaa6..695e9e392 100644
--- a/plugin/pkg/replacer/replacer.go
+++ b/plugin/pkg/replacer/replacer.go
@@ -35,13 +35,11 @@ func New(r *dns.Msg, rr *dnstest.Recorder, emptyValue string) Replacer {
 	req := request.Request{W: rr, Req: r}
 	rep := replacer{
 		replacements: map[string]string{
-			"{type}":  req.Type(),
-			"{name}":  req.Name(),
-			"{class}": req.Class(),
-			"{proto}": req.Proto(),
-			"{when}": func() string {
-				return time.Now().Format(timeFormat)
-			}(),
+			"{type}":   req.Type(),
+			"{name}":   req.Name(),
+			"{class}":  req.Class(),
+			"{proto}":  req.Proto(),
+			"{when}":   "", // made a noop
 			"{size}":   strconv.Itoa(req.Len()),
 			"{remote}": addrToRFC3986(req.IP()),
 			"{port}":   req.Port(),
@@ -163,7 +161,4 @@ func addrToRFC3986(addr string) string {
 	return addr
 }
 
-const (
-	timeFormat     = "02/Jan/2006:15:04:05 -0700"
-	headerReplacer = "{>"
-)
+const headerReplacer = "{>"