merged from gramsrv upstream

internal/rpc/dispatch_context_logging_test.go

@@ -0,0 +1,50 @@
+package rpc
+
+import (
+	"context"
+	"sync"
+	"testing"
+	"time"
+
+	"github.com/iamxvbaba/td/clock"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest/observer"
+)
+
+type loggingStepClock struct {
+	mu   sync.Mutex
+	now  time.Time
+	step time.Duration
+}
+
+func (c *loggingStepClock) Now() time.Time {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	c.now = c.now.Add(c.step)
+	return c.now
+}
+
+func (*loggingStepClock) Timer(d time.Duration) clock.Timer { return clock.System.Timer(d) }
+
+func (*loggingStepClock) Ticker(d time.Duration) clock.Ticker { return clock.System.Ticker(d) }
+
+func TestSlowSuccessfulPreHandlerDoesNotEnterInfoHotPath(t *testing.T) {
+	infoCore, infoLogs := observer.New(zap.InfoLevel)
+	infoRouter := New(Config{}, Deps{}, zap.New(infoCore), &loggingStepClock{step: 25 * time.Millisecond})
+	if _, _, err := infoRouter.prepareRPCDispatchContext(context.Background(), [8]byte{1}, 2, 0, "help.getConfig"); err != nil {
+		t.Fatal(err)
+	}
+	if got := infoLogs.FilterMessage("slow pre-handler").Len(); got != 0 {
+		t.Fatalf("slow successful pre-handler emitted %d Info logs, want none", got)
+	}
+
+	debugCore, debugLogs := observer.New(zap.DebugLevel)
+	debugRouter := New(Config{}, Deps{}, zap.New(debugCore), &loggingStepClock{step: 25 * time.Millisecond})
+	if _, _, err := debugRouter.prepareRPCDispatchContext(context.Background(), [8]byte{1}, 2, 0, "help.getConfig"); err != nil {
+		t.Fatal(err)
+	}
+	entries := debugLogs.FilterMessage("slow pre-handler").All()
+	if len(entries) != 1 || entries[0].Level != zap.DebugLevel {
+		t.Fatalf("slow pre-handler debug entries=%v, want one Debug entry", entries)
+	}
+}