more testcases

redwrasse · Feb 17, 2025 · aa34f37 · aa34f37
1 parent 4cf865a
commit aa34f37
Show file tree

Hide file tree

Showing 2 changed files with 72 additions and 22 deletions.
diff --git a/server/etcdserver/api/v3rpc/interceptor.go b/server/etcdserver/api/v3rpc/interceptor.go
@@ -206,7 +206,7 @@ type requestStats struct {
 	reqContent   string
 }
 
-// See https://pkg.go.dev/go.uber.org/zap#example-Object if want to finish
+// See https://pkg.go.dev/go.uber.org/zap#example-Object
 func (rs requestStats) MarshalLogObject(enc zapcore.ObjectEncoder) error {
 	enc.AddTime("start time", rs.startTime)
 	enc.AddDuration("time spent", rs.timeSpent)

diff --git a/server/etcdserver/api/v3rpc/interceptor_test.go b/server/etcdserver/api/v3rpc/interceptor_test.go
@@ -2,7 +2,6 @@ package v3rpc
 
 import (
 	"context"
-	"fmt"
 	"github.com/stretchr/testify/assert"
 	pb "go.etcd.io/etcd/api/v3/etcdserverpb"
 	"go.uber.org/zap"
@@ -30,7 +29,7 @@ import (
 //// to complete the RPC.
 //type UnaryServerInterceptor func(ctx context.Context, req any, info *UnaryServerInfo, handler UnaryHandler) (resp any, err error)
 
-func buildMockHandler(t *testing.T, mockResp interface{}, handlerLatency time.Duration) grpc.UnaryHandler {
+func buildMockUnaryHandler(t *testing.T, mockResp interface{}, handlerLatency time.Duration) grpc.UnaryHandler {
 	t.Helper()
 	return func(ctx context.Context, req interface{}) (interface{}, error) {
 		// Sleep to potentially trigger warn latency threshold in logUnaryInterceptor.
@@ -41,19 +40,20 @@ func buildMockHandler(t *testing.T, mockResp interface{}, handlerLatency time.Du
 
 func TestLogUnaryInterceptor(t *testing.T) {
 
-	// Warn on request latency if > 10ms, so as to trigger expensive request.
-	handlerWarnLatencyThreshold := time.Millisecond * 10
+	// Warn on request latency if > 5ms.
+	handlerWarnLatencyThreshold := time.Millisecond * 5
 
 	unaryServerInfo := &grpc.UnaryServerInfo{
 		FullMethod: "/foo/bar",
 	}
 
 	testcases := []struct {
-		name       string
-		req        interface{}
-		resp       interface{}
-		reqLatency time.Duration
-		debugLevel bool // debugLevel indicates whether log level is debug.
+		name                 string
+		req                  interface{}
+		resp                 interface{}
+		reqLatency           time.Duration
+		debugLevel           bool // debugLevel indicates whether log level is debug.
+		expectedRequestStats requestStats
 	}{
 		// TODO: write only a few testcases, the most important ones. (3-5 testcases total).
 		// Some checks:
@@ -67,13 +67,50 @@ func TestLogUnaryInterceptor(t *testing.T) {
 		// 			reqSizes for sucess and failure are sums of all request entities in the given transaction? (eg. include in test)
 		// 7. Check default unrecognized req/resp type values are -1.
 		// 8. NewLoggableTxnRequest() is involved string repr logic, might be worth testing. (and not tested in rafter_internal_stringer_test.go from what I see).
-		{"expensive RangeRequest", &pb.RangeRequest{Key: []byte("fooKey")}, &pb.RangeResponse{Count: 2},
-			time.Millisecond * 100, true}, // Make this an expensive handler that takes ~ 100 ms.
-		{"default request and response type", "fooRequest", "fooResponse", 0, true},
+		{"expensive RangeRequest", &pb.RangeRequest{Key: []byte("fooKey")}, &pb.RangeResponse{Count: 2}, // TODO justify/make more complete
+			time.Millisecond * 10, false,
+			requestStats{
+				responseType: "/foo/bar",
+				reqCount:     0,
+				reqSize:      8,
+				respCount:    2,
+				respSize:     2,
+				reqContent:   "key:\"fooKey\" ", // why?
+			},
+		}, // Make this an expensive handler that takes ~ 100 ms.
+		{"txn request", &pb.TxnRequest{ // FIXME add Successes and Failures to the TxnRequest
+			Compare: []*pb.Compare{&pb.Compare{
+				Key:      []byte("foo"),
+				RangeEnd: []byte("zoo"),
+			}}},
+			&pb.TxnResponse{
+				Succeeded: true,
+			}, // FIXME make realistic TxnResponse
+			0, true,
+			requestStats{
+				responseType: "/foo/bar",
+				reqCount:     0,
+				respSize:     2, // FIXME why all these values?
+				reqContent:   "compare:<key:\"foo\" range_end:\"zoo\" > success:<> failure:<>",
+			},
+		},
+
+		// Unrecognized request and response types log -1 values in request stats.
+		{"default request and response type", "fooRequest", "fooResponse", 0, true,
+			requestStats{
+				responseType: "/foo/bar",
+				reqCount:     -1,
+				reqSize:      -1,
+				respCount:    -1,
+				respSize:     -1,
+				reqContent:   "", // empty request content for default unrecognized type
+			}},
+		// Testcase with no request stats log generated.
+		{"no debug or warn level logs", "fooRequest", "fooResponse", 0, false, requestStats{}},
 	}
 	for _, tc := range testcases {
 		t.Run(tc.name, func(t *testing.T) {
-			expensiveUnaryHandler := buildMockHandler(t, tc.resp, tc.reqLatency)
+			expensiveUnaryHandler := buildMockUnaryHandler(t, tc.resp, tc.reqLatency)
 			logLevel := zapcore.InfoLevel
 			if tc.debugLevel {
 				logLevel = zapcore.DebugLevel
@@ -85,16 +122,29 @@ func TestLogUnaryInterceptor(t *testing.T) {
 			interceptor := newLogUnaryInterceptor(observedLogger, handlerWarnLatencyThreshold)
 			_, err := interceptor(context.TODO(), tc.req, unaryServerInfo, expensiveUnaryHandler)
 			assert.NoError(t, err)
-			//rangeResp, ok := resp.(*pb.RangeResponse)
-			//assert.True(t, ok)
-			//assert.Equal(t, int64(2), rangeResp.Count)
 
-			// FIXME: make assertions on log messages.
-			for _, le := range observedLogs.All() {
-				if le.Entry.Message == "request stats" {
-					fmt.Println(le.ContextMap())
-				}
+			rsLogs := observedLogs.FilterMessage("request stats")
 
+			// No request stats if log-level is not debug or warn latency threshold is not exceeded.
+			if !(tc.debugLevel || tc.reqLatency > handlerWarnLatencyThreshold) {
+				assert.Equal(t, 0, rsLogs.Len())
+			} else {
+				assert.Equal(t, 1, rsLogs.Len())
+				le := rsLogs.All()[0]
+				fld := le.Context[0]
+				rs, ok := fld.Interface.(requestStats)
+				assert.True(t, ok)
+				assert.Equal(t, tc.expectedRequestStats.responseType, rs.responseType)
+				assert.Equal(t, tc.expectedRequestStats.reqCount, rs.reqCount)
+				assert.Equal(t, tc.expectedRequestStats.reqSize, rs.reqSize)
+				assert.Equal(t, tc.expectedRequestStats.respCount, rs.respCount)
+				assert.Equal(t, tc.expectedRequestStats.respSize, rs.respSize)
+				assert.Equal(t, tc.expectedRequestStats.reqContent, rs.reqContent)
+				if tc.debugLevel {
+					assert.Equal(t, zapcore.DebugLevel, le.Entry.Level)
+				} else {
+					assert.Equal(t, zapcore.WarnLevel, le.Entry.Level)
+				}
 			}
 		})
 	}