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

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

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",

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"
 )

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"
 

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",

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"

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",

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

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",

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",

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"
 

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"

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 {

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"
 

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.

plugin/file/secondary.go

@@ -4,8 +4,6 @@ import (
 	"math/rand"
 	"time"
 
-	"github.com/coredns/coredns/plugin/pkg/log"
-
 	"github.com/miekg/dns"
 )
 

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"

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

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",

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 {

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().

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"

plugin/loadbalance/loadbalance.go

@@ -2,8 +2,6 @@
 package loadbalance
 
 import (
-	"github.com/coredns/coredns/plugin/pkg/log"
-
 	"github.com/miekg/dns"
 )
 

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",

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"

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",

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...)

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") {

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 {

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() {

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"

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"
 

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",

plugin/reload/reload.go

@@ -4,8 +4,6 @@ import (
 	"crypto/md5"
 	"time"
 
-	"github.com/coredns/coredns/plugin/pkg/log"
-
 	"github.com/mholt/caddy"
 )
 

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",

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",