Merge pull request #9588 from gyuho/aaa

rafthttp: add more debugging logs

Procfile

@@ -1,5 +1,5 @@
 # Use goreman to run `go get github.com/mattn/goreman`
-etcd1: bin/etcd --name infra1 --listen-client-urls http://127.0.0.1:2379 --advertise-client-urls http://127.0.0.1:2379 --listen-peer-urls http://127.0.0.1:12380 --initial-advertise-peer-urls http://127.0.0.1:12380 --initial-cluster-token etcd-cluster-1 --initial-cluster 'infra1=http://127.0.0.1:12380,infra2=http://127.0.0.1:22380,infra3=http://127.0.0.1:32380' --initial-cluster-state new --enable-pprof
-etcd2: bin/etcd --name infra2 --listen-client-urls http://127.0.0.1:22379 --advertise-client-urls http://127.0.0.1:22379 --listen-peer-urls http://127.0.0.1:22380 --initial-advertise-peer-urls http://127.0.0.1:22380 --initial-cluster-token etcd-cluster-1 --initial-cluster 'infra1=http://127.0.0.1:12380,infra2=http://127.0.0.1:22380,infra3=http://127.0.0.1:32380' --initial-cluster-state new --enable-pprof
-etcd3: bin/etcd --name infra3 --listen-client-urls http://127.0.0.1:32379 --advertise-client-urls http://127.0.0.1:32379 --listen-peer-urls http://127.0.0.1:32380 --initial-advertise-peer-urls http://127.0.0.1:32380 --initial-cluster-token etcd-cluster-1 --initial-cluster 'infra1=http://127.0.0.1:12380,infra2=http://127.0.0.1:22380,infra3=http://127.0.0.1:32380' --initial-cluster-state new --enable-pprof
+etcd1: bin/etcd --name infra1 --listen-client-urls http://127.0.0.1:2379 --advertise-client-urls http://127.0.0.1:2379 --listen-peer-urls http://127.0.0.1:12380 --initial-advertise-peer-urls http://127.0.0.1:12380 --initial-cluster-token etcd-cluster-1 --initial-cluster 'infra1=http://127.0.0.1:12380,infra2=http://127.0.0.1:22380,infra3=http://127.0.0.1:32380' --initial-cluster-state new --enable-pprof --logger zap --log-output stderr
+etcd2: bin/etcd --name infra2 --listen-client-urls http://127.0.0.1:22379 --advertise-client-urls http://127.0.0.1:22379 --listen-peer-urls http://127.0.0.1:22380 --initial-advertise-peer-urls http://127.0.0.1:22380 --initial-cluster-token etcd-cluster-1 --initial-cluster 'infra1=http://127.0.0.1:12380,infra2=http://127.0.0.1:22380,infra3=http://127.0.0.1:32380' --initial-cluster-state new --enable-pprof --logger zap --log-output stderr
+etcd3: bin/etcd --name infra3 --listen-client-urls http://127.0.0.1:32379 --advertise-client-urls http://127.0.0.1:32379 --listen-peer-urls http://127.0.0.1:32380 --initial-advertise-peer-urls http://127.0.0.1:32380 --initial-cluster-token etcd-cluster-1 --initial-cluster 'infra1=http://127.0.0.1:12380,infra2=http://127.0.0.1:22380,infra3=http://127.0.0.1:32380' --initial-cluster-state new --enable-pprof --logger zap --log-output stderr
 #proxy: bin/etcd grpc-proxy start --endpoints=127.0.0.1:2379,127.0.0.1:22379,127.0.0.1:32379 --listen-addr=127.0.0.1:23790 --advertise-client-url=127.0.0.1:23790 --enable-pprof

etcdserver/membership/cluster.go

@@ -344,8 +344,8 @@ func (c *RaftCluster) AddMember(m *Member) {
 			"added member",
 			zap.String("cluster-id", c.cid.String()),
 			zap.String("local-member-id", c.localID.String()),
-			zap.String("removed-remote-peer-id", m.ID.String()),
-			zap.Strings("removed-remote-peer-peer-urls", m.PeerURLs),
+			zap.String("added-peer-id", m.ID.String()),
+			zap.Strings("added-peer-peer-urls", m.PeerURLs),
 		)
 	} else {
 		plog.Infof("added member %s %v to cluster %s", m.ID, m.PeerURLs, c.cid)
@@ -424,7 +424,7 @@ func (c *RaftCluster) UpdateAttributes(id types.ID, attr Attributes) {
 			"skipped attributes update of removed member",
 			zap.String("cluster-id", c.cid.String()),
 			zap.String("local-member-id", c.localID.String()),
-			zap.String("removed-remote-peer-id", id.String()),
+			zap.String("updated-peer-id", id.String()),
 		)
 	} else {
 		plog.Warningf("skipped updating attributes of removed member %s", id)

rafthttp/http.go

@@ -455,6 +455,8 @@ func (h *streamHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		Writer:  w,
 		Flusher: w.(http.Flusher),
 		Closer:  c,
+		localID: h.tr.ID,
+		peerID:  h.id,
 	}
 	p.attachOutgoingConn(conn)
 	<-c.closeNotify()

rafthttp/peer_status.go

@@ -72,7 +72,7 @@ func (s *peerStatus) deactivate(failure failureType, reason string) {
 		return
 	}
 	if s.lg != nil {
-		s.lg.Warn("peer deactivated again", zap.String("peer-id", s.id.String()), zap.Error(errors.New(msg)))
+		s.lg.Debug("peer deactivated again", zap.String("peer-id", s.id.String()), zap.Error(errors.New(msg)))
 	}
 }
 

rafthttp/stream.go

@@ -101,6 +101,9 @@ type outgoingConn struct {
 	io.Writer
 	http.Flusher
 	io.Closer
+
+	localID types.ID
+	peerID  types.ID
 }
 
 // streamWriter writes messages to the attached outgoingConn.
@@ -242,6 +245,14 @@ func (cw *streamWriter) run() {
 			default:
 				plog.Panicf("unhandled stream type %s", conn.t)
 			}
+			if cw.lg != nil {
+				cw.lg.Info(
+					"set message encoder",
+					zap.String("from", conn.localID.String()),
+					zap.String("to", conn.peerID.String()),
+					zap.String("stream-type", t.String()),
+				)
+			}
 			flusher = conn.Flusher
 			unflushed = 0
 			cw.status.activate()
@@ -578,6 +589,14 @@ func (cr *streamReader) dial(t streamType) (io.ReadCloser, error) {
 	uu := u
 	uu.Path = path.Join(t.endpoint(), cr.tr.ID.String())
 
+	if cr.lg != nil {
+		cr.lg.Debug(
+			"dial stream reader",
+			zap.String("from", cr.tr.ID.String()),
+			zap.String("to", cr.peerID.String()),
+			zap.String("address", uu.String()),
+		)
+	}
 	req, err := http.NewRequest("GET", uu.String(), nil)
 	if err != nil {
 		cr.picker.unreachable(u)

rafthttp/transport.go

@@ -286,6 +286,15 @@ func (t *Transport) AddRemote(id types.ID, us []string) {
 		}
 	}
 	t.remotes[id] = startRemote(t, urls, id)
+
+	if t.Logger != nil {
+		t.Logger.Info(
+			"added new remote peer",
+			zap.String("local-member-id", t.ID.String()),
+			zap.String("remote-peer-id", id.String()),
+			zap.Strings("remote-peer-urls", us),
+		)
+	}
 }
 
 func (t *Transport) AddPeer(id types.ID, us []string) {
@@ -311,7 +320,12 @@ func (t *Transport) AddPeer(id types.ID, us []string) {
 	addPeerToProber(t.Logger, t.prober, id.String(), us)
 
 	if t.Logger != nil {
-		t.Logger.Info("added remote peer", zap.String("remote-peer-id", id.String()))
+		t.Logger.Info(
+			"added remote peer",
+			zap.String("local-member-id", t.ID.String()),
+			zap.String("remote-peer-id", id.String()),
+			zap.Strings("remote-peer-urls", us),
+		)
 	} else {
 		plog.Infof("added peer %s", id)
 	}
@@ -347,7 +361,11 @@ func (t *Transport) removePeer(id types.ID) {
 	t.prober.Remove(id.String())
 
 	if t.Logger != nil {
-		t.Logger.Info("removed remote peer", zap.String("remote-peer-id", id.String()))
+		t.Logger.Info(
+			"removed remote peer",
+			zap.String("local-member-id", t.ID.String()),
+			zap.String("removed-remote-peer-id", id.String()),
+		)
 	} else {
 		plog.Infof("removed peer %s", id)
 	}
@@ -374,7 +392,12 @@ func (t *Transport) UpdatePeer(id types.ID, us []string) {
 	addPeerToProber(t.Logger, t.prober, id.String(), us)
 
 	if t.Logger != nil {
-		t.Logger.Info("updated remote peer", zap.String("remote-peer-id", id.String()))
+		t.Logger.Info(
+			"updated remote peer",
+			zap.String("local-member-id", t.ID.String()),
+			zap.String("updated-remote-peer-id", id.String()),
+			zap.Strings("updated-remote-peer-urls", us),
+		)
 	} else {
 		plog.Infof("updated peer %s", id)
 	}