plugin/errors: remove cLogger and eLogger (#2657)

plugin/errors/errors.go

@@ -35,28 +35,19 @@ func (p *pattern) setTimer(t *time.Timer) {
 // errorHandler handles DNS errors (and errors from other plugin).
 type errorHandler struct {
 	patterns []*pattern
-	eLogger  func(int, string, string, string)
-	cLogger  func(uint32, string, time.Duration)
 	stopFlag uint32
 	Next     plugin.Handler
 }
 
 func newErrorHandler() *errorHandler {
-	return &errorHandler{eLogger: errorLogger, cLogger: consLogger}
-}
-
-func errorLogger(code int, qName, qType, err string) {
-	log.Errorf("%d %s %s: %s", code, qName, qType, err)
-}
-
-func consLogger(cnt uint32, pattern string, p time.Duration) {
-	log.Errorf("%d errors like '%s' occurred in last %s", cnt, pattern, p)
+	return &errorHandler{}
 }
 
 func (h *errorHandler) logPattern(i int) {
 	cnt := atomic.SwapUint32(&h.patterns[i].count, 0)
 	if cnt > 0 {
-		h.cLogger(cnt, h.patterns[i].pattern.String(), h.patterns[i].period)
+		log.Errorf("%d errors like '%s' occurred in last %s",
+			cnt, h.patterns[i].pattern.String(), h.patterns[i].period)
 	}
 }
 
@@ -102,7 +93,7 @@ func (h *errorHandler) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dn
 			}
 		}
 		state := request.Request{W: w, Req: r}
-		h.eLogger(rcode, state.Name(), state.Type(), strErr)
+		log.Errorf("%d %s %s: %s", rcode, state.Name(), state.Type(), strErr)
 	}
 
 	return rcode, err

plugin/errors/errors_test.go

@@ -8,6 +8,7 @@ import (
 	golog "log"
 	"math/rand"
 	"regexp"
+	"strconv"
 	"strings"
 	"sync"
 	"sync/atomic"
@@ -24,7 +25,7 @@ import (
 func TestErrors(t *testing.T) {
 	buf := bytes.Buffer{}
 	golog.SetOutput(&buf)
-	em := errorHandler{eLogger: errorLogger}
+	em := errorHandler{}
 
 	testErr := errors.New("test error")
 	tests := []struct {
@@ -72,58 +73,22 @@ func TestErrors(t *testing.T) {
 	}
 }
 
-func TestConsLogger(t *testing.T) {
+func TestLogPattern(t *testing.T) {
 	buf := bytes.Buffer{}
 	golog.SetOutput(&buf)
 
-	consLogger(5, "^Error.*!$", 3*time.Second)
-
-	exp := "[ERROR] plugin/errors: 5 errors like '^Error.*!$' occurred in last 3s"
-	act := buf.String()
-	if !strings.Contains(act, exp) {
-		t.Errorf("Unexpected log message, expected to contain %q, actual %q", exp, act)
-	}
-}
-
-func TestLogPattern(t *testing.T) {
 	h := &errorHandler{
 		patterns: []*pattern{{
 			count:   4,
 			period:  2 * time.Second,
-			pattern: regexp.MustCompile("^Error.*!$"),
+			pattern: regexp.MustCompile("^error.*!$"),
 		}},
-		cLogger: testConsLogger,
 	}
-	loggedData = loggedData[:0]
-
 	h.logPattern(0)
-	expLen := 1
-	if len(loggedData) != expLen {
-		t.Errorf("Unexpected number of logged messages, expected %d, actual %d",
-			expLen, len(loggedData))
-	}
-	expCnt := uint32(4)
-	if loggedData[0].cnt != expCnt {
-		t.Errorf("Unexpected 'count' in logged message, expected %d, actual %d",
-			expCnt, loggedData[0].cnt)
-	}
-	expPat := "^Error.*!$"
-	actPat := loggedData[0].pat
-	if actPat != expPat {
-		t.Errorf("Unexpected 'pattern' in logged message, expected %s, actual %s",
-			expPat, actPat)
-	}
-	expPer := "2s"
-	actPer := loggedData[0].dur.String()
-	if actPer != expPer {
-		t.Errorf("Unexpected 'period' in logged message, expected %s, actual %s",
-			expPer, actPer)
-	}
 
-	h.logPattern(0)
-	if len(loggedData) != expLen {
-		t.Errorf("Unexpected number of logged messages, expected %d, actual %d",
-			expLen, len(loggedData))
+	expLog := "4 errors like '^error.*!$' occurred in last 2s"
+	if log := buf.String(); !strings.Contains(log, expLog) {
+		t.Errorf("Expected log %q, but got %q", expLog, log)
 	}
 }
 
@@ -132,9 +97,8 @@ func TestInc(t *testing.T) {
 		stopFlag: 1,
 		patterns: []*pattern{{
 			period:  2 * time.Second,
-			pattern: regexp.MustCompile("^Error.*!$"),
+			pattern: regexp.MustCompile("^error.*!$"),
 		}},
-		cLogger: testConsLogger,
 	}
 
 	ret := h.inc(0)
@@ -186,14 +150,15 @@ func TestInc(t *testing.T) {
 }
 
 func TestStop(t *testing.T) {
+	buf := bytes.Buffer{}
+	golog.SetOutput(&buf)
+
 	h := &errorHandler{
 		patterns: []*pattern{{
 			period:  2 * time.Second,
-			pattern: regexp.MustCompile("^Error.*!$"),
+			pattern: regexp.MustCompile("^error.*!$"),
 		}},
-		cLogger: testConsLogger,
 	}
-	loggedData = loggedData[:0]
 
 	h.inc(0)
 	h.inc(0)
@@ -225,54 +190,34 @@ func TestStop(t *testing.T) {
 		t.Error("Timer was unexpectedly not stopped before")
 	}
 
-	expLen := 1
-	if len(loggedData) != expLen {
-		t.Errorf("Unexpected number of logged messages, expected %d, actual %d",
-			expLen, len(loggedData))
-	}
-	expCnt = uint32(3)
-	actCnt = loggedData[0].cnt
-	if actCnt != expCnt {
-		t.Errorf("Unexpected 'count' in logged message, expected %d, actual %d",
-			expCnt, actCnt)
+	expLog := "3 errors like '^error.*!$' occurred in last 2s"
+	if log := buf.String(); !strings.Contains(log, expLog) {
+		t.Errorf("Expected log %q, but got %q", expLog, log)
 	}
 }
 
+const (
+	pattern0 = "failed"
+	pattern1 = "down$"
+)
+
 func TestServeDNSConcurrent(t *testing.T) {
+	buf := bytes.NewBuffer(nil)
+	golog.SetOutput(buf)
+
 	eg := newErrorGenerator()
-	rep := &errorReport{}
 
 	h := &errorHandler{
 		patterns: []*pattern{
 			{
 				period:  3 * time.Nanosecond,
-				pattern: regexp.MustCompile("Failed"),
+				pattern: regexp.MustCompile(pattern0),
 			},
 			{
 				period:  2 * time.Nanosecond,
-				pattern: regexp.MustCompile("down$"),
+				pattern: regexp.MustCompile(pattern1),
 			},
 		},
-		cLogger: func(cnt uint32, pattern string, p time.Duration) {
-			rep.incLoggerCnt()
-			if pattern == "Failed" {
-				rep.incConsolidated(Err0, cnt)
-			} else if pattern == "down$" {
-				rep.incConsolidated(Err1, cnt)
-			}
-		},
-		eLogger: func(code int, n, t, e string) {
-			switch e {
-			case ErrStr0:
-				rep.incPassed(Err0)
-			case ErrStr1:
-				rep.incPassed(Err1)
-			case ErrStr2:
-				rep.incPassed(Err2)
-			case ErrStr3:
-				rep.incPassed(Err3)
-			}
-		},
 		Next: eg,
 	}
 
@@ -284,20 +229,19 @@ func TestServeDNSConcurrent(t *testing.T) {
 	runnersCnt := 9
 	runner := func() {
 		defer wg.Done()
-		for !eg.done() {
+		for eg.progress() < 100 {
 			h.ServeDNS(ctx, w, r)
 		}
 	}
+
 	wg.Add(runnersCnt)
 	for ; runnersCnt > 0; runnersCnt-- {
 		go runner()
 	}
 
 	stopCalled := false
-	for !eg.done() {
-		if !stopCalled &&
-			atomic.LoadUint32(&rep.s[Err0]) > ErrCnt0/2 &&
-			atomic.LoadUint32(&rep.s[Err1]) > ErrCnt1/2 {
+	for eg.progress() < 100 {
+		if !stopCalled && eg.progress() > 50 {
 			h.stop()
 			stopCalled = true
 		}
@@ -310,43 +254,30 @@ func TestServeDNSConcurrent(t *testing.T) {
 	wg.Wait()
 	time.Sleep(time.Millisecond)
 
-	if rep.loggerCnt() < 3 {
-		t.Errorf("Perhaps logger was never called by timer")
-	}
-	if rep.consolidated(Err0) == 0 {
-		t.Errorf("Err0 was never reported by consLogger")
-	}
-	if rep.consolidated(Err1) == 0 {
-		t.Errorf("Err1 was never reported by consLogger")
-	}
-	if rep.consolidated(Err0)+rep.passed(Err0) != ErrCnt0 {
-		t.Errorf("Unexpected Err0 count, expected %d, reported by consLogger %d and by ServeDNS %d",
-			ErrCnt0, rep.consolidated(Err0), rep.passed(Err0))
-	}
-	if rep.consolidated(Err1)+rep.passed(Err1) != ErrCnt1 {
-		t.Errorf("Unexpected Err1 count, expected %d, reported by consLogger %d and by ServeDNS %d",
-			ErrCnt1, rep.consolidated(Err1), rep.passed(Err1))
-	}
-	if rep.passed(Err2) != ErrCnt2 {
-		t.Errorf("Unexpected Err2 count, expected %d, reported by ServeDNS %d",
-			ErrCnt2, rep.passed(Err2))
-	}
-	if rep.passed(Err3) != ErrCnt3 {
-		t.Errorf("Unexpected Err3 count, expected %d, reported by ServeDNS %d",
-			ErrCnt3, rep.passed(Err3))
-	}
-}
+	rep := makeReport(t, buf)
 
-type logData struct {
-	cnt uint32
-	pat string
-	dur time.Duration
-}
-
-var loggedData []logData
-
-func testConsLogger(cnt uint32, pattern string, p time.Duration) {
-	loggedData = append(loggedData, logData{cnt, pattern, p})
+	if rep.c[Err0] == 0 {
+		t.Errorf("Err0 was never consolidated")
+	}
+	if rep.c[Err1] == 0 {
+		t.Errorf("Err1 was never consolidated")
+	}
+	if rep.c[Err0]+rep.r[Err0] != ErrCnt0 {
+		t.Errorf("Unexpected Err0 count, expected %d, consolidated %d and reported %d",
+			ErrCnt0, rep.c[Err0], rep.r[Err0])
+	}
+	if rep.c[Err1]+rep.r[Err1] != ErrCnt1 {
+		t.Errorf("Unexpected Err1 count, expected %d, consolidated %d and reported %d",
+			ErrCnt1, rep.c[Err1], rep.r[Err1])
+	}
+	if rep.r[Err2] != ErrCnt2 {
+		t.Errorf("Unexpected Err2 count, expected %d, reported %d",
+			ErrCnt2, rep.r[Err2])
+	}
+	if rep.r[Err3] != ErrCnt3 {
+		t.Errorf("Unexpected Err3 count, expected %d, reported %d",
+			ErrCnt3, rep.r[Err3])
+	}
 }
 
 // error generator
@@ -356,10 +287,10 @@ const (
 	Err2
 	Err3
 
-	ErrStr0 = "Failed to connect"
-	ErrStr1 = "Upstream is down"
-	ErrStr2 = "Access denied"
-	ErrStr3 = "Yet another error"
+	ErrStr0 = "failed to connect"
+	ErrStr1 = "upstream is down"
+	ErrStr2 = "access denied"
+	ErrStr3 = "yet another error"
 
 	ErrCnt0 = 120000
 	ErrCnt1 = 130000
@@ -374,7 +305,8 @@ type errorBunch struct {
 
 type errorGenerator struct {
 	errors   [4]errorBunch
-	doneFlag uint32
+	totalCnt int32
+	totalLim int32
 }
 
 func newErrorGenerator() *errorGenerator {
@@ -387,11 +319,13 @@ func newErrorGenerator() *errorGenerator {
 			{ErrCnt2, fmt.Errorf(ErrStr2)},
 			{ErrCnt3, fmt.Errorf(ErrStr3)},
 		},
+		totalLim: ErrCnt0 + ErrCnt1 + ErrCnt2 + ErrCnt3,
 	}
 }
 
-func (sh *errorGenerator) done() bool {
-	return atomic.LoadUint32(&sh.doneFlag) > 0
+// returns progress as a value from [0..100] range
+func (sh *errorGenerator) progress() int32 {
+	return atomic.LoadInt32(&sh.totalCnt) * 100 / sh.totalLim
 }
 
 func (sh *errorGenerator) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) {
@@ -399,11 +333,11 @@ func (sh *errorGenerator) ServeDNS(ctx context.Context, w dns.ResponseWriter, r
 	for c := 0; c < 4; c++ {
 		errInd := (i + c) & 3
 		if atomic.AddInt32(&sh.errors[errInd].cnt, -1) >= 0 {
+			atomic.AddInt32(&sh.totalCnt, 1)
 			return 0, sh.errors[errInd].err
 		}
 		atomic.AddInt32(&sh.errors[errInd].cnt, 1)
 	}
-	atomic.StoreUint32(&sh.doneFlag, 1)
 	return 0, nil
 }
 
@@ -411,33 +345,39 @@ func (sh *errorGenerator) Name() string { return "errorGenerator" }
 
 // error report
 type errorReport struct {
-	s [4]uint32
-	p [4]uint32
-	l uint32
+	c [4]uint32
+	r [4]uint32
 }
 
-func (er *errorReport) consolidated(i int) uint32 {
-	return atomic.LoadUint32(&er.s[i])
-}
+func makeReport(t *testing.T, b *bytes.Buffer) errorReport {
+	logDump := b.String()
+	r := errorReport{}
 
-func (er *errorReport) incConsolidated(i int, cnt uint32) {
-	atomic.AddUint32(&er.s[i], cnt)
-}
+	re := regexp.MustCompile(`(\d+) errors like '(.*)' occurred`)
+	m := re.FindAllStringSubmatch(logDump, -1)
+	for _, sub := range m {
+		ind := 0
+		switch sub[2] {
+		case pattern0:
+			ind = Err0
+		case pattern1:
+			ind = Err1
+		default:
+			t.Fatalf("Unknown pattern found in log: %s", sub[0])
+		}
+		n, err := strconv.ParseUint(sub[1], 10, 32)
+		if err != nil {
+			t.Fatalf("Invalid number found in log: %s", sub[0])
+		}
+		r.c[ind] += uint32(n)
+	}
+	t.Logf("%d consolidated messages found", len(m))
 
-func (er *errorReport) passed(i int) uint32 {
-	return atomic.LoadUint32(&er.p[i])
-}
-
-func (er *errorReport) incPassed(i int) {
-	atomic.AddUint32(&er.p[i], 1)
-}
-
-func (er *errorReport) loggerCnt() uint32 {
-	return atomic.LoadUint32(&er.l)
-}
-
-func (er *errorReport) incLoggerCnt() {
-	atomic.AddUint32(&er.l, 1)
+	r.r[Err0] = uint32(strings.Count(logDump, ErrStr0))
+	r.r[Err1] = uint32(strings.Count(logDump, ErrStr1))
+	r.r[Err2] = uint32(strings.Count(logDump, ErrStr2))
+	r.r[Err3] = uint32(strings.Count(logDump, ErrStr3))
+	return r
 }
 
 func genErrorHandler(rcode int, err error) plugin.Handler {