Use logging (#1718)

* update docs

* plugins: use plugin specific logging

Hooking up pkg/log also changed NewWithPlugin to just take a string
instead of a plugin.Handler as that is more flexible and for instance
the Root "plugin" doesn't implement it fully.

Same logging from the reload plugin:

.:1043
2018/04/22 08:56:37 [INFO] CoreDNS-1.1.1
2018/04/22 08:56:37 [INFO] linux/amd64, go1.10.1,
CoreDNS-1.1.1
linux/amd64, go1.10.1,
2018/04/22 08:56:37 [INFO] plugin/reload: Running configuration MD5 = ec4c9c55cd19759ea1c46b8c45742b06
2018/04/22 08:56:54 [INFO] Reloading
2018/04/22 08:56:54 [INFO] plugin/reload: Running configuration MD5 = 9e2bfdd85bdc9cceb740ba9c80f34c1a
2018/04/22 08:56:54 [INFO] Reloading complete

* update docs

* better doc

36 files changed, 61 insertions, 45 deletions

diff --git a/plugin.md b/plugin.md
index e94de6d1c..49b32236f 100644
--- a/plugin.md
+++ b/plugin.md
@@ -38,7 +38,15 @@ See a couple of blog posts on how to write and add plugin to CoreDNS:
 If your plugin needs to output a log line you should use the `plugin/pkg/log` package. This package
 implements log levels. The standard way of outputting is: `log.Info` for info level messages. The
 levels available are `log.Info`, `log.Warning`, `log.Error`, `log.Debug`. Each of these also has
-a `f` variant.
+a `f` variant. The plugin's name should be included, by using the log package like so:
+
+~~~ go
+import clog "github.com/coredns/coredns/plugin/pkg/log"
+
+var log = clog.NewWithPlugin("whoami")
+
+log.Info("message") // outputs: [INFO] plugin/whoami: message
+~~~
 
 In general, logging should be left to the higher layers by returning an error. However, if there is
 a reason to consume the error and notify the user, then logging in the plugin itself can be
diff --git a/plugin/auto/setup.go b/plugin/auto/setup.go
index ddb2c2d2a..8f087e899 100644
--- a/plugin/auto/setup.go
+++ b/plugin/auto/setup.go
@@ -10,13 +10,15 @@ import (
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/metrics"
-	"github.com/coredns/coredns/plugin/pkg/log"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/pkg/parse"
 	"github.com/coredns/coredns/plugin/pkg/upstream"
 
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("auto")
+
 func init() {
 	caddy.RegisterPlugin("auto", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/auto/walk.go b/plugin/auto/walk.go
index 6ad06569f..351210509 100644
--- a/plugin/auto/walk.go
+++ b/plugin/auto/walk.go
@@ -7,7 +7,6 @@ import (
 	"regexp"
 
 	"github.com/coredns/coredns/plugin/file"
-	"github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/miekg/dns"
 )
diff --git a/plugin/cache/cache.go b/plugin/cache/cache.go
index f27c0c9d3..12cbdb9ed 100644
--- a/plugin/cache/cache.go
+++ b/plugin/cache/cache.go
@@ -8,7 +8,6 @@ import (
 
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/pkg/cache"
-	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/pkg/response"
 	"github.com/coredns/coredns/request"
 
diff --git a/plugin/cache/setup.go b/plugin/cache/setup.go
index 8fe8eb59c..57233bd66 100644
--- a/plugin/cache/setup.go
+++ b/plugin/cache/setup.go
@@ -9,10 +9,13 @@ import (
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/metrics"
 	"github.com/coredns/coredns/plugin/pkg/cache"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("cache")
+
 func init() {
 	caddy.RegisterPlugin("cache", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/dnssec/responsewriter.go b/plugin/dnssec/responsewriter.go
index e3bb75800..c3dcc581e 100644
--- a/plugin/dnssec/responsewriter.go
+++ b/plugin/dnssec/responsewriter.go
@@ -4,7 +4,6 @@ import (
 	"time"
 
 	"github.com/coredns/coredns/plugin"
-	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
diff --git a/plugin/dnssec/setup.go b/plugin/dnssec/setup.go
index 2f82315f8..0d3dabb0d 100644
--- a/plugin/dnssec/setup.go
+++ b/plugin/dnssec/setup.go
@@ -9,10 +9,13 @@ import (
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/metrics"
 	"github.com/coredns/coredns/plugin/pkg/cache"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("dnssec")
+
 func init() {
 	caddy.RegisterPlugin("dnssec", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/dnstap/dnstapio/io.go b/plugin/dnstap/dnstapio/io.go
index a6f0442a0..65e2e222e 100644
--- a/plugin/dnstap/dnstapio/io.go
+++ b/plugin/dnstap/dnstapio/io.go
@@ -5,12 +5,14 @@ import (
 	"sync/atomic"
 	"time"
 
-	"github.com/coredns/coredns/plugin/pkg/log"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	tap "github.com/dnstap/golang-dnstap"
 	fs "github.com/farsightsec/golang-framestream"
 )
 
+var log = clog.NewWithPlugin("dnstap")
+
 const (
 	tcpWriteBufSize = 1024 * 1024
 	tcpTimeout      = 4 * time.Second
diff --git a/plugin/dnstap/setup.go b/plugin/dnstap/setup.go
index d071710e7..c7050b35c 100644
--- a/plugin/dnstap/setup.go
+++ b/plugin/dnstap/setup.go
@@ -7,11 +7,14 @@ import (
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/dnstap/dnstapio"
 	"github.com/coredns/coredns/plugin/pkg/dnsutil"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 	"github.com/mholt/caddy/caddyfile"
 )
 
+var log = clog.NewWithPlugin("dnstap")
+
 func init() {
 	caddy.RegisterPlugin("dnstap", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/etcd/setup.go b/plugin/etcd/setup.go
index 6b83ebc37..e8d91a605 100644
--- a/plugin/etcd/setup.go
+++ b/plugin/etcd/setup.go
@@ -6,6 +6,7 @@ import (
 
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 	mwtls "github.com/coredns/coredns/plugin/pkg/tls"
 	"github.com/coredns/coredns/plugin/pkg/upstream"
 	"github.com/coredns/coredns/plugin/proxy"
@@ -14,6 +15,8 @@ import (
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("etcd")
+
 func init() {
 	caddy.RegisterPlugin("etcd", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/etcd/stub.go b/plugin/etcd/stub.go
index 683217733..c270bcd2b 100644
--- a/plugin/etcd/stub.go
+++ b/plugin/etcd/stub.go
@@ -7,7 +7,6 @@ import (
 
 	"github.com/coredns/coredns/plugin/etcd/msg"
 	"github.com/coredns/coredns/plugin/pkg/dnsutil"
-	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/proxy"
 	"github.com/coredns/coredns/request"
 
diff --git a/plugin/etcd/stub_handler.go b/plugin/etcd/stub_handler.go
index 92a0103c5..ac533f810 100644
--- a/plugin/etcd/stub_handler.go
+++ b/plugin/etcd/stub_handler.go
@@ -4,7 +4,6 @@ import (
 	"context"
 	"errors"
 
-	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
diff --git a/plugin/file/file.go b/plugin/file/file.go
index cc77da81c..1f27c582d 100644
--- a/plugin/file/file.go
+++ b/plugin/file/file.go
@@ -7,12 +7,14 @@ import (
 	"io"
 
 	"github.com/coredns/coredns/plugin"
-	"github.com/coredns/coredns/plugin/pkg/log"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
 )
 
+var log = clog.NewWithPlugin("file")
+
 type (
 	// File is the plugin that reads zone data from disk.
 	File struct {
diff --git a/plugin/file/notify.go b/plugin/file/notify.go
index e7ea0dd78..ce6a0b095 100644
--- a/plugin/file/notify.go
+++ b/plugin/file/notify.go
@@ -4,7 +4,6 @@ import (
 	"fmt"
 	"net"
 
-	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/pkg/rcode"
 	"github.com/coredns/coredns/request"
 
diff --git a/plugin/file/reload.go b/plugin/file/reload.go
index 28e85b5eb..af06b98ac 100644
--- a/plugin/file/reload.go
+++ b/plugin/file/reload.go
@@ -3,8 +3,6 @@ package file
 import (
 	"os"
 	"time"
-
-	"github.com/coredns/coredns/plugin/pkg/log"
 )
 
 // TickTime is the default time we use to reload zone. Exported to be tweaked in tests.
diff --git a/plugin/file/secondary.go b/plugin/file/secondary.go
index 5874b62fc..dc732ee66 100644
--- a/plugin/file/secondary.go
+++ b/plugin/file/secondary.go
@@ -4,8 +4,6 @@ import (
 	"math/rand"
 	"time"
 
-	"github.com/coredns/coredns/plugin/pkg/log"
-
 	"github.com/miekg/dns"
 )
 
diff --git a/plugin/file/xfr.go b/plugin/file/xfr.go
index af179ac4e..3ad380902 100644
--- a/plugin/file/xfr.go
+++ b/plugin/file/xfr.go
@@ -5,7 +5,6 @@ import (
 	"fmt"
 
 	"github.com/coredns/coredns/plugin"
-	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
diff --git a/plugin/health/health.go b/plugin/health/health.go
index 782099154..7f35b0709 100644
--- a/plugin/health/health.go
+++ b/plugin/health/health.go
@@ -8,9 +8,11 @@ import (
 	"sync"
 	"time"
 
-	"github.com/coredns/coredns/plugin/pkg/log"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 )
 
+var log = clog.NewWithPlugin("health")
+
 // Health implements healthchecks by polling plugins.
 type health struct {
 	Addr     string
diff --git a/plugin/hosts/setup.go b/plugin/hosts/setup.go
index 3197a5289..ed5cd5c7a 100644
--- a/plugin/hosts/setup.go
+++ b/plugin/hosts/setup.go
@@ -8,11 +8,13 @@ import (
 
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
-	"github.com/coredns/coredns/plugin/pkg/log"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("hosts")
+
 func init() {
 	caddy.RegisterPlugin("hosts", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/kubernetes/apiproxy.go b/plugin/kubernetes/apiproxy.go
index a4d25879f..305522cbe 100644
--- a/plugin/kubernetes/apiproxy.go
+++ b/plugin/kubernetes/apiproxy.go
@@ -7,7 +7,6 @@ import (
 	"net/http"
 
 	"github.com/coredns/coredns/plugin/pkg/healthcheck"
-	"github.com/coredns/coredns/plugin/pkg/log"
 )
 
 type proxyHandler struct {
diff --git a/plugin/kubernetes/setup.go b/plugin/kubernetes/setup.go
index db55ba71f..c637ed96c 100644
--- a/plugin/kubernetes/setup.go
+++ b/plugin/kubernetes/setup.go
@@ -12,6 +12,7 @@ import (
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/pkg/dnsutil"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/pkg/parse"
 	"github.com/coredns/coredns/plugin/pkg/upstream"
 
@@ -20,6 +21,8 @@ import (
 	meta "k8s.io/apimachinery/pkg/apis/meta/v1"
 )
 
+var log = clog.NewWithPlugin("kubernetes")
+
 func init() {
 	// Kubernetes plugin uses the kubernetes library, which uses glog (ugh), we must set this *flag*,
 	// so we don't log to the filesystem, which can fill up and crash CoreDNS indirectly by calling os.Exit().
diff --git a/plugin/kubernetes/xfr.go b/plugin/kubernetes/xfr.go
index df1058dda..afee4aa20 100644
--- a/plugin/kubernetes/xfr.go
+++ b/plugin/kubernetes/xfr.go
@@ -8,7 +8,6 @@ import (
 
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/etcd/msg"
-	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
diff --git a/plugin/loadbalance/loadbalance.go b/plugin/loadbalance/loadbalance.go
index 56672092e..031f841f4 100644
--- a/plugin/loadbalance/loadbalance.go
+++ b/plugin/loadbalance/loadbalance.go
@@ -2,8 +2,6 @@
 package loadbalance
 
 import (
-	"github.com/coredns/coredns/plugin/pkg/log"
-
 	"github.com/miekg/dns"
 )
 
diff --git a/plugin/loadbalance/setup.go b/plugin/loadbalance/setup.go
index c2d90958e..38dce6308 100644
--- a/plugin/loadbalance/setup.go
+++ b/plugin/loadbalance/setup.go
@@ -3,9 +3,13 @@ package loadbalance
 import (
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
+
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("loadbalance")
+
 func init() {
 	caddy.RegisterPlugin("loadbalance", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/metrics/metrics.go b/plugin/metrics/metrics.go
index b989ccc2f..e183d33d5 100644
--- a/plugin/metrics/metrics.go
+++ b/plugin/metrics/metrics.go
@@ -9,7 +9,6 @@ import (
 
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/metrics/vars"
-	"github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
diff --git a/plugin/metrics/setup.go b/plugin/metrics/setup.go
index 2aff8ec5c..52d5775c1 100644
--- a/plugin/metrics/setup.go
+++ b/plugin/metrics/setup.go
@@ -7,10 +7,13 @@ import (
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/coremain"
 	"github.com/coredns/coredns/plugin"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("prometheus")
+
 func init() {
 	caddy.RegisterPlugin("prometheus", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/pkg/log/plugin.go b/plugin/pkg/log/plugin.go
index c79d657c7..354c19d3f 100644
--- a/plugin/pkg/log/plugin.go
+++ b/plugin/pkg/log/plugin.go
@@ -3,8 +3,6 @@ package log
 import (
 	"fmt"
 	golog "log"
-
-	"github.com/coredns/coredns/plugin"
 )
 
 // P is a logger that includes the plugin doing the logging.
@@ -12,9 +10,9 @@ type P struct {
 	plugin string
 }
 
-// NewWithPlugin return a logger that shows the plugin that logs the message.
+// NewWithPlugin returns a logger that includes "plugin/name: " in the log message.
 // I.e [INFO] plugin/<name>: message.
-func NewWithPlugin(h plugin.Handler) P { return P{h.Name()} }
+func NewWithPlugin(name string) P { return P{name} }
 
 func (p P) logf(level, format string, v ...interface{}) {
 	s := level + pFormat(p.plugin) + fmt.Sprintf(format, v...)
diff --git a/plugin/pkg/log/plugin_test.go b/plugin/pkg/log/plugin_test.go
index a7799322e..b24caa48b 100644
--- a/plugin/pkg/log/plugin_test.go
+++ b/plugin/pkg/log/plugin_test.go
@@ -2,28 +2,17 @@ package log
 
 import (
 	"bytes"
-	"context"
 	golog "log"
 	"strings"
 	"testing"
-
-	"github.com/miekg/dns"
 )
 
-type p struct{}
-
-func (p p) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) {
-	return 0, nil
-}
-
-func (p p) Name() string { return "testplugin" }
-
 func TestPlugins(t *testing.T) {
 	var f bytes.Buffer
 	const ts = "test"
 	golog.SetOutput(&f)
 
-	lg := NewWithPlugin(p{})
+	lg := NewWithPlugin("testplugin")
 
 	lg.Info(ts)
 	if x := f.String(); !strings.Contains(x, "plugin/testplugin") {
diff --git a/plugin/pprof/pprof.go b/plugin/pprof/pprof.go
index d85053701..6cfaa5490 100644
--- a/plugin/pprof/pprof.go
+++ b/plugin/pprof/pprof.go
@@ -6,8 +6,6 @@ import (
 	"net"
 	"net/http"
 	pp "net/http/pprof"
-
-	"github.com/coredns/coredns/plugin/pkg/log"
 )
 
 type handler struct {
diff --git a/plugin/pprof/setup.go b/plugin/pprof/setup.go
index ea5e9ce4d..cdc346374 100644
--- a/plugin/pprof/setup.go
+++ b/plugin/pprof/setup.go
@@ -5,10 +5,13 @@ import (
 	"sync"
 
 	"github.com/coredns/coredns/plugin"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("pprof")
+
 const defaultAddr = "localhost:6053"
 
 func init() {
diff --git a/plugin/proxy/google.go b/plugin/proxy/google.go
index 9fc824092..2c265ba4f 100644
--- a/plugin/proxy/google.go
+++ b/plugin/proxy/google.go
@@ -12,7 +12,6 @@ import (
 	"time"
 
 	"github.com/coredns/coredns/plugin/pkg/healthcheck"
-	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
diff --git a/plugin/proxy/grpc.go b/plugin/proxy/grpc.go
index 905fa729d..dc388c91e 100644
--- a/plugin/proxy/grpc.go
+++ b/plugin/proxy/grpc.go
@@ -6,7 +6,6 @@ import (
 	"fmt"
 
 	"github.com/coredns/coredns/pb"
-	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/pkg/trace"
 	"github.com/coredns/coredns/request"
 
diff --git a/plugin/proxy/setup.go b/plugin/proxy/setup.go
index 268579751..279e02cac 100644
--- a/plugin/proxy/setup.go
+++ b/plugin/proxy/setup.go
@@ -4,10 +4,13 @@ import (
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/metrics"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("proxy")
+
 func init() {
 	caddy.RegisterPlugin("proxy", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/reload/reload.go b/plugin/reload/reload.go
index c1803c89d..d04bb037b 100644
--- a/plugin/reload/reload.go
+++ b/plugin/reload/reload.go
@@ -4,8 +4,6 @@ import (
 	"crypto/md5"
 	"time"
 
-	"github.com/coredns/coredns/plugin/pkg/log"
-
 	"github.com/mholt/caddy"
 )
 
diff --git a/plugin/reload/setup.go b/plugin/reload/setup.go
index 08b70e5ed..c6b33e959 100644
--- a/plugin/reload/setup.go
+++ b/plugin/reload/setup.go
@@ -7,10 +7,13 @@ import (
 	"time"
 
 	"github.com/coredns/coredns/plugin"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("reload")
+
 func init() {
 	caddy.RegisterPlugin("reload", caddy.Plugin{
 		ServerType: "dns",
diff --git a/plugin/root/root.go b/plugin/root/root.go
index a4f8ef808..6b73cfb27 100644
--- a/plugin/root/root.go
+++ b/plugin/root/root.go
@@ -5,11 +5,13 @@ import (
 
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
-	"github.com/coredns/coredns/plugin/pkg/log"
+	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
 
+var log = clog.NewWithPlugin("root")
+
 func init() {
 	caddy.RegisterPlugin("root", caddy.Plugin{
 		ServerType: "dns",