pkg/log: fix data race on d (#2698)

* pkg/log: fix data race on d

Wrap d in a mutex to prevent data race. This makes is slower, but this
is a debugging aid anyway. It's not used normally.

Signed-off-by: Miek Gieben <miek@miek.nl>

* Fix tests compilation

Signed-off-by: Miek Gieben <miek@miek.nl>

* Fix test compile

Signed-off-by: Miek Gieben <miek@miek.nl>

6 files changed, 47 insertions, 26 deletions

diff --git a/core/dnsserver/server.go b/core/dnsserver/server.go
index fe509a21b..558954304 100644
--- a/core/dnsserver/server.go
+++ b/core/dnsserver/server.go
@@ -62,7 +62,7 @@ func NewServer(addr string, group []*Config) (*Server, error) {
 	for _, site := range group {
 		if site.Debug {
 			s.debug = true
-			log.D = true
+			log.D.Set()
 		}
 		// set the config per zone
 		s.zones[site.Zone] = site
diff --git a/plugin/debug/pcap.go b/plugin/debug/pcap.go
index 053c2d9dd..0663f6dce 100644
--- a/plugin/debug/pcap.go
+++ b/plugin/debug/pcap.go
@@ -23,7 +23,7 @@ import (
 //
 // msg will prefix the pcap dump.
 func Hexdump(m *dns.Msg, v ...interface{}) {
-	if !log.D {
+	if !log.D.Value() {
 		return
 	}
 
@@ -39,7 +39,7 @@ func Hexdump(m *dns.Msg, v ...interface{}) {
 
 // Hexdumpf dumps a DNS message as Hexdump, but allows a format string.
 func Hexdumpf(m *dns.Msg, format string, v ...interface{}) {
-	if !log.D {
+	if !log.D.Value() {
 		return
 	}
 
diff --git a/plugin/debug/pcap_test.go b/plugin/debug/pcap_test.go
index 724189db7..b2796e399 100644
--- a/plugin/debug/pcap_test.go
+++ b/plugin/debug/pcap_test.go
@@ -17,10 +17,21 @@ func msg() *dns.Msg {
 	m.SetQuestion("example.local.", dns.TypeA)
 	m.SetEdns0(4096, true)
 	m.Id = 10
-
 	return m
 }
 
+func TestNoDebug(t *testing.T) {
+	// Must come first, because set log.D.Set() which is impossible to undo.
+	var f bytes.Buffer
+	golog.SetOutput(&f)
+
+	str := "Hi There!"
+	Hexdumpf(msg(), "%s %d", str, 10)
+	if len(f.Bytes()) != 0 {
+		t.Errorf("Expected no output, got %d bytes", len(f.Bytes()))
+	}
+}
+
 func ExampleLogHexdump() {
 	buf, _ := msg().Pack()
 	h := hexdump(buf)
@@ -36,7 +47,7 @@ func ExampleLogHexdump() {
 func TestHexdump(t *testing.T) {
 	var f bytes.Buffer
 	golog.SetOutput(&f)
-	log.D = true
+	log.D.Set()
 
 	str := "Hi There!"
 	Hexdump(msg(), str)
@@ -50,7 +61,7 @@ func TestHexdump(t *testing.T) {
 func TestHexdumpf(t *testing.T) {
 	var f bytes.Buffer
 	golog.SetOutput(&f)
-	log.D = true
+	log.D.Set()
 
 	str := "Hi There!"
 	Hexdumpf(msg(), "%s %d", str, 10)
@@ -60,15 +71,3 @@ func TestHexdumpf(t *testing.T) {
 		t.Errorf("The string %s %d, is not contained in the logged output: %s", str, 10, logged)
 	}
 }
-
-func TestNoDebug(t *testing.T) {
-	var f bytes.Buffer
-	golog.SetOutput(&f)
-	log.D = false
-
-	str := "Hi There!"
-	Hexdumpf(msg(), "%s %d", str, 10)
-	if len(f.Bytes()) != 0 {
-		t.Errorf("Expected no output, got %d bytes", len(f.Bytes()))
-	}
-}
diff --git a/plugin/pkg/log/log.go b/plugin/pkg/log/log.go
index b4bd1cad8..3050999af 100644
--- a/plugin/pkg/log/log.go
+++ b/plugin/pkg/log/log.go
@@ -13,11 +13,33 @@ import (
 	"io/ioutil"
 	golog "log"
 	"os"
+	"sync"
 	"time"
 )
 
-// D controls whether we should output debug logs. If true, we do.
-var D bool
+// D controls whether we should output debug logs. If true, we do, once set
+// it can not be unset.
+var D = &d{}
+
+type d struct {
+	on bool
+	sync.RWMutex
+}
+
+// Set sets d to true.
+func (d *d) Set() {
+	d.Lock()
+	d.on = true
+	d.Unlock()
+}
+
+// Value return the boolean value of d.
+func (d *d) Value() bool {
+	d.RLock()
+	b := d.on
+	d.RUnlock()
+	return b
+}
 
 // RFC3339Milli doesn't exist, invent it here.
 func clock() string { return time.Now().Format("2006-01-02T15:04:05.000Z07:00") }
@@ -35,7 +57,7 @@ func log(level string, v ...interface{}) {
 // Debug is equivalent to log.Print(), but prefixed with "[DEBUG] ". It only outputs something
 // if D is true.
 func Debug(v ...interface{}) {
-	if !D {
+	if !D.Value() {
 		return
 	}
 	log(debug, v...)
@@ -44,7 +66,7 @@ func Debug(v ...interface{}) {
 // 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 {
+	if !D.Value() {
 		return
 	}
 	logf(debug, format, v...)
diff --git a/plugin/pkg/log/log_test.go b/plugin/pkg/log/log_test.go
index 2b0de75cd..4f0dc4f43 100644
--- a/plugin/pkg/log/log_test.go
+++ b/plugin/pkg/log/log_test.go
@@ -18,7 +18,7 @@ func TestDebug(t *testing.T) {
 	}
 	f.Reset()
 
-	D = true
+	D.Set()
 	Debug("debug")
 	if x := f.String(); !strings.Contains(x, debug+"debug") {
 		t.Errorf("Expected debug log to be %s, got %s", debug+"debug", x)
@@ -29,7 +29,7 @@ func TestDebugx(t *testing.T) {
 	var f bytes.Buffer
 	golog.SetOutput(&f)
 
-	D = true
+	D.Set()
 
 	Debugf("%s", "debug")
 	if x := f.String(); !strings.Contains(x, debug+"debug") {
diff --git a/plugin/pkg/log/plugin.go b/plugin/pkg/log/plugin.go
index 0cc5f881a..8dbffa07e 100644
--- a/plugin/pkg/log/plugin.go
+++ b/plugin/pkg/log/plugin.go
@@ -24,7 +24,7 @@ func (p P) log(level string, v ...interface{}) {
 
 // Debug logs as log.Debug.
 func (p P) Debug(v ...interface{}) {
-	if !D {
+	if !D.Value() {
 		return
 	}
 	p.log(debug, v...)
@@ -32,7 +32,7 @@ func (p P) Debug(v ...interface{}) {
 
 // Debugf logs as log.Debugf.
 func (p P) Debugf(format string, v ...interface{}) {
-	if !D {
+	if !D.Value() {
 		return
 	}
 	p.logf(debug, format, v...)