diff --git a/etcdserver/apply_v2.go b/etcdserver/apply_v2.go index ad88f4657..48bfc6685 100644 --- a/etcdserver/apply_v2.go +++ b/etcdserver/apply_v2.go @@ -16,6 +16,7 @@ package etcdserver import ( "encoding/json" + "fmt" "path" "time" @@ -109,7 +110,11 @@ func (a *applierV2store) Sync(r *RequestV2) Response { // applyV2Request interprets r as a call to v2store.X // and returns a Response interpreted from v2store.Event func (s *EtcdServer) applyV2Request(r *RequestV2) Response { - defer warnOfExpensiveRequest(s.getLogger(), time.Now(), r, nil, nil) + stringer := panicAlternativeStringer{ + stringer: r, + alternative: func() string { return fmt.Sprintf("id:%d,method:%s,path:%s", r.ID, r.Method, r.Path) }, + } + defer warnOfExpensiveRequest(s.getLogger(), time.Now(), stringer, nil, nil) switch r.Method { case "POST": diff --git a/etcdserver/util.go b/etcdserver/util.go index 6dfa5fd45..91b3f72c9 100644 --- a/etcdserver/util.go +++ b/etcdserver/util.go @@ -171,3 +171,21 @@ func warnOfExpensiveGenericRequest(lg *zap.Logger, now time.Time, reqStringer fm func isNil(msg proto.Message) bool { return msg == nil || reflect.ValueOf(msg).IsNil() } + +// panicAlternativeStringer wraps a fmt.Stringer, and if calling String() panics, calls the alternative instead. +// This is needed to ensure logging slow v2 requests does not panic, which occurs when running integration tests +// with the embedded server with github.com/golang/protobuf v1.4.0+. See https://github.com/etcd-io/etcd/issues/12197. +type panicAlternativeStringer struct { + stringer fmt.Stringer + alternative func() string +} + +func (n panicAlternativeStringer) String() (s string) { + defer func() { + if err := recover(); err != nil { + s = n.alternative() + } + }() + s = n.stringer.String() + return s +} diff --git a/etcdserver/util_test.go b/etcdserver/util_test.go index 3c4ee7ee9..8a5c54d72 100644 --- a/etcdserver/util_test.go +++ b/etcdserver/util_test.go @@ -90,3 +90,23 @@ func (s *nopTransporterWithActiveTime) Stop() {} func (s *nopTransporterWithActiveTime) Pause() {} func (s *nopTransporterWithActiveTime) Resume() {} func (s *nopTransporterWithActiveTime) reset(am map[types.ID]time.Time) { s.activeMap = am } + +func TestPanicAlternativeStringer(t *testing.T) { + p := panicAlternativeStringer{alternative: func() string { return "alternative" }} + + p.stringer = testStringerFunc(func() string { panic("here") }) + if s := p.String(); s != "alternative" { + t.Fatalf("expected 'alternative', got %q", s) + } + + p.stringer = testStringerFunc(func() string { return "test" }) + if s := p.String(); s != "test" { + t.Fatalf("expected 'test', got %q", s) + } +} + +type testStringerFunc func() string + +func (s testStringerFunc) String() string { + return s() +}