From 0f07519e9efdd13418ab57daec94a58f59a08bf6 Mon Sep 17 00:00:00 2001 From: crazycs Date: Fri, 15 Sep 2023 23:49:42 +0800 Subject: [PATCH 1/4] refact mock tikv server Signed-off-by: crazycs520 --- internal/client/client_fail_test.go | 10 ++--- internal/client/client_test.go | 23 ++++++------ internal/client/main_test.go | 1 + .../mock_tikv_service.go} | 37 ++++++++++++------- 4 files changed, 42 insertions(+), 29 deletions(-) rename internal/client/{mock_tikv_service_test.go => mock_server/mock_tikv_service.go} (77%) diff --git a/internal/client/client_fail_test.go b/internal/client/client_fail_test.go index 43e7697696..e7d4139707 100644 --- a/internal/client/client_fail_test.go +++ b/internal/client/client_fail_test.go @@ -36,7 +36,6 @@ package client import ( "context" - "fmt" "sync/atomic" "testing" "time" @@ -47,6 +46,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/tikv/client-go/v2/config" + "github.com/tikv/client-go/v2/internal/client/mock_server" "github.com/tikv/client-go/v2/tikvrpc" ) @@ -54,11 +54,11 @@ func TestPanicInRecvLoop(t *testing.T) { require.Nil(t, failpoint.Enable("tikvclient/panicInFailPendingRequests", `panic`)) require.Nil(t, failpoint.Enable("tikvclient/gotErrorInRecvLoop", `return("0")`)) - server, port := startMockTikvService() + server, port := mock_server.StartMockTikvService() require.True(t, port > 0) defer server.Stop() - addr := fmt.Sprintf("%s:%d", "127.0.0.1", port) + addr := server.Addr() rpcClient := NewRPCClient() rpcClient.option.dialTimeout = time.Second / 3 @@ -82,10 +82,10 @@ func TestPanicInRecvLoop(t *testing.T) { } func TestRecvErrorInMultipleRecvLoops(t *testing.T) { - server, port := startMockTikvService() + server, port := mock_server.StartMockTikvService() require.True(t, port > 0) defer server.Stop() - addr := fmt.Sprintf("%s:%d", "127.0.0.1", port) + addr := server.Addr() // Enable batch and limit the connection count to 1 so that // there is only one BatchCommands stream for each host or forwarded host. diff --git a/internal/client/client_test.go b/internal/client/client_test.go index 52bf305649..c01f753d4e 100644 --- a/internal/client/client_test.go +++ b/internal/client/client_test.go @@ -55,6 +55,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/tikv/client-go/v2/config" + "github.com/tikv/client-go/v2/internal/client/mock_server" "github.com/tikv/client-go/v2/internal/logutil" "github.com/tikv/client-go/v2/tikvrpc" "go.uber.org/zap" @@ -116,11 +117,11 @@ func TestCancelTimeoutRetErr(t *testing.T) { } func TestSendWhenReconnect(t *testing.T) { - server, port := startMockTikvService() + server, port := mock_server.StartMockTikvService() require.True(t, port > 0) rpcClient := NewRPCClient() - addr := fmt.Sprintf("%s:%d", "127.0.0.1", port) + addr := server.Addr() conn, err := rpcClient.getConnArray(addr, true) assert.Nil(t, err) @@ -240,7 +241,7 @@ func TestCollapseResolveLock(t *testing.T) { } func TestForwardMetadataByUnaryCall(t *testing.T) { - server, port := startMockTikvService() + server, port := mock_server.StartMockTikvService() require.True(t, port > 0) defer server.Stop() addr := fmt.Sprintf("%s:%d", "127.0.0.1", port) @@ -255,7 +256,7 @@ func TestForwardMetadataByUnaryCall(t *testing.T) { var checkCnt uint64 // Check no corresponding metadata if ForwardedHost is empty. - server.setMetaChecker(func(ctx context.Context) error { + server.SetMetaChecker(func(ctx context.Context) error { atomic.AddUint64(&checkCnt, 1) // gRPC may set some metadata by default, e.g. "context-type". md, ok := metadata.FromIncomingContext(ctx) @@ -283,7 +284,7 @@ func TestForwardMetadataByUnaryCall(t *testing.T) { checkCnt = 0 forwardedHost := "127.0.0.1:6666" // Check the metadata exists. - server.setMetaChecker(func(ctx context.Context) error { + server.SetMetaChecker(func(ctx context.Context) error { atomic.AddUint64(&checkCnt, 1) // gRPC may set some metadata by default, e.g. "context-type". md, ok := metadata.FromIncomingContext(ctx) @@ -308,10 +309,10 @@ func TestForwardMetadataByUnaryCall(t *testing.T) { } func TestForwardMetadataByBatchCommands(t *testing.T) { - server, port := startMockTikvService() + server, port := mock_server.StartMockTikvService() require.True(t, port > 0) defer server.Stop() - addr := fmt.Sprintf("%s:%d", "127.0.0.1", port) + addr := server.Addr() // Enable batch and limit the connection count to 1 so that // there is only one BatchCommands stream for each host or forwarded host. @@ -324,7 +325,7 @@ func TestForwardMetadataByBatchCommands(t *testing.T) { var checkCnt uint64 setCheckHandler := func(forwardedHost string) { - server.setMetaChecker(func(ctx context.Context) error { + server.SetMetaChecker(func(ctx context.Context) error { atomic.AddUint64(&checkCnt, 1) md, ok := metadata.FromIncomingContext(ctx) if forwardedHost == "" { @@ -641,10 +642,10 @@ func TestBatchClientRecoverAfterServerRestart(t *testing.T) { conf.TiKVClient.MaxBatchSize = 128 })() - server, port := startMockTikvService() + server, port := mock_server.StartMockTikvService() require.True(t, port > 0) require.True(t, server.IsRunning()) - addr := server.addr + addr := server.Addr() client := NewRPCClient() defer func() { err := client.Close() @@ -681,7 +682,7 @@ func TestBatchClientRecoverAfterServerRestart(t *testing.T) { logutil.BgLogger().Info("restart mock tikv server") server.Start(addr) require.True(t, server.IsRunning()) - require.Equal(t, addr, server.addr) + require.Equal(t, addr, server.Addr()) // Wait batch client to auto reconnect. start := time.Now() diff --git a/internal/client/main_test.go b/internal/client/main_test.go index c4d2be246f..6a22714f06 100644 --- a/internal/client/main_test.go +++ b/internal/client/main_test.go @@ -26,6 +26,7 @@ func TestMain(m *testing.M) { opts := []goleak.Option{ goleak.IgnoreTopFunction("google.golang.org/grpc.(*ClientConn).WaitForStateChange"), goleak.IgnoreTopFunction("github.com/tikv/client-go/v2/internal/retry.newBackoffFn.func1"), + goleak.IgnoreTopFunction("github.com/tikv/client-go/v2/internal/retry.(*Config).createBackoffFn.newBackoffFn.func2"), } goleak.VerifyTestMain(m, opts...) } diff --git a/internal/client/mock_tikv_service_test.go b/internal/client/mock_server/mock_tikv_service.go similarity index 77% rename from internal/client/mock_tikv_service_test.go rename to internal/client/mock_server/mock_tikv_service.go index 40234c1d58..392d3a5fbd 100644 --- a/internal/client/mock_tikv_service_test.go +++ b/internal/client/mock_server/mock_tikv_service.go @@ -18,7 +18,7 @@ // https://github.com/pingcap/tidb/tree/cc5e161ac06827589c4966674597c137cc9e809c/store/tikv/client/mock_tikv_service_test.go // -package client +package mock_server import ( "context" @@ -36,7 +36,7 @@ import ( "google.golang.org/grpc" ) -type server struct { +type MockServer struct { tikvpb.TikvServer grpcServer *grpc.Server addr string @@ -49,21 +49,28 @@ type server struct { } } -func (s *server) KvPrewrite(ctx context.Context, req *kvrpcpb.PrewriteRequest) (*kvrpcpb.PrewriteResponse, error) { +func (s *MockServer) KvGet(ctx context.Context, req *kvrpcpb.GetRequest) (*kvrpcpb.GetResponse, error) { + if err := s.checkMetadata(ctx); err != nil { + return nil, err + } + return &kvrpcpb.GetResponse{}, nil +} + +func (s *MockServer) KvPrewrite(ctx context.Context, req *kvrpcpb.PrewriteRequest) (*kvrpcpb.PrewriteResponse, error) { if err := s.checkMetadata(ctx); err != nil { return nil, err } return &kvrpcpb.PrewriteResponse{}, nil } -func (s *server) CoprocessorStream(req *coprocessor.Request, ss tikvpb.Tikv_CoprocessorStreamServer) error { +func (s *MockServer) CoprocessorStream(req *coprocessor.Request, ss tikvpb.Tikv_CoprocessorStreamServer) error { if err := s.checkMetadata(ss.Context()); err != nil { return err } return ss.Send(&coprocessor.Response{}) } -func (s *server) BatchCommands(ss tikvpb.Tikv_BatchCommandsServer) error { +func (s *MockServer) BatchCommands(ss tikvpb.Tikv_BatchCommandsServer) error { if err := s.checkMetadata(ss.Context()); err != nil { return err } @@ -94,13 +101,13 @@ func (s *server) BatchCommands(ss tikvpb.Tikv_BatchCommandsServer) error { } } -func (s *server) setMetaChecker(check func(context.Context) error) { +func (s *MockServer) SetMetaChecker(check func(context.Context) error) { s.metaChecker.Lock() s.metaChecker.check = check s.metaChecker.Unlock() } -func (s *server) checkMetadata(ctx context.Context) error { +func (s *MockServer) checkMetadata(ctx context.Context) error { s.metaChecker.Lock() defer s.metaChecker.Unlock() if s.metaChecker.check != nil { @@ -109,16 +116,20 @@ func (s *server) checkMetadata(ctx context.Context) error { return nil } -func (s *server) IsRunning() bool { +func (s *MockServer) IsRunning() bool { return atomic.LoadInt64(&s.running) == 1 } -func (s *server) Stop() { +func (s *MockServer) Addr() string { + return s.addr +} + +func (s *MockServer) Stop() { s.grpcServer.Stop() atomic.StoreInt64(&s.running, 0) } -func (s *server) Start(addr string) int { +func (s *MockServer) Start(addr string) int { if addr == "" { addr = fmt.Sprintf("%s:%d", "127.0.0.1", 0) } @@ -148,9 +159,9 @@ func (s *server) Start(addr string) int { return port } -// Try to start a gRPC server and retrun the server instance and binded port. -func startMockTikvService() (*server, int) { - server := &server{} +// StartMockTikvService try to start a gRPC server and retrun the server instance and binded port. +func StartMockTikvService() (*MockServer, int) { + server := &MockServer{} port := server.Start("") return server, port } From e5da718c6c5e8db2cc510c5895fdcac04244e0a2 Mon Sep 17 00:00:00 2001 From: crazycs520 Date: Mon, 16 Oct 2023 23:57:51 +0800 Subject: [PATCH 2/4] fix Signed-off-by: crazycs520 --- internal/client/client_batch.go | 6 ++- internal/locate/region_request_test.go | 53 ++++++++++++++++++++++++++ tikvrpc/tikvrpc.go | 4 +- 3 files changed, 61 insertions(+), 2 deletions(-) diff --git a/internal/client/client_batch.go b/internal/client/client_batch.go index 3c1129bc5f..2467df70d7 100644 --- a/internal/client/client_batch.go +++ b/internal/client/client_batch.go @@ -296,6 +296,9 @@ func (a *batchConn) fetchMorePendingRequests( const idleTimeout = 3 * time.Minute +// BatchSendLoopPanicFlag only used for testing. +var BatchSendLoopPanicFlag = int64(0) + func (a *batchConn) batchSendLoop(cfg config.TiKVClient) { defer func() { if r := recover(); r != nil { @@ -303,7 +306,8 @@ func (a *batchConn) batchSendLoop(cfg config.TiKVClient) { logutil.BgLogger().Error("batchSendLoop", zap.Reflect("r", r), zap.Stack("stack")) - logutil.BgLogger().Info("restart batchSendLoop") + atomic.AddInt64(&BatchSendLoopPanicFlag, 1) + logutil.BgLogger().Info("restart batchSendLoop", zap.Int64("count", atomic.LoadInt64(&BatchSendLoopPanicFlag))) go a.batchSendLoop(cfg) } }() diff --git a/internal/locate/region_request_test.go b/internal/locate/region_request_test.go index 3e187cf804..701c1facd5 100644 --- a/internal/locate/region_request_test.go +++ b/internal/locate/region_request_test.go @@ -37,8 +37,10 @@ package locate import ( "context" "fmt" + "math/rand" "net" "sync" + "sync/atomic" "testing" "time" "unsafe" @@ -51,7 +53,9 @@ import ( "github.com/pingcap/kvproto/pkg/tikvpb" "github.com/pkg/errors" "github.com/stretchr/testify/suite" + "github.com/tikv/client-go/v2/config" "github.com/tikv/client-go/v2/internal/client" + "github.com/tikv/client-go/v2/internal/client/mock_server" "github.com/tikv/client-go/v2/internal/mockstore/mocktikv" "github.com/tikv/client-go/v2/internal/retry" "github.com/tikv/client-go/v2/tikvrpc" @@ -659,3 +663,52 @@ func (s *testRegionRequestToSingleStoreSuite) TestStaleReadRetry() { s.Nil(regionErr) s.Equal([]byte("value"), resp.Resp.(*kvrpcpb.GetResponse).Value) } + +func (s *testRegionRequestToSingleStoreSuite) TestBatchClientSendLoopPanic() { + // This test should use `go test -race` to run. + config.UpdateGlobal(func(conf *config.Config) { + conf.TiKVClient.MaxBatchSize = 128 + })() + + server, port := mock_server.StartMockTikvService() + s.True(port > 0) + rpcClient := client.NewRPCClient() + s.regionRequestSender.client = &fnClient{fn: func(ctx context.Context, addr string, req *tikvrpc.Request, timeout time.Duration) (response *tikvrpc.Response, err error) { + return rpcClient.SendRequest(ctx, server.Addr(), req, timeout) + }} + tf := func(s *Store, bo *retry.Backoffer) livenessState { + return reachable + } + + defer func() { + rpcClient.Close() + server.Stop() + }() + + var wg sync.WaitGroup + for i := 0; i < 100; i++ { + wg.Add(1) + go func() { + defer wg.Done() + for j := 0; j < 100; j++ { + ctx, cancel := context.WithCancel(context.Background()) + bo := retry.NewBackofferWithVars(ctx, int(client.ReadTimeoutShort.Milliseconds()), nil) + region, err := s.cache.LocateRegionByID(bo, s.region) + s.Nil(err) + s.NotNil(region) + go func() { + // mock for kill query execution or timeout. + time.Sleep(time.Millisecond * time.Duration(rand.Intn(5)+1)) + cancel() + }() + req := tikvrpc.NewRequest(tikvrpc.CmdCop, &coprocessor.Request{Data: []byte("a"), StartTs: 1}) + regionRequestSender := NewRegionRequestSender(s.cache, s.regionRequestSender.client) + regionRequestSender.regionCache.testingKnobs.mockRequestLiveness.Store((*livenessFunc)(&tf)) + regionRequestSender.SendReq(bo, req, region.Region, client.ReadTimeoutShort) + } + }() + } + wg.Wait() + // batchSendLoop should not panic. + s.Equal(atomic.LoadInt64(&client.BatchSendLoopPanicFlag), int64(0)) +} diff --git a/tikvrpc/tikvrpc.go b/tikvrpc/tikvrpc.go index 0119e55db1..25cdb04493 100644 --- a/tikvrpc/tikvrpc.go +++ b/tikvrpc/tikvrpc.go @@ -699,7 +699,9 @@ type MPPStreamResponse struct { // SetContext set the Context field for the given req to the specified ctx. func SetContext(req *Request, region *metapb.Region, peer *metapb.Peer) error { - ctx := &req.Context + // Shallow copy the context to avoid concurrent modification. + copyCtx := req.Context + ctx := ©Ctx if region != nil { ctx.RegionId = region.Id ctx.RegionEpoch = region.RegionEpoch From 1db837bfecfe9384ed587b539836de48b88d0e02 Mon Sep 17 00:00:00 2001 From: crazycs520 Date: Tue, 17 Oct 2023 10:42:10 +0800 Subject: [PATCH 3/4] fix Signed-off-by: crazycs520 --- internal/locate/region_request_test.go | 4 ++-- tikvrpc/tikvrpc.go | 8 +++++--- 2 files changed, 7 insertions(+), 5 deletions(-) diff --git a/internal/locate/region_request_test.go b/internal/locate/region_request_test.go index 701c1facd5..e503405bd3 100644 --- a/internal/locate/region_request_test.go +++ b/internal/locate/region_request_test.go @@ -673,7 +673,7 @@ func (s *testRegionRequestToSingleStoreSuite) TestBatchClientSendLoopPanic() { server, port := mock_server.StartMockTikvService() s.True(port > 0) rpcClient := client.NewRPCClient() - s.regionRequestSender.client = &fnClient{fn: func(ctx context.Context, addr string, req *tikvrpc.Request, timeout time.Duration) (response *tikvrpc.Response, err error) { + fnClient := &fnClient{fn: func(ctx context.Context, addr string, req *tikvrpc.Request, timeout time.Duration) (response *tikvrpc.Response, err error) { return rpcClient.SendRequest(ctx, server.Addr(), req, timeout) }} tf := func(s *Store, bo *retry.Backoffer) livenessState { @@ -702,7 +702,7 @@ func (s *testRegionRequestToSingleStoreSuite) TestBatchClientSendLoopPanic() { cancel() }() req := tikvrpc.NewRequest(tikvrpc.CmdCop, &coprocessor.Request{Data: []byte("a"), StartTs: 1}) - regionRequestSender := NewRegionRequestSender(s.cache, s.regionRequestSender.client) + regionRequestSender := NewRegionRequestSender(s.cache, fnClient) regionRequestSender.regionCache.testingKnobs.mockRequestLiveness.Store((*livenessFunc)(&tf)) regionRequestSender.SendReq(bo, req, region.Region, client.ReadTimeoutShort) } diff --git a/tikvrpc/tikvrpc.go b/tikvrpc/tikvrpc.go index 25cdb04493..354e0b2ee7 100644 --- a/tikvrpc/tikvrpc.go +++ b/tikvrpc/tikvrpc.go @@ -699,15 +699,17 @@ type MPPStreamResponse struct { // SetContext set the Context field for the given req to the specified ctx. func SetContext(req *Request, region *metapb.Region, peer *metapb.Peer) error { - // Shallow copy the context to avoid concurrent modification. - copyCtx := req.Context - ctx := ©Ctx + ctx := &req.Context if region != nil { ctx.RegionId = region.Id ctx.RegionEpoch = region.RegionEpoch } ctx.Peer = peer + // Shallow copy the context to avoid concurrent modification. + copyCtx := req.Context + ctx = ©Ctx + switch req.Type { case CmdGet: req.Get().Context = ctx From 31fce767aaaa3251a30fb654abfa64dd5a79269e Mon Sep 17 00:00:00 2001 From: crazycs520 Date: Tue, 17 Oct 2023 16:30:13 +0800 Subject: [PATCH 4/4] Fix batch client batchSendLoop panic Signed-off-by: crazycs520 --- internal/client/client_batch.go | 14 +++++++------- internal/locate/region_cache.go | 2 +- internal/locate/region_request_test.go | 2 +- tikvrpc/tikvrpc.go | 15 +++++++++------ util/misc.go | 2 +- 5 files changed, 19 insertions(+), 16 deletions(-) diff --git a/internal/client/client_batch.go b/internal/client/client_batch.go index 2467df70d7..0d572f45d7 100644 --- a/internal/client/client_batch.go +++ b/internal/client/client_batch.go @@ -296,18 +296,18 @@ func (a *batchConn) fetchMorePendingRequests( const idleTimeout = 3 * time.Minute -// BatchSendLoopPanicFlag only used for testing. -var BatchSendLoopPanicFlag = int64(0) +// BatchSendLoopPanicCounter is only used for testing. +var BatchSendLoopPanicCounter int64 = 0 func (a *batchConn) batchSendLoop(cfg config.TiKVClient) { defer func() { if r := recover(); r != nil { metrics.TiKVPanicCounter.WithLabelValues(metrics.LabelBatchSendLoop).Inc() logutil.BgLogger().Error("batchSendLoop", - zap.Reflect("r", r), + zap.Any("r", r), zap.Stack("stack")) - atomic.AddInt64(&BatchSendLoopPanicFlag, 1) - logutil.BgLogger().Info("restart batchSendLoop", zap.Int64("count", atomic.LoadInt64(&BatchSendLoopPanicFlag))) + atomic.AddInt64(&BatchSendLoopPanicCounter, 1) + logutil.BgLogger().Info("restart batchSendLoop", zap.Int64("count", atomic.LoadInt64(&BatchSendLoopPanicCounter))) go a.batchSendLoop(cfg) } }() @@ -434,7 +434,7 @@ func (s *batchCommandsStream) recv() (resp *tikvpb.BatchCommandsResponse, err er if r := recover(); r != nil { metrics.TiKVPanicCounter.WithLabelValues(metrics.LabelBatchRecvLoop).Inc() logutil.BgLogger().Error("batchCommandsClient.recv panic", - zap.Reflect("r", r), + zap.Any("r", r), zap.Stack("stack")) err = errors.New("batch conn recv paniced") } @@ -602,7 +602,7 @@ func (c *batchCommandsClient) batchRecvLoop(cfg config.TiKVClient, tikvTransport if r := recover(); r != nil { metrics.TiKVPanicCounter.WithLabelValues(metrics.LabelBatchRecvLoop).Inc() logutil.BgLogger().Error("batchRecvLoop", - zap.Reflect("r", r), + zap.Any("r", r), zap.Stack("stack")) logutil.BgLogger().Info("restart batchRecvLoop") go c.batchRecvLoop(cfg, tikvTransportLayerLoad, streamClient) diff --git a/internal/locate/region_cache.go b/internal/locate/region_cache.go index 622e70aecc..110b32aa56 100644 --- a/internal/locate/region_cache.go +++ b/internal/locate/region_cache.go @@ -508,7 +508,7 @@ func (c *RegionCache) checkAndResolve(needCheckStores []*Store, needCheck func(* r := recover() if r != nil { logutil.BgLogger().Error("panic in the checkAndResolve goroutine", - zap.Reflect("r", r), + zap.Any("r", r), zap.Stack("stack trace")) } }() diff --git a/internal/locate/region_request_test.go b/internal/locate/region_request_test.go index e503405bd3..7adc5e0146 100644 --- a/internal/locate/region_request_test.go +++ b/internal/locate/region_request_test.go @@ -710,5 +710,5 @@ func (s *testRegionRequestToSingleStoreSuite) TestBatchClientSendLoopPanic() { } wg.Wait() // batchSendLoop should not panic. - s.Equal(atomic.LoadInt64(&client.BatchSendLoopPanicFlag), int64(0)) + s.Equal(atomic.LoadInt64(&client.BatchSendLoopPanicCounter), int64(0)) } diff --git a/tikvrpc/tikvrpc.go b/tikvrpc/tikvrpc.go index 354e0b2ee7..6e1d2373d6 100644 --- a/tikvrpc/tikvrpc.go +++ b/tikvrpc/tikvrpc.go @@ -699,17 +699,20 @@ type MPPStreamResponse struct { // SetContext set the Context field for the given req to the specified ctx. func SetContext(req *Request, region *metapb.Region, peer *metapb.Peer) error { - ctx := &req.Context if region != nil { - ctx.RegionId = region.Id - ctx.RegionEpoch = region.RegionEpoch + req.Context.RegionId = region.Id + req.Context.RegionEpoch = region.RegionEpoch } - ctx.Peer = peer + req.Context.Peer = peer // Shallow copy the context to avoid concurrent modification. - copyCtx := req.Context - ctx = ©Ctx + return AttachContext(req, req.Context) +} +// AttachContext sets the request context to the request, +// Parameter `rpcCtx` use `kvrpcpb.Context` instead of `*kvrpcpb.Context` to avoid concurrent modification by shallow copy. +func AttachContext(req *Request, rpcCtx kvrpcpb.Context) error { + ctx := &rpcCtx switch req.Type { case CmdGet: req.Get().Context = ctx diff --git a/util/misc.go b/util/misc.go index bd3e2b7793..e324bf7974 100644 --- a/util/misc.go +++ b/util/misc.go @@ -89,7 +89,7 @@ func WithRecovery(exec func(), recoverFn func(r interface{})) { } if r != nil { logutil.BgLogger().Error("panic in the recoverable goroutine", - zap.Reflect("r", r), + zap.Any("r", r), zap.Stack("stack trace")) } }()