From a84413bd07fddefdf967d244aa4fafad24923737 Mon Sep 17 00:00:00 2001 From: Miek Gieben Date: Thu, 23 May 2019 21:02:30 +0100 Subject: [PATCH] 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 * Fix tests compilation Signed-off-by: Miek Gieben * Fix test compile Signed-off-by: Miek Gieben --- core/dnsserver/server.go | 2 +- plugin/debug/pcap.go | 4 ++-- plugin/debug/pcap_test.go | 29 ++++++++++++++--------------- plugin/pkg/log/log.go | 30 ++++++++++++++++++++++++++---- plugin/pkg/log/log_test.go | 4 ++-- plugin/pkg/log/plugin.go | 4 ++-- 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...)