Merge pull request #12238 from liggitt/slow-v2-panic

etcdserver: Avoid panics logging slow v2 requests in integration tests

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":

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
+}

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()
+}