pkg/transport: log cert file not found in server-side

CHANGELOG-3.4.md

@@ -8,8 +8,9 @@ See [code changes](https://github.com/coreos/etcd/compare/v3.3.0...v3.4.0) and [
 
 - TODO: Rewrite [client balancer](TODO) with [new gRPC balancer interface](TODO).
 - Add [jitter to watch progress notify](https://github.com/coreos/etcd/pull/9278) to prevent [spikes in `etcd_network_client_grpc_sent_bytes_total`](https://github.com/coreos/etcd/issues/9246).
-- Add [warnings on requests taking too long](https://github.com/coreos/etcd/pull/9288).
+- Improve [slow requests warning logging](https://github.com/coreos/etcd/pull/9288).
   - e.g. `etcdserver: read-only range request "key:\"\\000\" range_end:\"\\000\" " took too long [3.389041388s] to execute`
+- Improve [TLS setup error logging](https://github.com/coreos/etcd/pull/9518) for [better debugging experience](https://github.com/coreos/etcd/issues/9400).
 - Improve [long-running concurrent read transactions under light write workloads](https://github.com/coreos/etcd/pull/9296).
   - Previously, periodic commit on pending writes blocks incoming read transactions, even if there is no pending write.
   - Now, periodic commit operation does not block concurrent read transactions, thus improves long-running read transaction performance.

embed/config.go

@@ -36,6 +36,7 @@ import (
 
 	"github.com/coreos/pkg/capnslog"
 	"github.com/ghodss/yaml"
+	"go.uber.org/zap"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/grpclog"
 )
@@ -197,9 +198,16 @@ type Config struct {
 	// - https://github.com/coreos/etcd/issues/9353
 	HostWhitelist map[string]struct{}
 
-	Debug                 bool   `json:"debug"`
-	LogPkgLevels          string `json:"log-package-levels"`
-	LogOutput             string `json:"log-output"`
+	// Logger logs server-side operations.
+	// If nil, all logs are discarded.
+	// TODO: make it configurable with existing logger.
+	// Currently, only logs TLS transport.
+	Logger *zap.Logger
+
+	Debug        bool   `json:"debug"`
+	LogPkgLevels string `json:"log-package-levels"`
+	LogOutput    string `json:"log-output"`
+
 	EnablePprof           bool   `json:"enable-pprof"`
 	Metrics               string `json:"metrics"`
 	ListenMetricsUrls     []url.URL
@@ -263,6 +271,7 @@ func NewConfig() *Config {
 	apurl, _ := url.Parse(DefaultInitialAdvertisePeerURLs)
 	lcurl, _ := url.Parse(DefaultListenClientURLs)
 	acurl, _ := url.Parse(DefaultAdvertiseClientURLs)
+	lg, _ := zap.NewProduction()
 	cfg := &Config{
 		MaxSnapFiles:          DefaultMaxSnapshots,
 		MaxWalFiles:           DefaultMaxWALs,
@@ -282,6 +291,7 @@ func NewConfig() *Config {
 		ClusterState:          ClusterStateFlagNew,
 		InitialClusterToken:   "etcd-cluster",
 		StrictReconfigCheck:   DefaultStrictReconfigCheck,
+		Logger:                lg,
 		LogOutput:             DefaultLogOutput,
 		Metrics:               "basic",
 		EnableV2:              DefaultEnableV2,
@@ -315,6 +325,7 @@ func (cfg *Config) SetupLogging() {
 
 	capnslog.SetGlobalLogLevel(capnslog.INFO)
 	if cfg.Debug {
+		cfg.Logger = zap.NewExample()
 		capnslog.SetGlobalLogLevel(capnslog.DEBUG)
 		grpc.EnableTracing = true
 		// enable info, warning, error
@@ -601,7 +612,7 @@ func (cfg *Config) ClientSelfCert() (err error) {
 		for i, u := range cfg.LCUrls {
 			chosts[i] = u.Host
 		}
-		cfg.ClientTLSInfo, err = transport.SelfCert(filepath.Join(cfg.Dir, "fixtures", "client"), chosts)
+		cfg.ClientTLSInfo, err = transport.SelfCert(cfg.Logger, filepath.Join(cfg.Dir, "fixtures", "client"), chosts)
 		return err
 	} else if cfg.ClientAutoTLS {
 		plog.Warningf("ignoring client auto TLS since certs given")
@@ -615,7 +626,7 @@ func (cfg *Config) PeerSelfCert() (err error) {
 		for i, u := range cfg.LPUrls {
 			phosts[i] = u.Host
 		}
-		cfg.PeerTLSInfo, err = transport.SelfCert(filepath.Join(cfg.Dir, "fixtures", "peer"), phosts)
+		cfg.PeerTLSInfo, err = transport.SelfCert(cfg.Logger, filepath.Join(cfg.Dir, "fixtures", "peer"), phosts)
 		return err
 	} else if cfg.PeerAutoTLS {
 		plog.Warningf("ignoring peer auto TLS since certs given")

etcdctl/ctlv3/command/global.go

@@ -29,8 +29,10 @@ import (
 	"github.com/coreos/etcd/pkg/flags"
 	"github.com/coreos/etcd/pkg/srv"
 	"github.com/coreos/etcd/pkg/transport"
+
 	"github.com/spf13/cobra"
 	"github.com/spf13/pflag"
+	"go.uber.org/zap"
 	"google.golang.org/grpc/grpclog"
 )
 
@@ -169,6 +171,7 @@ func newClientCfg(endpoints []string, dialTimeout, keepAliveTime, keepAliveTimeo
 	// set tls if any one tls option set
 	var cfgtls *transport.TLSInfo
 	tlsinfo := transport.TLSInfo{}
+	tlsinfo.Logger, _ = zap.NewProduction()
 	if scfg.cert != "" {
 		tlsinfo.CertFile = scfg.cert
 		cfgtls = &tlsinfo

etcdmain/etcd.go

@@ -318,7 +318,7 @@ func startProxy(cfg *config) error {
 	}
 	listenerTLS := cfg.ec.ClientTLSInfo
 	if cfg.ec.ClientAutoTLS && cTLS {
-		listenerTLS, err = transport.SelfCert(filepath.Join(cfg.ec.Dir, "clientCerts"), cHosts)
+		listenerTLS, err = transport.SelfCert(cfg.ec.Logger, filepath.Join(cfg.ec.Dir, "clientCerts"), cHosts)
 		if err != nil {
 			plog.Fatalf("proxy: could not initialize self-signed client certs (%v)", err)
 		}

etcdmain/grpc_proxy.go

@@ -42,6 +42,7 @@ import (
 	grpc_prometheus "github.com/grpc-ecosystem/go-grpc-prometheus"
 	"github.com/soheilhy/cmux"
 	"github.com/spf13/cobra"
+	"go.uber.org/zap"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/grpclog"
 )
@@ -162,7 +163,11 @@ func startGRPCProxy(cmd *cobra.Command, args []string) {
 	if tlsinfo == nil && grpcProxyListenAutoTLS {
 		host := []string{"https://" + grpcProxyListenAddr}
 		dir := filepath.Join(grpcProxyDataDir, "fixtures", "proxy")
-		autoTLS, err := transport.SelfCert(dir, host)
+		lg, _ := zap.NewProduction()
+		if grpcProxyDebug {
+			lg = zap.NewExample()
+		}
+		autoTLS, err := transport.SelfCert(lg, dir, host)
 		if err != nil {
 			plog.Fatal(err)
 		}

pkg/transport/listener.go

@@ -32,8 +32,11 @@ import (
 	"time"
 
 	"github.com/coreos/etcd/pkg/tlsutil"
+
+	"go.uber.org/zap"
 )
 
+// NewListener creates a new listner.
 func NewListener(addr, scheme string, tlsinfo *TLSInfo) (l net.Listener, err error) {
 	if l, err = newListener(addr, scheme); err != nil {
 		return nil, err
@@ -79,6 +82,10 @@ type TLSInfo struct {
 
 	// AllowedCN is a CN which must be provided by a client.
 	AllowedCN string
+
+	// Logger logs TLS errors.
+	// If nil, all logs are discarded.
+	Logger *zap.Logger
 }
 
 func (info TLSInfo) String() string {
@@ -89,10 +96,11 @@ func (info TLSInfo) Empty() bool {
 	return info.CertFile == "" && info.KeyFile == ""
 }
 
-func SelfCert(dirpath string, hosts []string) (info TLSInfo, err error) {
+func SelfCert(lg *zap.Logger, dirpath string, hosts []string) (info TLSInfo, err error) {
 	if err = os.MkdirAll(dirpath, 0700); err != nil {
 		return
 	}
+	info.Logger = lg
 
 	certPath := filepath.Join(dirpath, "cert.pem")
 	keyPath := filepath.Join(dirpath, "key.pem")
@@ -108,6 +116,10 @@ func SelfCert(dirpath string, hosts []string) (info TLSInfo, err error) {
 	serialNumberLimit := new(big.Int).Lsh(big.NewInt(1), 128)
 	serialNumber, err := rand.Int(rand.Reader, serialNumberLimit)
 	if err != nil {
+		info.Logger.Warn(
+			"cannot generate random number",
+			zap.Error(err),
+		)
 		return
 	}
 
@@ -133,39 +145,62 @@ func SelfCert(dirpath string, hosts []string) (info TLSInfo, err error) {
 
 	priv, err := ecdsa.GenerateKey(elliptic.P521(), rand.Reader)
 	if err != nil {
+		info.Logger.Warn(
+			"cannot generate ECDSA key",
+			zap.Error(err),
+		)
 		return
 	}
 
 	derBytes, err := x509.CreateCertificate(rand.Reader, &tmpl, &tmpl, &priv.PublicKey, priv)
 	if err != nil {
+		info.Logger.Warn(
+			"cannot generate x509 certificate",
+			zap.Error(err),
+		)
 		return
 	}
 
 	certOut, err := os.Create(certPath)
 	if err != nil {
+		info.Logger.Warn(
+			"cannot cert file",
+			zap.String("path", certPath),
+			zap.Error(err),
+		)
 		return
 	}
 	pem.Encode(certOut, &pem.Block{Type: "CERTIFICATE", Bytes: derBytes})
 	certOut.Close()
+	info.Logger.Debug("created cert file", zap.String("path", certPath))
 
 	b, err := x509.MarshalECPrivateKey(priv)
 	if err != nil {
 		return
 	}
 	keyOut, err := os.OpenFile(keyPath, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, 0600)
 	if err != nil {
+		info.Logger.Warn(
+			"cannot key file",
+			zap.String("path", keyPath),
+			zap.Error(err),
+		)
 		return
 	}
 	pem.Encode(keyOut, &pem.Block{Type: "EC PRIVATE KEY", Bytes: b})
 	keyOut.Close()
+	info.Logger.Debug("created key file", zap.String("path", keyPath))
 
-	return SelfCert(dirpath, hosts)
+	return SelfCert(lg, dirpath, hosts)
 }
 
 func (info TLSInfo) baseConfig() (*tls.Config, error) {
 	if info.KeyFile == "" || info.CertFile == "" {
 		return nil, fmt.Errorf("KeyFile and CertFile must both be present[key: %v, cert: %v]", info.KeyFile, info.CertFile)
 	}
+	if info.Logger == nil {
+		info.Logger = zap.NewNop()
+	}
 
 	tlsCert, err := tlsutil.NewCert(info.CertFile, info.KeyFile, info.parseFunc)
 	if err != nil {
@@ -193,11 +228,43 @@ func (info TLSInfo) baseConfig() (*tls.Config, error) {
 
 	// this only reloads certs when there's a client request
 	// TODO: support server-side refresh (e.g. inotify, SIGHUP), caching
-	cfg.GetCertificate = func(clientHello *tls.ClientHelloInfo) (*tls.Certificate, error) {
-		return tlsutil.NewCert(info.CertFile, info.KeyFile, info.parseFunc)
+	cfg.GetCertificate = func(clientHello *tls.ClientHelloInfo) (cert *tls.Certificate, err error) {
+		cert, err = tlsutil.NewCert(info.CertFile, info.KeyFile, info.parseFunc)
+		if os.IsNotExist(err) {
+			info.Logger.Warn(
+				"failed to find peer cert files",
+				zap.String("cert-file", info.CertFile),
+				zap.String("key-file", info.KeyFile),
+				zap.Error(err),
+			)
+		} else if err != nil {
+			info.Logger.Warn(
+				"failed to create peer certificate",
+				zap.String("cert-file", info.CertFile),
+				zap.String("key-file", info.KeyFile),
+				zap.Error(err),
+			)
+		}
+		return cert, err
 	}
-	cfg.GetClientCertificate = func(unused *tls.CertificateRequestInfo) (*tls.Certificate, error) {
-		return tlsutil.NewCert(info.CertFile, info.KeyFile, info.parseFunc)
+	cfg.GetClientCertificate = func(unused *tls.CertificateRequestInfo) (cert *tls.Certificate, err error) {
+		cert, err = tlsutil.NewCert(info.CertFile, info.KeyFile, info.parseFunc)
+		if os.IsNotExist(err) {
+			info.Logger.Warn(
+				"failed to find client cert files",
+				zap.String("cert-file", info.CertFile),
+				zap.String("key-file", info.KeyFile),
+				zap.Error(err),
+			)
+		} else if err != nil {
+			info.Logger.Warn(
+				"failed to create client certificate",
+				zap.String("cert-file", info.CertFile),
+				zap.String("key-file", info.KeyFile),
+				zap.Error(err),
+			)
+		}
+		return cert, err
 	}
 	return cfg, nil
 }

pkg/transport/listener_test.go

@@ -22,14 +22,16 @@ import (
 	"os"
 	"testing"
 	"time"
+
+	"go.uber.org/zap"
 )
 
 func createSelfCert() (*TLSInfo, func(), error) {
 	d, terr := ioutil.TempDir("", "etcd-test-tls-")
 	if terr != nil {
 		return nil, nil, terr
 	}
-	info, err := SelfCert(d, []string{"127.0.0.1"})
+	info, err := SelfCert(zap.NewExample(), d, []string{"127.0.0.1"})
 	if err != nil {
 		return nil, nil, err
 	}
@@ -259,7 +261,7 @@ func TestNewListenerTLSInfoSelfCert(t *testing.T) {
 		t.Fatal(err)
 	}
 	defer os.RemoveAll(tmpdir)
-	tlsinfo, err := SelfCert(tmpdir, []string{"127.0.0.1"})
+	tlsinfo, err := SelfCert(zap.NewExample(), tmpdir, []string{"127.0.0.1"})
 	if err != nil {
 		t.Fatal(err)
 	}

pkg/transport/proxy.go

@@ -25,9 +25,8 @@ import (
 	"sync"
 	"time"
 
-	"go.uber.org/zap"
-
 	humanize "github.com/dustin/go-humanize"
+	"go.uber.org/zap"
 )
 
 // Proxy defines proxy layer that simulates common network faults,