From aa34f374cf4ccdca488e627d086c5bcf44721aea Mon Sep 17 00:00:00 2001 From: redwrasse Date: Mon, 17 Feb 2025 00:13:51 -0800 Subject: [PATCH] more testcases --- server/etcdserver/api/v3rpc/interceptor.go | 2 +- .../etcdserver/api/v3rpc/interceptor_test.go | 92 ++++++++++++++----- 2 files changed, 72 insertions(+), 22 deletions(-) diff --git a/server/etcdserver/api/v3rpc/interceptor.go b/server/etcdserver/api/v3rpc/interceptor.go index c3e4b47c7f7..3e7753f5f65 100644 --- 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 index eda23f06194..9222aef344f 100644 --- 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: 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) + } } }) }