pkg/log: ability for debug logs (#1689)

* pkg/log: ability for debug logs

When the debug plugin is enabled all log.Debug calls will print to
standard; if not there are a noop (almost).

The log package wraps some standard log functions as well, so just
replacing "log" with "plugin/pkg/log" should be enough to use this
package.

* docs

* Add docs

* lint

* Test fallthrough to log pkg as well

* simple package - up test coverage

* add other log levels as well

* update docs

core/dnsserver/server.go

@@ -11,6 +11,7 @@ import (
 	"github.com/coredns/coredns/plugin"
 	"github.com/coredns/coredns/plugin/metrics/vars"
 	"github.com/coredns/coredns/plugin/pkg/edns"
+	"github.com/coredns/coredns/plugin/pkg/log"
 	"github.com/coredns/coredns/plugin/pkg/rcode"
 	"github.com/coredns/coredns/plugin/pkg/trace"
 	"github.com/coredns/coredns/request"
@@ -60,6 +61,7 @@ func NewServer(addr string, group []*Config) (*Server, error) {
 	for _, site := range group {
 		if site.Debug {
 			s.debug = true
+			log.D = true
 		}
 		// set the config per zone
 		s.zones[site.Zone] = site

plugin.md

@@ -35,11 +35,15 @@ See a couple of blog posts on how to write and add plugin to CoreDNS:
 
 ## Logging
 
-If your plugin needs to output a log line you should use the `log` package. CoreDNS does not
-implement log levels. The standard way of outputing is: `log.Printf("[LEVEL] ...")`, and LEVEL
-can be: `INFO`, `WARNING` or `ERROR`.
+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.
+
 In general, logging should be left to the higher layers by returning an error. However, if there is
-a reason to consume the error but notify the user, then logging in the plugin can be acceptable.
+a reason to consume the error and notify the user, then logging in the plugin itself can be
+acceptable. The `Debug*` functions only output something when the *debug* plugin is loaded in the
+server.
 
 ## Metrics
 

plugin/pkg/log/log.go

@@ -0,0 +1,69 @@
+// 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].
+// 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.
+package log
+
+import (
+	"fmt"
+	golog "log"
+)
+
+// D controls whether we should ouput debug logs. If true, we do.
+var D bool
+
+// logf calls log.Printf prefixed with level.
+func logf(level, format string, v ...interface{}) {
+	s := level + fmt.Sprintf(format, v...)
+	golog.Print(s)
+}
+
+// log calls log.Print prefixed with level.
+func log(level string, v ...interface{}) { s := level + fmt.Sprint(v...); golog.Print(s) }
+
+// Debug is equivalent to log.Print(), but prefixed with "[DEBUG] ". It only outputs something
+// if D is true.
+func Debug(v ...interface{}) {
+	if !D {
+		return
+	}
+	log(debug, v...)
+}
+
+// Debugf is equivalent to log.Printf(), but prefixed with "[DEBUG] ". It only outputs something
+// if D is true.
+func Debugf(format string, v ...interface{}) {
+	if !D {
+		return
+	}
+	logf(debug, format, v...)
+}
+
+// Info is equivalent to log.Print, but prefixed with "[INFO] ".
+func Info(v ...interface{}) { log(info, v...) }
+
+// Infof is equivalent to log.Printf, but prefixed with "[INFO] ".
+func Infof(format string, v ...interface{}) { logf(info, format, v...) }
+
+// Warning is equivalent to log.Print, but prefixed with "[WARNING] ".
+func Warning(v ...interface{}) { log(warning, v...) }
+
+// Warningf is equivalent to log.Printf, but prefixed with "[WARNING] ".
+func Warningf(format string, v ...interface{}) { logf(warning, format, v...) }
+
+// Error is equivalent to log.Print, but prefixed with "[ERROR] ".
+func Error(v ...interface{}) { log(err, v...) }
+
+// Errorf is equivalent to log.Printf, but prefixed with "[ERROR] ".
+func Errorf(format string, v ...interface{}) { logf(err, format, v...) }
+
+const (
+	debug   = "[DEBUG] "
+	err     = "[ERROR] "
+	warning = "[WARNING] "
+	info    = "[INFO] "
+)

plugin/pkg/log/log_test.go

@@ -0,0 +1,61 @@
+package log
+
+import (
+	"bytes"
+	golog "log"
+	"strings"
+	"testing"
+)
+
+func TestDebug(t *testing.T) {
+	var f bytes.Buffer
+	golog.SetOutput(&f)
+
+	// D == false
+	Debug("debug")
+	if x := f.String(); x != "" {
+		t.Errorf("Expected no debug logs, got %s", x)
+	}
+
+	D = true
+	Debug("debug")
+	if x := f.String(); !strings.Contains(x, debug+"debug") {
+		t.Errorf("Expected debug log to be %s, got %s", debug+"debug", x)
+	}
+}
+
+func TestDebugx(t *testing.T) {
+	var f bytes.Buffer
+	golog.SetOutput(&f)
+
+	D = true
+
+	Debugf("%s", "debug")
+	if x := f.String(); !strings.Contains(x, debug+"debug") {
+		t.Errorf("Expected debug log to be %s, got %s", debug+"debug", x)
+	}
+
+	Debug("debug")
+	if x := f.String(); !strings.Contains(x, debug+"debug") {
+		t.Errorf("Expected debug log to be %s, got %s", debug+"debug", x)
+	}
+}
+
+func TestLevels(t *testing.T) {
+	var f bytes.Buffer
+	const ts = "test"
+	golog.SetOutput(&f)
+
+	Info(ts)
+	if x := f.String(); !strings.Contains(x, info+ts) {
+		t.Errorf("Expected log to be %s, got %s", info+ts, x)
+	}
+	Warning(ts)
+	if x := f.String(); !strings.Contains(x, warning+ts) {
+		t.Errorf("Expected log to be %s, got %s", warning+ts, x)
+	}
+	Error(ts)
+	if x := f.String(); !strings.Contains(x, err+ts) {
+		t.Errorf("Expected log to be %s, got %s", err+ts, x)
+	}
+}