Update all plugins to use plugin/pkg/log (#1694)

* Update all plugins to use plugin/pkg/log

I wish this could have been done with sed. Alas manually changed all
callers to use the new plugin/pkg/log package.

* Error -> Info

* Add docs to debug plugin as well

plugin/auto/setup.go

@@ -1,7 +1,6 @@
 package auto
 
 import (
-	"log"
 	"os"
 	"path"
 	"regexp"
@@ -11,6 +10,7 @@ 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"
 	"github.com/coredns/coredns/plugin/pkg/parse"
 	"github.com/coredns/coredns/plugin/pkg/upstream"
 
@@ -108,7 +108,7 @@ func autoParse(c *caddy.Controller) (Auto, error) {
 				_, err := os.Stat(a.loader.directory)
 				if err != nil {
 					if os.IsNotExist(err) {
-						log.Printf("[WARNING] Directory does not exist: %s", a.loader.directory)
+						log.Warningf("Directory does not exist: %s", a.loader.directory)
 					} else {
 						return a, c.Errf("Unable to access root path '%s': %v", a.loader.directory, err)
 					}

plugin/auto/walk.go

@@ -1,13 +1,13 @@
 package auto
 
 import (
-	"log"
 	"os"
 	"path"
 	"path/filepath"
 	"regexp"
 
 	"github.com/coredns/coredns/plugin/file"
+	"github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/miekg/dns"
 )
@@ -40,7 +40,7 @@ func (a Auto) Walk() error {
 
 		reader, err := os.Open(path)
 		if err != nil {
-			log.Printf("[WARNING] Opening %s failed: %s", path, err)
+			log.Warningf("Opening %s failed: %s", path, err)
 			return nil
 		}
 		defer reader.Close()
@@ -48,7 +48,7 @@ func (a Auto) Walk() error {
 		// Serial for loading a zone is 0, because it is a new zone.
 		zo, err := file.Parse(reader, origin, path, 0)
 		if err != nil {
-			log.Printf("[WARNING] Parse zone `%s': %v", origin, err)
+			log.Warningf("Parse zone `%s': %v", origin, err)
 			return nil
 		}
 
@@ -64,7 +64,7 @@ func (a Auto) Walk() error {
 
 		zo.Notify()
 
-		log.Printf("[INFO] Inserting zone `%s' from: %s", origin, path)
+		log.Infof("Inserting zone `%s' from: %s", origin, path)
 
 		toDelete[origin] = false
 
@@ -82,7 +82,7 @@ func (a Auto) Walk() error {
 
 		a.Zones.Remove(origin)
 
-		log.Printf("[INFO] Deleting zone `%s'", origin)
+		log.Infof("Deleting zone `%s'", origin)
 	}
 
 	return nil

plugin/auto/walk_test.go

@@ -2,7 +2,6 @@ package auto
 
 import (
 	"io/ioutil"
-	"log"
 	"os"
 	"path"
 	"regexp"
@@ -20,8 +19,6 @@ www IN A 127.0.0.1
 `
 
 func TestWalk(t *testing.T) {
-	log.SetOutput(ioutil.Discard)
-
 	tempdir, err := createFiles()
 	if err != nil {
 		if tempdir != "" {
@@ -53,8 +50,6 @@ func TestWalk(t *testing.T) {
 }
 
 func TestWalkNonExistent(t *testing.T) {
-	log.SetOutput(ioutil.Discard)
-
 	nonExistingDir := "highly_unlikely_to_exist_dir"
 
 	ldr := loader{

plugin/auto/watcher_test.go

@@ -1,8 +1,6 @@
 package auto
 
 import (
-	"io/ioutil"
-	"log"
 	"os"
 	"path"
 	"regexp"
@@ -10,8 +8,6 @@ import (
 )
 
 func TestWatcher(t *testing.T) {
-	log.SetOutput(ioutil.Discard)
-
 	tempdir, err := createFiles()
 	if err != nil {
 		if tempdir != "" {

plugin/cache/cache.go

@@ -4,11 +4,11 @@ package cache
 import (
 	"encoding/binary"
 	"hash/fnv"
-	"log"
 	"time"
 
 	"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"
 
@@ -178,13 +178,13 @@ func (w *ResponseWriter) set(m *dns.Msg, key int, mt response.Type, duration tim
 	case response.OtherError:
 		// don't cache these
 	default:
-		log.Printf("[WARNING] Caching called with unknown classification: %d", mt)
+		log.Warningf("Caching called with unknown classification: %d", mt)
 	}
 }
 
 // Write implements the dns.ResponseWriter interface.
 func (w *ResponseWriter) Write(buf []byte) (int, error) {
-	log.Print("[WARNING] Caching called with Write: not caching reply")
+	log.Warning("Caching called with Write: not caching reply")
 	if w.prefetch {
 		return 0, nil
 	}

plugin/cache/cache_test.go

@@ -1,8 +1,6 @@
 package cache
 
 import (
-	"io/ioutil"
-	"log"
 	"testing"
 	"time"
 
@@ -162,8 +160,6 @@ func TestCache(t *testing.T) {
 
 	c, crr := newTestCache(maxTTL)
 
-	log.SetOutput(ioutil.Discard)
-
 	for _, tc := range cacheTestCases {
 		m := tc.in.Msg()
 		m = cacheMsg(m, tc)

plugin/debug/README.md

@@ -7,7 +7,8 @@
 ## Description
 
 Normally CoreDNS will recover from panics, using *debug* inhibits this. The main use of *debug* is
-to help testing.
+to help testing. A side effect of using *debug* is that `log.Debug` and `log.Debugf` will be printed
+to standard output.
 
 Note that the *errors* plugin (if loaded) will also set a `recover` negating this setting. 
 
@@ -19,7 +20,7 @@ debug
 
 ## Examples
 
-Disable the ability to recover from crashes:
+Disable the ability to recover from crashes and show debug logging:
 
 ~~~ corefile
 . {

plugin/debug/debug_test.go

@@ -1,8 +1,6 @@
 package debug
 
 import (
-	"io/ioutil"
-	"log"
 	"testing"
 
 	"github.com/coredns/coredns/core/dnsserver"
@@ -11,8 +9,6 @@ import (
 )
 
 func TestDebug(t *testing.T) {
-	log.SetOutput(ioutil.Discard)
-
 	tests := []struct {
 		input         string
 		shouldErr     bool

plugin/dnssec/responsewriter.go

@@ -1,10 +1,10 @@
 package dnssec
 
 import (
-	"log"
 	"time"
 
 	"github.com/coredns/coredns/plugin"
+	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
@@ -40,7 +40,7 @@ func (d *ResponseWriter) WriteMsg(res *dns.Msg) error {
 
 // Write implements the dns.ResponseWriter interface.
 func (d *ResponseWriter) Write(buf []byte) (int, error) {
-	log.Print("[WARNING] Dnssec called with Write: not signing reply")
+	log.Warning("Dnssec called with Write: not signing reply")
 	n, err := d.ResponseWriter.Write(buf)
 	return n, err
 }

plugin/dnstap/dnstapio/io.go

@@ -1,11 +1,12 @@
 package dnstapio
 
 import (
-	"log"
 	"net"
 	"sync/atomic"
 	"time"
 
+	"github.com/coredns/coredns/plugin/pkg/log"
+
 	tap "github.com/dnstap/golang-dnstap"
 	fs "github.com/farsightsec/golang-framestream"
 )
@@ -70,7 +71,7 @@ func (dio *dnstapIO) newConnect() error {
 // Connect connects to the dnstop endpoint.
 func (dio *dnstapIO) Connect() {
 	if err := dio.newConnect(); err != nil {
-		log.Print("[ERROR] No connection to dnstap endpoint")
+		log.Error("No connection to dnstap endpoint")
 	}
 	go dio.serve()
 }
@@ -102,16 +103,16 @@ func (dio *dnstapIO) flushBuffer() {
 		if err := dio.newConnect(); err != nil {
 			return
 		}
-		log.Print("[INFO] Reconnected to dnstap")
+		log.Info("Reconnected to dnstap")
 	}
 
 	if err := dio.enc.flushBuffer(); err != nil {
-		log.Printf("[WARN] Connection lost: %s", err)
+		log.Warningf("Connection lost: %s", err)
 		dio.closeConnection()
 		if err := dio.newConnect(); err != nil {
-			log.Printf("[ERROR] Cannot connect to dnstap: %s", err)
+			log.Errorf("Cannot connect to dnstap: %s", err)
 		} else {
-			log.Print("[INFO] Reconnected to dnstap")
+			log.Info("Reconnected to dnstap")
 		}
 	}
 }
@@ -134,7 +135,7 @@ func (dio *dnstapIO) serve() {
 			dio.write(&payload)
 		case <-timeout:
 			if dropped := atomic.SwapUint32(&dio.dropped, 0); dropped > 0 {
-				log.Printf("[WARN] Dropped dnstap messages: %d", dropped)
+				log.Warningf("Dropped dnstap messages: %d", dropped)
 			}
 			dio.flushBuffer()
 			timeout = time.After(flushTimeout)

plugin/etcd/stub.go

@@ -1,13 +1,13 @@
 package etcd
 
 import (
-	"log"
 	"net"
 	"strconv"
 	"time"
 
 	"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"
 
@@ -50,7 +50,7 @@ Services:
 		}
 		ip := net.ParseIP(serv.Host)
 		if ip == nil {
-			log.Printf("[WARNING] Non IP address stub nameserver: %s", serv.Host)
+			log.Warningf("Non IP address stub nameserver: %s", serv.Host)
 			continue
 		}
 
@@ -64,7 +64,7 @@ Services:
 			// We must *also* chop of dns.stub. which means cutting two more labels.
 			domain = dnsutil.Join(labels[1 : len(labels)-dns.CountLabel(z)-2])
 			if domain == z {
-				log.Printf("[WARNING] Skipping nameserver for domain we are authoritative for: %s", domain)
+				log.Warningf("Skipping nameserver for domain we are authoritative for: %s", domain)
 				continue Services
 			}
 		}

plugin/etcd/stub_handler.go

@@ -2,8 +2,8 @@ package etcd
 
 import (
 	"errors"
-	"log"
 
+	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
@@ -19,7 +19,7 @@ type Stub struct {
 // ServeDNS implements the plugin.Handler interface.
 func (s Stub) ServeDNS(ctx context.Context, w dns.ResponseWriter, req *dns.Msg) (int, error) {
 	if hasStubEdns0(req) {
-		log.Printf("[WARNING] Forwarding cycle detected, refusing msg: %s", req.Question[0].Name)
+		log.Warningf("Forwarding cycle detected, refusing msg: %s", req.Question[0].Name)
 		return dns.RcodeRefused, errors.New("stub forward cycle")
 	}
 	req = addStubEdns0(req)

plugin/file/file.go

@@ -4,9 +4,9 @@ package file
 import (
 	"fmt"
 	"io"
-	"log"
 
 	"github.com/coredns/coredns/plugin"
+	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
@@ -52,24 +52,24 @@ func (f File) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (i
 			state.SizeAndDo(m)
 			w.WriteMsg(m)
 
-			log.Printf("[INFO] Notify from %s for %s: checking transfer", state.IP(), zone)
+			log.Infof("Notify from %s for %s: checking transfer", state.IP(), zone)
 			ok, err := z.shouldTransfer()
 			if ok {
 				z.TransferIn()
 			} else {
-				log.Printf("[INFO] Notify from %s for %s: no serial increase seen", state.IP(), zone)
+				log.Infof("Notify from %s for %s: no serial increase seen", state.IP(), zone)
 			}
 			if err != nil {
-				log.Printf("[WARNING] Notify from %s for %s: failed primary check: %s", state.IP(), zone, err)
+				log.Warningf("Notify from %s for %s: failed primary check: %s", state.IP(), zone, err)
 			}
 			return dns.RcodeSuccess, nil
 		}
-		log.Printf("[INFO] Dropping notify from %s for %s", state.IP(), zone)
+		log.Infof("Dropping notify from %s for %s", state.IP(), zone)
 		return dns.RcodeSuccess, nil
 	}
 
 	if z.Expired != nil && *z.Expired {
-		log.Printf("[ERROR] Zone %s is expired", zone)
+		log.Errorf("Zone %s is expired", zone)
 		return dns.RcodeServerFailure, nil
 	}
 

plugin/file/notify.go

@@ -2,9 +2,9 @@ package file
 
 import (
 	"fmt"
-	"log"
 	"net"
 
+	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/pkg/rcode"
 	"github.com/coredns/coredns/request"
 
@@ -53,9 +53,9 @@ func notify(zone string, to []string) error {
 			continue
 		}
 		if err := notifyAddr(c, m, t); err != nil {
-			log.Print("[ERROR] " + err.Error())
+			log.Error(err.Error())
 		} else {
-			log.Printf("[INFO] Sent notify for zone %q to %q", zone, t)
+			log.Infof("Sent notify for zone %q to %q", zone, t)
 		}
 	}
 	return nil

plugin/file/reload.go

@@ -1,9 +1,10 @@
 package file
 
 import (
-	"log"
 	"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.
@@ -25,7 +26,7 @@ func (z *Zone) Reload() error {
 			case <-tick.C:
 				reader, err := os.Open(z.file)
 				if err != nil {
-					log.Printf("[ERROR] Failed to open zone %q in %q: %v", z.origin, z.file, err)
+					log.Errorf("Failed to open zone %q in %q: %v", z.origin, z.file, err)
 					continue
 				}
 
@@ -33,7 +34,7 @@ func (z *Zone) Reload() error {
 				zone, err := Parse(reader, z.origin, z.file, serial)
 				if err != nil {
 					if _, ok := err.(*serialErr); !ok {
-						log.Printf("[ERROR] Parsing zone %q: %v", z.origin, err)
+						log.Errorf("Parsing zone %q: %v", z.origin, err)
 					}
 					continue
 				}
@@ -44,7 +45,7 @@ func (z *Zone) Reload() error {
 				z.Tree = zone.Tree
 				z.reloadMu.Unlock()
 
-				log.Printf("[INFO] Successfully reloaded zone %q in %q with serial %d", z.origin, z.file, z.Apex.SOA.Serial)
+				log.Infof("Successfully reloaded zone %q in %q with serial %d", z.origin, z.file, z.Apex.SOA.Serial)
 				z.Notify()
 
 			case <-z.reloadShutdown:

plugin/file/reload_test.go

@@ -2,7 +2,6 @@ package file
 
 import (
 	"io/ioutil"
-	"log"
 	"os"
 	"strings"
 	"testing"
@@ -15,8 +14,6 @@ import (
 )
 
 func TestZoneReload(t *testing.T) {
-	log.SetOutput(ioutil.Discard)
-
 	fileName, rm, err := test.TempFile(".", reloadZoneTest)
 	if err != nil {
 		t.Fatalf("failed to create zone: %s", err)

plugin/file/secondary.go

@@ -1,10 +1,11 @@
 package file
 
 import (
-	"log"
 	"math/rand"
 	"time"
 
+	"github.com/coredns/coredns/plugin/pkg/log"
+
 	"github.com/miekg/dns"
 )
 
@@ -27,19 +28,19 @@ Transfer:
 		t := new(dns.Transfer)
 		c, err := t.In(m, tr)
 		if err != nil {
-			log.Printf("[ERROR] Failed to setup transfer `%s' with `%q': %v", z.origin, tr, err)
+			log.Errorf("Failed to setup transfer `%s' with `%q': %v", z.origin, tr, err)
 			Err = err
 			continue Transfer
 		}
 		for env := range c {
 			if env.Error != nil {
-				log.Printf("[ERROR] Failed to transfer `%s' from %q: %v", z.origin, tr, env.Error)
+				log.Errorf("Failed to transfer `%s' from %q: %v", z.origin, tr, env.Error)
 				Err = env.Error
 				continue Transfer
 			}
 			for _, rr := range env.RR {
 				if err := z1.Insert(rr); err != nil {
-					log.Printf("[ERROR] Failed to parse transfer `%s' from: %q: %v", z.origin, tr, err)
+					log.Errorf("Failed to parse transfer `%s' from: %q: %v", z.origin, tr, err)
 					Err = err
 					continue Transfer
 				}
@@ -55,7 +56,7 @@ Transfer:
 	z.Tree = z1.Tree
 	z.Apex = z1.Apex
 	*z.Expired = false
-	log.Printf("[INFO] Transferred: %s from %s", z.origin, tr)
+	log.Infof("Transferred: %s from %s", z.origin, tr)
 	return nil
 }
 
@@ -139,7 +140,7 @@ Restart:
 
 			ok, err := z.shouldTransfer()
 			if err != nil {
-				log.Printf("[WARNING] Failed retry check %s", err)
+				log.Warningf("Failed retry check %s", err)
 				continue
 			}
 
@@ -162,7 +163,7 @@ Restart:
 
 			ok, err := z.shouldTransfer()
 			if err != nil {
-				log.Printf("[WARNING] Failed refresh check %s", err)
+				log.Warningf("Failed refresh check %s", err)
 				retryActive = true
 				continue
 			}

plugin/file/secondary_test.go

@@ -2,8 +2,6 @@ package file
 
 import (
 	"fmt"
-	"io/ioutil"
-	"log"
 	"testing"
 
 	"github.com/coredns/coredns/plugin/test"
@@ -72,7 +70,6 @@ const testZone = "secondary.miek.nl."
 
 func TestShouldTransfer(t *testing.T) {
 	soa := soa{250}
-	log.SetOutput(ioutil.Discard)
 
 	dns.HandleFunc(testZone, soa.Handler)
 	defer dns.HandleRemove(testZone)
@@ -117,7 +114,6 @@ func TestShouldTransfer(t *testing.T) {
 
 func TestTransferIn(t *testing.T) {
 	soa := soa{250}
-	log.SetOutput(ioutil.Discard)
 
 	dns.HandleFunc(testZone, soa.Handler)
 	defer dns.HandleRemove(testZone)

plugin/file/xfr.go

@@ -2,9 +2,9 @@ package file
 
 import (
 	"fmt"
-	"log"
 
 	"github.com/coredns/coredns/plugin"
+	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
@@ -38,7 +38,7 @@ func (x Xfr) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (in
 
 	j, l := 0, 0
 	records = append(records, records[0]) // add closing SOA to the end
-	log.Printf("[INFO] Outgoing transfer of %d records of zone %s to %s started", len(records), x.origin, state.IP())
+	log.Infof("Outgoing transfer of %d records of zone %s to %s started", len(records), x.origin, state.IP())
 	for i, r := range records {
 		l += dns.Len(r)
 		if l > transferLength {

plugin/health/health.go

@@ -3,11 +3,12 @@ package health
 
 import (
 	"io"
-	"log"
 	"net"
 	"net/http"
 	"sync"
 	"time"
+
+	"github.com/coredns/coredns/plugin/pkg/log"
 )
 
 // Health implements healthchecks by polling plugins.
@@ -67,7 +68,7 @@ func (h *health) OnShutdown() error {
 	h.SetOk(false)
 
 	if h.lameduck > 0 {
-		log.Printf("[INFO] Going into lameduck mode for %s", h.lameduck)
+		log.Infof("Going into lameduck mode for %s", h.lameduck)
 		time.Sleep(h.lameduck)
 	}
 

plugin/hosts/setup.go

@@ -1,7 +1,6 @@
 package hosts
 
 import (
-	"log"
 	"os"
 	"path"
 	"strings"
@@ -9,6 +8,7 @@ import (
 
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
+	"github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
@@ -87,13 +87,13 @@ func hostsParse(c *caddy.Controller) (Hosts, error) {
 			s, err := os.Stat(h.path)
 			if err != nil {
 				if os.IsNotExist(err) {
-					log.Printf("[WARNING] File does not exist: %s", h.path)
+					log.Warningf("File does not exist: %s", h.path)
 				} else {
 					return h, c.Errf("unable to access hosts file '%s': %v", h.path, err)
 				}
 			}
 			if s != nil && s.IsDir() {
-				log.Printf("[WARNING] hosts file %q is a directory", h.path)
+				log.Warningf("Hosts file %q is a directory", h.path)
 			}
 		}
 

plugin/kubernetes/apiproxy.go

@@ -3,11 +3,11 @@ package kubernetes
 import (
 	"fmt"
 	"io"
-	"log"
 	"net"
 	"net/http"
 
 	"github.com/coredns/coredns/plugin/pkg/healthcheck"
+	"github.com/coredns/coredns/plugin/pkg/log"
 )
 
 type proxyHandler struct {
@@ -27,19 +27,19 @@ func (p *proxyHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 
 	d, err := net.Dial(network, address)
 	if err != nil {
-		log.Printf("[ERROR] Unable to establish connection to upstream %s://%s: %s", network, address, err)
+		log.Errorf("Unable to establish connection to upstream %s://%s: %s", network, address, err)
 		http.Error(w, fmt.Sprintf("Unable to establish connection to upstream %s://%s: %s", network, address, err), 500)
 		return
 	}
 	hj, ok := w.(http.Hijacker)
 	if !ok {
-		log.Print("[ERROR] Unable to establish connection: no hijacker")
+		log.Error("Unable to establish connection: no hijacker")
 		http.Error(w, "Unable to establish connection: no hijacker", 500)
 		return
 	}
 	nc, _, err := hj.Hijack()
 	if err != nil {
-		log.Printf("[ERROR] Unable to hijack connection: %s", err)
+		log.Errorf("Unable to hijack connection: %s", err)
 		http.Error(w, fmt.Sprintf("Unable to hijack connection: %s", err), 500)
 		return
 	}
@@ -48,7 +48,7 @@ func (p *proxyHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 
 	err = r.Write(d)
 	if err != nil {
-		log.Printf("[ERROR] Unable to copy connection to upstream %s://%s: %s", network, address, err)
+		log.Errorf("Unable to copy connection to upstream %s://%s: %s", network, address, err)
 		http.Error(w, fmt.Sprintf("Unable to copy connection to upstream %s://%s: %s", network, address, err), 500)
 		return
 	}

plugin/kubernetes/xfr.go

@@ -1,14 +1,15 @@
 package kubernetes
 
 import (
-	"log"
 	"math"
 	"net"
 	"strings"
 
 	"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"
 	"golang.org/x/net/context"
 	api "k8s.io/api/core/v1"
@@ -50,7 +51,7 @@ func (k *Kubernetes) Transfer(ctx context.Context, state request.Request) (int,
 	records = append(records, soa...)
 	go func(ch chan *dns.Envelope) {
 		j, l := 0, 0
-		log.Printf("[INFO] Outgoing transfer of %d records of zone %s to %s started", len(records), state.Zone, state.IP())
+		log.Infof("Outgoing transfer of %d records of zone %s to %s started", len(records), state.Zone, state.IP())
 		for i, r := range records {
 			l += dns.Len(r)
 			if l > transferLength {

plugin/loadbalance/loadbalance.go

@@ -2,7 +2,7 @@
 package loadbalance
 
 import (
-	"log"
+	"github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/miekg/dns"
 )
@@ -75,7 +75,7 @@ func roundRobinShuffle(records []dns.RR) {
 // Write implements the dns.ResponseWriter interface.
 func (r *RoundRobinResponseWriter) Write(buf []byte) (int, error) {
 	// Should we pack and unpack here to fiddle with the packet... Not likely.
-	log.Print("[WARNING] RoundRobin called with Write: no shuffling records")
+	log.Warning("RoundRobin called with Write: not shuffling records")
 	n, err := r.ResponseWriter.Write(buf)
 	return n, err
 }

plugin/metrics/metrics.go

@@ -2,7 +2,6 @@
 package metrics
 
 import (
-	"log"
 	"net"
 	"net/http"
 	"os"
@@ -12,6 +11,7 @@ import (
 	"github.com/coredns/coredns/coremain"
 	"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"
@@ -88,7 +88,7 @@ func (m *Metrics) ZoneNames() []string {
 func (m *Metrics) OnStartup() error {
 	ln, err := net.Listen("tcp", m.Addr)
 	if err != nil {
-		log.Printf("[ERROR] Failed to start metrics handler: %s", err)
+		log.Errorf("Failed to start metrics handler: %s", err)
 		return err
 	}
 

plugin/pkg/healthcheck/healthcheck.go

@@ -3,13 +3,14 @@ package healthcheck
 import (
 	"io"
 	"io/ioutil"
-	"log"
 	"net"
 	"net/http"
 	"net/url"
 	"sync"
 	"sync/atomic"
 	"time"
+
+	"github.com/coredns/coredns/plugin/pkg/log"
 )
 
 // UpstreamHostDownFunc can be used to customize how Down behaves.
@@ -122,7 +123,7 @@ func (uh *UpstreamHost) HealthCheckURL() {
 	}()
 
 	if err != nil {
-		log.Printf("[WARNING] Host %s health check probe failed: %v", uh.Name, err)
+		log.Warningf("Host %s health check probe failed: %v", uh.Name, err)
 		atomic.AddInt32(&uh.Fails, 1)
 		return
 	}
@@ -132,7 +133,7 @@ func (uh *UpstreamHost) HealthCheckURL() {
 		r.Body.Close()
 
 		if r.StatusCode < 200 || r.StatusCode >= 400 {
-			log.Printf("[WARNING] Host %s health check returned HTTP code %d", uh.Name, r.StatusCode)
+			log.Warningf("Host %s health check returned HTTP code %d", uh.Name, r.StatusCode)
 			atomic.AddInt32(&uh.Fails, 1)
 			return
 		}

plugin/pkg/healthcheck/policy.go

@@ -1,9 +1,10 @@
 package healthcheck
 
 import (
-	"log"
 	"math/rand"
 	"sync/atomic"
+
+	"github.com/coredns/coredns/plugin/pkg/log"
 )
 
 var (
@@ -64,7 +65,7 @@ type Spray struct{}
 func (r *Spray) Select(pool HostPool) *UpstreamHost {
 	rnd := rand.Int() % len(pool)
 	randHost := pool[rnd]
-	log.Printf("[WARNING] All hosts reported as down, spraying to target: %s", randHost.Name)
+	log.Warningf("All hosts reported as down, spraying to target: %s", randHost.Name)
 	return randHost
 }
 

plugin/pkg/healthcheck/policy_test.go

@@ -1,8 +1,6 @@
 package healthcheck
 
 import (
-	"io/ioutil"
-	"log"
 	"net/http"
 	"net/http/httptest"
 	"os"
@@ -13,8 +11,6 @@ import (
 var workableServer *httptest.Server
 
 func TestMain(m *testing.M) {
-	log.SetOutput(ioutil.Discard)
-
 	workableServer = httptest.NewServer(http.HandlerFunc(
 		func(w http.ResponseWriter, r *http.Request) {
 			// do nothing

plugin/pprof/pprof.go

@@ -3,10 +3,11 @@
 package pprof
 
 import (
-	"log"
 	"net"
 	"net/http"
 	pp "net/http/pprof"
+
+	"github.com/coredns/coredns/plugin/pkg/log"
 )
 
 type handler struct {
@@ -18,7 +19,7 @@ type handler struct {
 func (h *handler) Startup() error {
 	ln, err := net.Listen("tcp", h.addr)
 	if err != nil {
-		log.Printf("[ERROR] Failed to start pprof handler: %s", err)
+		log.Errorf("Failed to start pprof handler: %s", err)
 		return err
 	}
 

plugin/proxy/google.go

@@ -5,13 +5,13 @@ import (
 	"encoding/json"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net"
 	"net/http"
 	"net/url"
 	"time"
 
 	"github.com/coredns/coredns/plugin/pkg/healthcheck"
+	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/request"
 
 	"github.com/miekg/dns"
@@ -65,7 +65,7 @@ func (g *google) Exchange(ctx context.Context, addr string, state request.Reques
 		return m, nil
 	}
 
-	log.Printf("[WARNING] Failed to connect to HTTPS backend %q: %s", g.endpoint, backendErr)
+	log.Warningf("Failed to connect to HTTPS backend %q: %s", g.endpoint, backendErr)
 	return nil, backendErr
 }
 
@@ -119,17 +119,17 @@ func (g *google) OnStartup(p *Proxy) error {
 
 	new, err := g.bootstrapProxy.Lookup(state, g.endpoint, dns.TypeA)
 	if err != nil {
-		log.Printf("[WARNING] Failed to bootstrap A records %q: %s", g.endpoint, err)
+		log.Warningf("Failed to bootstrap A records %q: %s", g.endpoint, err)
 	} else {
 		addrs, err1 := extractAnswer(new)
 		if err1 != nil {
-			log.Printf("[WARNING] Failed to bootstrap A records %q: %s", g.endpoint, err1)
+			log.Warningf("Failed to bootstrap A records %q: %s", g.endpoint, err1)
 		} else {
 
 			up := newUpstream(addrs, oldUpstream.(*staticUpstream))
 			p.Upstreams = &[]Upstream{up}
 
-			log.Printf("[INFO] Bootstrapping A records %q found: %v", g.endpoint, addrs)
+			log.Infof("Bootstrapping A records %q found: %v", g.endpoint, addrs)
 		}
 	}
 
@@ -140,24 +140,24 @@ func (g *google) OnStartup(p *Proxy) error {
 			select {
 			case <-tick.C:
 
-				log.Printf("[INFO] Resolving A records %q", g.endpoint)
+				log.Infof("Resolving A records %q", g.endpoint)
 
 				new, err := g.bootstrapProxy.Lookup(state, g.endpoint, dns.TypeA)
 				if err != nil {
-					log.Printf("[WARNING] Failed to resolve A records %q: %s", g.endpoint, err)
+					log.Warningf("Failed to resolve A records %q: %s", g.endpoint, err)
 					continue
 				}
 
 				addrs, err1 := extractAnswer(new)
 				if err1 != nil {
-					log.Printf("[WARNING] Failed to resolve A records %q: %s", g.endpoint, err1)
+					log.Warningf("Failed to resolve A records %q: %s", g.endpoint, err1)
 					continue
 				}
 
 				up := newUpstream(addrs, oldUpstream.(*staticUpstream))
 				p.Upstreams = &[]Upstream{up}
 
-				log.Printf("[INFO] Resolving A records %q found: %v", g.endpoint, addrs)
+				log.Infof("Resolving A records %q found: %v", g.endpoint, addrs)
 
 			case <-g.quit:
 				return

plugin/proxy/grpc.go

@@ -3,9 +3,9 @@ package proxy
 import (
 	"crypto/tls"
 	"fmt"
-	"log"
 
 	"github.com/coredns/coredns/pb"
+	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/pkg/trace"
 	"github.com/coredns/coredns/request"
 
@@ -67,7 +67,7 @@ func (g *grpcClient) OnShutdown(p *Proxy) error {
 	for i, conn := range g.conns {
 		err := conn.Close()
 		if err != nil {
-			log.Printf("[WARNING] Error closing connection %d: %s\n", i, err)
+			log.Warningf("Error closing connection %d: %s\n", i, err)
 		}
 	}
 	g.conns = []*grpc.ClientConn{}
@@ -84,13 +84,13 @@ func (g *grpcClient) OnStartup(p *Proxy) error {
 			intercept := otgrpc.OpenTracingClientInterceptor(t.Tracer(), otgrpc.IncludingSpans(onlyIfParent))
 			dialOpts = append(dialOpts, grpc.WithUnaryInterceptor(intercept))
 		} else {
-			log.Printf("[WARNING] Wrong type for trace plugin reference: %s", p.Trace)
+			log.Warningf("Wrong type for trace plugin reference: %s", p.Trace)
 		}
 	}
 	for _, host := range g.upstream.Hosts {
 		conn, err := grpc.Dial(host.Name, dialOpts...)
 		if err != nil {
-			log.Printf("[WARNING] Skipping gRPC host '%s' due to Dial error: %s\n", host.Name, err)
+			log.Warningf("Skipping gRPC host '%s' due to Dial error: %s\n", host.Name, err)
 		} else {
 			g.clients[host.Name] = pb.NewDnsServiceClient(conn)
 			g.conns = append(g.conns, conn)

plugin/proxy/healthcheck_test.go

@@ -2,8 +2,6 @@ package proxy
 
 import (
 	"fmt"
-	"io/ioutil"
-	"log"
 	"net/http"
 	"net/http/httptest"
 	"strings"
@@ -18,10 +16,6 @@ import (
 	"github.com/miekg/dns"
 )
 
-func init() {
-	log.SetOutput(ioutil.Discard)
-}
-
 func TestUnhealthy(t *testing.T) {
 	// High HC interval, we want to test the HC after failed queries.
 	config := "proxy . %s {\n health_check /healthcheck:%s 10s \nfail_timeout 100ms\n}"

plugin/reload/reload.go

@@ -2,9 +2,10 @@ package reload
 
 import (
 	"crypto/md5"
-	"log"
 	"time"
 
+	"github.com/coredns/coredns/plugin/pkg/log"
+
 	"github.com/mholt/caddy"
 )
 
@@ -36,7 +37,7 @@ func hook(event caddy.EventName, info interface{}) error {
 	// this should be an instance. ok to panic if not
 	instance := info.(*caddy.Instance)
 	md5sum := md5.Sum(instance.Caddyfile().Body())
-	log.Printf("[INFO] Running configuration MD5 = %x\n", md5sum)
+	log.Infof("Running configuration MD5 = %x\n", md5sum)
 
 	go func() {
 		tick := time.NewTicker(r.interval)
@@ -57,7 +58,7 @@ func hook(event caddy.EventName, info interface{}) error {
 					r.usage = maybeUsed
 					_, err := instance.Restart(corefile)
 					if err != nil {
-						log.Printf("[ERROR] Corefile changed but reload failed: %s\n", err)
+						log.Errorf("Corefile changed but reload failed: %s\n", err)
 						continue
 					}
 					// we are done, if the plugin was not set used, then it is not.

plugin/root/root.go

@@ -1,11 +1,11 @@
 package root
 
 import (
-	"log"
 	"os"
 
 	"github.com/coredns/coredns/core/dnsserver"
 	"github.com/coredns/coredns/plugin"
+	"github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/mholt/caddy"
 )
@@ -33,7 +33,7 @@ func setup(c *caddy.Controller) error {
 		if os.IsNotExist(err) {
 			// Allow this, because the folder might appear later.
 			// But make sure the user knows!
-			log.Printf("[WARNING] Root path does not exist: %s", config.Root)
+			log.Warningf("Root path does not exist: %s", config.Root)
 		} else {
 			return plugin.Error("root", c.Errf("unable to access root path '%s': %v", config.Root, err))
 		}

plugin/root/root_test.go

@@ -3,7 +3,6 @@ package root
 import (
 	"fmt"
 	"io/ioutil"
-	"log"
 	"os"
 	"path/filepath"
 	"strings"
@@ -15,8 +14,6 @@ import (
 )
 
 func TestRoot(t *testing.T) {
-	log.SetOutput(ioutil.Discard)
-
 	// Predefined error substrings
 	parseErrContent := "Error during parsing:"
 	unableToAccessErrContent := "unable to access root path"

plugin/tls/tls_test.go

@@ -1,8 +1,6 @@
 package tls
 
 import (
-	"io/ioutil"
-	"log"
 	"strings"
 	"testing"
 
@@ -10,16 +8,14 @@ import (
 )
 
 func TestTLS(t *testing.T) {
-	log.SetOutput(ioutil.Discard)
-
 	tests := []struct {
 		input              string
 		shouldErr          bool
 		expectedRoot       string // expected root, set to the controller. Empty for negative cases.
 		expectedErrContent string // substring from the expected error. Empty for positive cases.
 	}{
-	// positive
+		// positive
-	// negative
+		// negative
 	}
 
 	for i, test := range tests {