coredns/plugin/errors/errors_test.go

package errors

import (
	"bytes"
	"context"
	"errors"
	"fmt"
	golog "log"
	"math/rand"
	"regexp"
	"strings"
	"sync"
	"sync/atomic"
	"testing"
	"time"

	"github.com/coredns/coredns/plugin"
	"github.com/coredns/coredns/plugin/pkg/dnstest"
	"github.com/coredns/coredns/plugin/test"

	"github.com/miekg/dns"
)

func TestErrors(t *testing.T) {
	buf := bytes.Buffer{}
	golog.SetOutput(&buf)
	em := errorHandler{eLogger: errorLogger}

	testErr := errors.New("test error")
	tests := []struct {
		next         plugin.Handler
		expectedCode int
		expectedLog  string
		expectedErr  error
	}{
		{
			next:         genErrorHandler(dns.RcodeSuccess, nil),
			expectedCode: dns.RcodeSuccess,
			expectedLog:  "",
			expectedErr:  nil,
		},
		{
			next:         genErrorHandler(dns.RcodeNotAuth, testErr),
			expectedCode: dns.RcodeNotAuth,
			expectedLog:  fmt.Sprintf("%d %s: %v\n", dns.RcodeNotAuth, "example.org. A", testErr),
			expectedErr:  testErr,
		},
	}

	ctx := context.TODO()
	req := new(dns.Msg)
	req.SetQuestion("example.org.", dns.TypeA)

	for i, tc := range tests {
		em.Next = tc.next
		buf.Reset()
		rec := dnstest.NewRecorder(&test.ResponseWriter{})
		code, err := em.ServeDNS(ctx, rec, req)

		if err != tc.expectedErr {
			t.Errorf("Test %d: Expected error %v, but got %v",
				i, tc.expectedErr, err)
		}
		if code != tc.expectedCode {
			t.Errorf("Test %d: Expected status code %d, but got %d",
				i, tc.expectedCode, code)
		}
		if log := buf.String(); !strings.Contains(log, tc.expectedLog) {
			t.Errorf("Test %d: Expected log %q, but got %q",
				i, tc.expectedLog, log)
		}
	}
}

func TestConsLogger(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.*!$"),
		}},
		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))
	}
}

func TestInc(t *testing.T) {
	h := &errorHandler{
		stopFlag: 1,
		patterns: []*pattern{{
			period:  2 * time.Second,
			pattern: regexp.MustCompile("^Error.*!$"),
		}},
		cLogger: testConsLogger,
	}

	ret := h.inc(0)
	if ret {
		t.Error("Unexpected return value, expected false, actual true")
	}

	h.stopFlag = 0
	ret = h.inc(0)
	if !ret {
		t.Error("Unexpected return value, expected true, actual false")
	}

	expCnt := uint32(1)
	actCnt := atomic.LoadUint32(&h.patterns[0].count)
	if actCnt != expCnt {
		t.Errorf("Unexpected 'count', expected %d, actual %d", expCnt, actCnt)
	}

	t1 := h.patterns[0].timer()
	if t1 == nil {
		t.Error("Unexpected 'timer', expected not nil")
	}

	ret = h.inc(0)
	if !ret {
		t.Error("Unexpected return value, expected true, actual false")
	}

	expCnt = uint32(2)
	actCnt = atomic.LoadUint32(&h.patterns[0].count)
	if actCnt != expCnt {
		t.Errorf("Unexpected 'count', expected %d, actual %d", expCnt, actCnt)
	}

	t2 := h.patterns[0].timer()
	if t2 != t1 {
		t.Error("Unexpected 'timer', expected the same")
	}

	ret = t1.Stop()
	if !ret {
		t.Error("Timer was unexpectedly stopped before")
	}
	ret = t2.Stop()
	if ret {
		t.Error("Timer was unexpectedly not stopped before")
	}
}

func TestStop(t *testing.T) {
	h := &errorHandler{
		patterns: []*pattern{{
			period:  2 * time.Second,
			pattern: regexp.MustCompile("^Error.*!$"),
		}},
		cLogger: testConsLogger,
	}
	loggedData = loggedData[:0]

	h.inc(0)
	h.inc(0)
	h.inc(0)
	expCnt := uint32(3)
	actCnt := atomic.LoadUint32(&h.patterns[0].count)
	if actCnt != expCnt {
		t.Fatalf("Unexpected initial 'count', expected %d, actual %d", expCnt, actCnt)
	}

	h.stop()

	expCnt = uint32(0)
	actCnt = atomic.LoadUint32(&h.patterns[0].count)
	if actCnt != expCnt {
		t.Errorf("Unexpected 'count', expected %d, actual %d", expCnt, actCnt)
	}

	expStop := uint32(1)
	actStop := h.stopFlag
	if actStop != expStop {
		t.Errorf("Unexpected 'stop', expected %d, actual %d", expStop, actStop)
	}

	t1 := h.patterns[0].timer()
	if t1 == nil {
		t.Error("Unexpected 'timer', expected not nil")
	} else if t1.Stop() {
		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)
	}
}

func TestServeDNSConcurrent(t *testing.T) {
	eg := newErrorGenerator()
	rep := &errorReport{}

	h := &errorHandler{
		patterns: []*pattern{
			{
				period:  3 * time.Nanosecond,
				pattern: regexp.MustCompile("Failed"),
			},
			{
				period:  2 * time.Nanosecond,
				pattern: regexp.MustCompile("down$"),
			},
		},
		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,
	}

	ctx := context.TODO()
	r := new(dns.Msg)
	w := &test.ResponseWriter{}

	var wg sync.WaitGroup
	runnersCnt := 9
	runner := func() {
		defer wg.Done()
		for !eg.done() {
			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 {
			h.stop()
			stopCalled = true
		}
		h.ServeDNS(ctx, w, r)
	}
	if !stopCalled {
		h.stop()
	}

	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))
	}
}

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})
}

// error generator
const (
	Err0 = iota
	Err1
	Err2
	Err3

	ErrStr0 = "Failed to connect"
	ErrStr1 = "Upstream is down"
	ErrStr2 = "Access denied"
	ErrStr3 = "Yet another error"

	ErrCnt0 = 120000
	ErrCnt1 = 130000
	ErrCnt2 = 150000
	ErrCnt3 = 100000
)

type errorBunch struct {
	cnt int32
	err error
}

type errorGenerator struct {
	errors   [4]errorBunch
	doneFlag uint32
}

func newErrorGenerator() *errorGenerator {
	rand.Seed(time.Now().UnixNano())

	return &errorGenerator{
		errors: [4]errorBunch{
			{ErrCnt0, fmt.Errorf(ErrStr0)},
			{ErrCnt1, fmt.Errorf(ErrStr1)},
			{ErrCnt2, fmt.Errorf(ErrStr2)},
			{ErrCnt3, fmt.Errorf(ErrStr3)},
		},
	}
}

func (sh *errorGenerator) done() bool {
	return atomic.LoadUint32(&sh.doneFlag) > 0
}

func (sh *errorGenerator) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) {
	i := rand.Int()
	for c := 0; c < 4; c++ {
		errInd := (i + c) & 3
		if atomic.AddInt32(&sh.errors[errInd].cnt, -1) >= 0 {
			return 0, sh.errors[errInd].err
		}
		atomic.AddInt32(&sh.errors[errInd].cnt, 1)
	}
	atomic.StoreUint32(&sh.doneFlag, 1)
	return 0, nil
}

func (sh *errorGenerator) Name() string { return "errorGenerator" }

// error report
type errorReport struct {
	s [4]uint32
	p [4]uint32
	l uint32
}

func (er *errorReport) consolidated(i int) uint32 {
	return atomic.LoadUint32(&er.s[i])
}

func (er *errorReport) incConsolidated(i int, cnt uint32) {
	atomic.AddUint32(&er.s[i], cnt)
}

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)
}

func genErrorHandler(rcode int, err error) plugin.Handler {
	return plugin.HandlerFunc(func(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) {
		return rcode, err
	})
}