Merge pull request #9580 from gyuho/log

embed: clean up initial server start logs

embed/config.go

@@ -294,27 +294,37 @@ func NewConfig() *Config {
 	cfg := &Config{
 		MaxSnapFiles: DefaultMaxSnapshots,
 		MaxWalFiles:  DefaultMaxWALs,
+
 		Name: DefaultName,
+
 		SnapCount:       etcdserver.DefaultSnapCount,
 		MaxTxnOps:       DefaultMaxTxnOps,
 		MaxRequestBytes: DefaultMaxRequestBytes,
+
 		GRPCKeepAliveMinTime:  DefaultGRPCKeepAliveMinTime,
 		GRPCKeepAliveInterval: DefaultGRPCKeepAliveInterval,
 		GRPCKeepAliveTimeout:  DefaultGRPCKeepAliveTimeout,
+
 		TickMs:     100,
 		ElectionMs: 1000,
+
 		LPUrls: []url.URL{*lpurl},
 		LCUrls: []url.URL{*lcurl},
 		APUrls: []url.URL{*apurl},
 		ACUrls: []url.URL{*acurl},
+
 		ClusterState:        ClusterStateFlagNew,
 		InitialClusterToken: "etcd-cluster",
+
 		StrictReconfigCheck: DefaultStrictReconfigCheck,
 		Metrics:             "basic",
 		EnableV2:            DefaultEnableV2,
+
 		CORS:          map[string]struct{}{"*": {}},
 		HostWhitelist: map[string]struct{}{"*": {}},
+
 		AuthToken: "simple",
+
 		PreVote: false, // TODO: enable by default in v3.5
 
 		loggerMu:     new(sync.RWMutex),
@@ -642,17 +652,11 @@ func (cfg *Config) Validate() error {
 		return err
 	}
 	if err := checkHostURLs(cfg.APUrls); err != nil {
-		addrs := make([]string, len(cfg.APUrls))
+		addrs := cfg.getAPURLs()
-		for i := range cfg.APUrls {
-			addrs[i] = cfg.APUrls[i].String()
-		}
 		return fmt.Errorf(`--initial-advertise-peer-urls %q must be "host:port" (%v)`, strings.Join(addrs, ","), err)
 	}
 	if err := checkHostURLs(cfg.ACUrls); err != nil {
-		addrs := make([]string, len(cfg.ACUrls))
+		addrs := cfg.getACURLs()
-		for i := range cfg.ACUrls {
-			addrs[i] = cfg.ACUrls[i].String()
-		}
 		return fmt.Errorf(`--advertise-client-urls %q must be "host:port" (%v)`, strings.Join(addrs, ","), err)
 	}
 	// Check if conflicting flags are passed.
@@ -903,3 +907,43 @@ func checkHostURLs(urls []url.URL) error {
 	}
 	return nil
 }
+
+func (cfg *Config) getAPURLs() (ss []string) {
+	ss = make([]string, len(cfg.APUrls))
+	for i := range cfg.APUrls {
+		ss[i] = cfg.APUrls[i].String()
+	}
+	return ss
+}
+
+func (cfg *Config) getLPURLs() (ss []string) {
+	ss = make([]string, len(cfg.LPUrls))
+	for i := range cfg.LPUrls {
+		ss[i] = cfg.LPUrls[i].String()
+	}
+	return ss
+}
+
+func (cfg *Config) getACURLs() (ss []string) {
+	ss = make([]string, len(cfg.ACUrls))
+	for i := range cfg.ACUrls {
+		ss[i] = cfg.ACUrls[i].String()
+	}
+	return ss
+}
+
+func (cfg *Config) getLCURLs() (ss []string) {
+	ss = make([]string, len(cfg.LCUrls))
+	for i := range cfg.LCUrls {
+		ss[i] = cfg.LCUrls[i].String()
+	}
+	return ss
+}
+
+func (cfg *Config) getMetricsURLs() (ss []string) {
+	ss = make([]string, len(cfg.ListenMetricsUrls))
+	for i := range cfg.ListenMetricsUrls {
+		ss[i] = cfg.ListenMetricsUrls[i].String()
+	}
+	return ss
+}

embed/etcd.go

@@ -111,12 +111,26 @@ func StartEtcd(inCfg *Config) (e *Etcd, err error) {
 		e = nil
 	}()
 
-	if e.Peers, err = startPeerListeners(cfg); err != nil {
+	if e.cfg.logger != nil {
+		e.cfg.logger.Info(
+			"configuring peer listeners",
+			zap.Strings("listen-peer-urls", e.cfg.getLPURLs()),
+		)
+	}
+	if e.Peers, err = configurePeerListeners(cfg); err != nil {
 		return e, err
 	}
-	if e.sctxs, err = startClientListeners(cfg); err != nil {
+
+	if e.cfg.logger != nil {
+		e.cfg.logger.Info(
+			"configuring client listeners",
+			zap.Strings("listen-client-urls", e.cfg.getLCURLs()),
+		)
+	}
+	if e.sctxs, err = configureClientListeners(cfg); err != nil {
 		return e, err
 	}
+
 	for _, sctx := range e.sctxs {
 		e.Clients = append(e.Clients, sctx.l)
 	}
@@ -189,11 +203,7 @@ func StartEtcd(inCfg *Config) (e *Etcd, err error) {
 		}
 		sort.Strings(ss)
 		if e.cfg.logger != nil {
-			e.cfg.logger.Info(
+			e.cfg.logger.Info("configured CORS", zap.Strings("cors", ss))
-				"starting with CORS",
-				zap.String("server-id", e.Server.ID().String()),
-				zap.Strings("cors", ss),
-			)
 		} else {
 			plog.Infof("%s starting with cors %q", e.Server.ID(), ss)
 		}
@@ -205,11 +215,7 @@ func StartEtcd(inCfg *Config) (e *Etcd, err error) {
 		}
 		sort.Strings(ss)
 		if e.cfg.logger != nil {
-			e.cfg.logger.Info(
+			e.cfg.logger.Info("configured host whitelist", zap.Strings("hosts", ss))
-				"starting with host whitelist",
-				zap.String("server-id", e.Server.ID().String()),
-				zap.Strings("hosts", ss),
-			)
 		} else {
 			plog.Infof("%s starting with host whitelist %q", e.Server.ID(), ss)
 		}
@@ -240,6 +246,17 @@ func StartEtcd(inCfg *Config) (e *Etcd, err error) {
 		return e, err
 	}
 
+	if e.cfg.logger != nil {
+		e.cfg.logger.Info(
+			"now serving peer/client/metrics",
+			zap.String("local-member-id", e.Server.ID().String()),
+			zap.Strings("initial-advertise-peer-urls", e.cfg.getAPURLs()),
+			zap.Strings("listen-peer-urls", e.cfg.getLPURLs()),
+			zap.Strings("advertise-client-urls", e.cfg.getACURLs()),
+			zap.Strings("listen-client-urls", e.cfg.getLCURLs()),
+			zap.Strings("listen-metrics-urls", e.cfg.getMetricsURLs()),
+		)
+	}
 	serving = true
 	return e, nil
 }
@@ -336,7 +353,7 @@ func stopServers(ctx context.Context, ss *servers) {
 
 func (e *Etcd) Err() <-chan error { return e.errc }
 
-func startPeerListeners(cfg *Config) (peers []*peerListener, err error) {
+func configurePeerListeners(cfg *Config) (peers []*peerListener, err error) {
 	if err = cfg.PeerSelfCert(); err != nil {
 		if cfg.logger != nil {
 			cfg.logger.Fatal("failed to get peer self-signed certs", zap.Error(err))
@@ -360,7 +377,11 @@ func startPeerListeners(cfg *Config) (peers []*peerListener, err error) {
 		for i := range peers {
 			if peers[i] != nil && peers[i].close != nil {
 				if cfg.logger != nil {
-					cfg.logger.Info("stopping listening for peers", zap.String("address", cfg.LPUrls[i].String()))
+					cfg.logger.Warn(
+						"closing peer listener",
+						zap.String("address", cfg.LPUrls[i].String()),
+						zap.Error(err),
+					)
 				} else {
 					plog.Info("stopping listening for peers on ", cfg.LPUrls[i].String())
 				}
@@ -397,11 +418,6 @@ func startPeerListeners(cfg *Config) (peers []*peerListener, err error) {
 		peers[i].close = func(context.Context) error {
 			return peers[i].Listener.Close()
 		}
-		if cfg.logger != nil {
-			cfg.logger.Info("listening for peers", zap.String("address", u.String()))
-		} else {
-			plog.Info("listening for peers on ", u.String())
-		}
 	}
 	return peers, nil
 }
@@ -417,6 +433,7 @@ func (e *Etcd) servePeers() (err error) {
 	}
 
 	for _, p := range e.Peers {
+		u := p.Listener.Addr().String()
 		gs := v3rpc.Server(e.Server, peerTLScfg)
 		m := cmux.New(p.Listener)
 		go gs.Serve(m.Match(cmux.HTTP2()))
@@ -431,7 +448,19 @@ func (e *Etcd) servePeers() (err error) {
 			// gracefully shutdown http.Server
 			// close open listeners, idle connections
 			// until context cancel or time-out
+			if e.cfg.logger != nil {
+				e.cfg.logger.Info(
+					"stopping serving peer traffic",
+					zap.String("address", u),
+				)
+			}
 			stopServers(ctx, &servers{secure: peerTLScfg != nil, grpc: gs, http: srv})
+			if e.cfg.logger != nil {
+				e.cfg.logger.Info(
+					"stopped serving peer traffic",
+					zap.String("address", u),
+				)
+			}
 			return nil
 		}
 	}
@@ -439,13 +468,22 @@ func (e *Etcd) servePeers() (err error) {
 	// start peer servers in a goroutine
 	for _, pl := range e.Peers {
 		go func(l *peerListener) {
+			u := l.Addr().String()
+			if e.cfg.logger != nil {
+				e.cfg.logger.Info(
+					"serving peer traffic",
+					zap.String("address", u),
+				)
+			} else {
+				plog.Info("listening for peers on ", u)
+			}
 			e.errHandler(l.serve())
 		}(pl)
 	}
 	return nil
 }
 
-func startClientListeners(cfg *Config) (sctxs map[string]*serveCtx, err error) {
+func configureClientListeners(cfg *Config) (sctxs map[string]*serveCtx, err error) {
 	if err = cfg.ClientSelfCert(); err != nil {
 		if cfg.logger != nil {
 			cfg.logger.Fatal("failed to get client self-signed certs", zap.Error(err))
@@ -464,7 +502,6 @@ func startClientListeners(cfg *Config) (sctxs map[string]*serveCtx, err error) {
 	sctxs = make(map[string]*serveCtx)
 	for _, u := range cfg.LCUrls {
 		sctx := newServeCtx(cfg.logger)
-
 		if u.Scheme == "http" || u.Scheme == "unix" {
 			if !cfg.ClientTLSInfo.Empty() {
 				if cfg.logger != nil {
@@ -528,20 +565,20 @@ func startClientListeners(cfg *Config) (sctxs map[string]*serveCtx, err error) {
 			}
 		}
 
-		if cfg.logger != nil {
-			cfg.logger.Info("listening for client requests", zap.String("host", u.Host))
-		} else {
-			plog.Info("listening for client requests on ", u.Host)
-		}
 		defer func() {
-			if err != nil {
+			if err == nil {
+				return
+			}
 			sctx.l.Close()
 			if cfg.logger != nil {
-					cfg.logger.Info("stopping listening for client requests", zap.String("host", u.Host))
+				cfg.logger.Warn(
+					"closing peer listener",
+					zap.String("address", u.Host),
+					zap.Error(err),
+				)
 			} else {
 				plog.Info("stopping listening for client requests on ", u.Host)
 			}
-			}
 		}()
 		for k := range cfg.UserHandlers {
 			sctx.userHandlers[k] = cfg.UserHandlers[k]
@@ -561,7 +598,10 @@ func startClientListeners(cfg *Config) (sctxs map[string]*serveCtx, err error) {
 func (e *Etcd) serveClients() (err error) {
 	if !e.cfg.ClientTLSInfo.Empty() {
 		if e.cfg.logger != nil {
-			e.cfg.logger.Info("starting with client TLS", zap.String("tls-info", fmt.Sprintf("%+v", e.cfg.ClientTLSInfo)))
+			e.cfg.logger.Info(
+				"starting with client TLS",
+				zap.String("tls-info", fmt.Sprintf("%+v", e.cfg.ClientTLSInfo)),
+			)
 		} else {
 			plog.Infof("ClientTLS: %s", e.cfg.ClientTLSInfo)
 		}
@@ -627,7 +667,10 @@ func (e *Etcd) serveMetrics() (err error) {
 			e.metricsListeners = append(e.metricsListeners, ml)
 			go func(u url.URL, ln net.Listener) {
 				if e.cfg.logger != nil {
-					e.cfg.logger.Info("listening for metrics", zap.String("url", u.String()))
+					e.cfg.logger.Info(
+						"serving metrics",
+						zap.String("address", u.String()),
+					)
 				} else {
 					plog.Info("listening for metrics on ", u.String())
 				}

embed/serve.go

@@ -90,9 +90,7 @@ func (sctx *serveCtx) serve(
 	logger := defaultLog.New(ioutil.Discard, "etcdhttp", 0)
 	<-s.ReadyNotify()
 
-	if sctx.lg != nil {
+	if sctx.lg == nil {
-		sctx.lg.Info("ready to server client requests")
-	} else {
 		plog.Info("ready to serve client requests")
 	}
 
@@ -136,7 +134,7 @@ func (sctx *serveCtx) serve(
 		sctx.serversC <- &servers{grpc: gs, http: srvhttp}
 		if sctx.lg != nil {
 			sctx.lg.Info(
-				"serving insecure client requests; this is strongly discouraged!",
+				"serving client traffic insecurely; this is strongly discouraged!",
 				zap.String("address", sctx.l.Addr().String()),
 			)
 		} else {
@@ -186,7 +184,7 @@ func (sctx *serveCtx) serve(
 		sctx.serversC <- &servers{secure: true, grpc: gs, http: srv}
 		if sctx.lg != nil {
 			sctx.lg.Info(
-				"serving client requests",
+				"serving client traffic insecurely",
 				zap.String("address", sctx.l.Addr().String()),
 			)
 		} else {

etcdserver/config.go

@@ -248,20 +248,12 @@ func (c *ServerConfig) print(initial bool) {
 			plog.Infof("initial cluster = %s", c.InitialPeerURLsMap)
 		}
 	} else {
-		caddrs := make([]string, len(c.ClientURLs))
-		for i := range c.ClientURLs {
-			caddrs[i] = c.ClientURLs[i].String()
-		}
-		paddrs := make([]string, len(c.PeerURLs))
-		for i := range c.PeerURLs {
-			paddrs[i] = c.PeerURLs[i].String()
-		}
 		state := "new"
 		if !c.NewCluster {
 			state = "existing"
 		}
 		c.Logger.Info(
-			"server starting",
+			"server configuration",
 			zap.String("name", c.Name),
 			zap.String("data-dir", c.DataDir),
 			zap.String("member-dir", c.MemberDir()),
@@ -272,8 +264,8 @@ func (c *ServerConfig) print(initial bool) {
 			zap.Int("election-tick-ms", c.ElectionTicks),
 			zap.String("election-timeout", fmt.Sprintf("%v", time.Duration(c.ElectionTicks*int(c.TickMs))*time.Millisecond)),
 			zap.Uint64("snapshot-count", c.SnapCount),
-			zap.Strings("advertise-client-urls", caddrs),
+			zap.Strings("advertise-client-urls", c.getACURLs()),
-			zap.Strings("initial-advertise-peer-urls", paddrs),
+			zap.Strings("initial-advertise-peer-urls", c.getAPURLs()),
 			zap.Bool("initial", initial),
 			zap.String("initial-cluster", c.InitialPeerURLsMap.String()),
 			zap.String("initial-cluster-state", state),
@@ -309,3 +301,19 @@ func (c *ServerConfig) bootstrapTimeout() time.Duration {
 }
 
 func (c *ServerConfig) backendPath() string { return filepath.Join(c.SnapDir(), "db") }
+
+func (c *ServerConfig) getAPURLs() (ss []string) {
+	ss = make([]string, len(c.PeerURLs))
+	for i := range c.PeerURLs {
+		ss[i] = c.PeerURLs[i].String()
+	}
+	return ss
+}
+
+func (c *ServerConfig) getACURLs() (ss []string) {
+	ss = make([]string, len(c.ClientURLs))
+	for i := range c.ClientURLs {
+		ss[i] = c.ClientURLs[i].String()
+	}
+	return ss
+}

etcdserver/server.go

@@ -711,7 +711,7 @@ func (s *EtcdServer) start() {
 	if s.ClusterVersion() != nil {
 		if lg != nil {
 			lg.Info(
-				"starting server",
+				"starting etcd server",
 				zap.String("local-member-id", s.ID().String()),
 				zap.String("local-server-version", version.Version),
 				zap.String("cluster-id", s.Cluster().ID().String()),
@@ -723,7 +723,7 @@ func (s *EtcdServer) start() {
 	} else {
 		if lg != nil {
 			lg.Info(
-				"starting server",
+				"starting etcd server",
 				zap.String("local-member-id", s.ID().String()),
 				zap.String("local-server-version", version.Version),
 				zap.String("cluster-version", "to_be_decided"),