diff options
Diffstat (limited to 'plugin/errors/errors_test.go')
| -rw-r--r-- | plugin/errors/errors_test.go | 381 |
1 files changed, 377 insertions, 4 deletions
diff --git a/plugin/errors/errors_test.go b/plugin/errors/errors_test.go index afe809c71..9265d3fc2 100644 --- a/plugin/errors/errors_test.go +++ b/plugin/errors/errors_test.go @@ -5,9 +5,14 @@ import ( "context" "errors" "fmt" - "log" + golog "log" + "math/rand" + "regexp" "strings" + "sync" + "sync/atomic" "testing" + "time" "github.com/coredns/coredns/plugin" "github.com/coredns/coredns/plugin/pkg/dnstest" @@ -18,8 +23,8 @@ import ( func TestErrors(t *testing.T) { buf := bytes.Buffer{} - log.SetOutput(&buf) - em := errorHandler{} + golog.SetOutput(&buf) + em := errorHandler{eLogger: errorLogger} testErr := errors.New("test error") tests := []struct { @@ -37,7 +42,7 @@ func TestErrors(t *testing.T) { { next: genErrorHandler(dns.RcodeNotAuth, testErr), expectedCode: dns.RcodeNotAuth, - expectedLog: fmt.Sprintf("[ERROR] %d %s: %v\n", dns.RcodeNotAuth, "example.org. A", testErr), + expectedLog: fmt.Sprintf("%d %s: %v\n", dns.RcodeNotAuth, "example.org. A", testErr), expectedErr: testErr, }, } @@ -67,6 +72,374 @@ func TestErrors(t *testing.T) { } } +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.*!$' occured 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 |