diff --git a/CHANGELOG-3.4.md b/CHANGELOG-3.4.md index b5899d85538..923123f64f7 100644 --- a/CHANGELOG-3.4.md +++ b/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. diff --git a/embed/config.go b/embed/config.go index b654503c0ff..256eb67841c 100644 --- a/embed/config.go +++ b/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") diff --git a/etcdctl/ctlv3/command/global.go b/etcdctl/ctlv3/command/global.go index b9398944e9a..618e4aafb38 100644 --- a/etcdctl/ctlv3/command/global.go +++ b/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 diff --git a/etcdmain/etcd.go b/etcdmain/etcd.go index 5697f9bb534..5aa41aa4e5a 100644 --- a/etcdmain/etcd.go +++ b/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) } diff --git a/etcdmain/grpc_proxy.go b/etcdmain/grpc_proxy.go index 81fbbca8e65..8e2b2edfc57 100644 --- a/etcdmain/grpc_proxy.go +++ b/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) } diff --git a/pkg/transport/listener.go b/pkg/transport/listener.go index 15a4500692f..d2c017b6e9a 100644 --- a/pkg/transport/listener.go +++ b/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,20 +145,34 @@ 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 { @@ -154,18 +180,27 @@ func SelfCert(dirpath string, hosts []string) (info TLSInfo, err error) { } 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 } diff --git a/pkg/transport/listener_test.go b/pkg/transport/listener_test.go index ab3a3568792..6c508c313ea 100644 --- a/pkg/transport/listener_test.go +++ b/pkg/transport/listener_test.go @@ -22,6 +22,8 @@ import ( "os" "testing" "time" + + "go.uber.org/zap" ) func createSelfCert() (*TLSInfo, func(), error) { @@ -29,7 +31,7 @@ func createSelfCert() (*TLSInfo, func(), error) { 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) } diff --git a/pkg/transport/proxy.go b/pkg/transport/proxy.go index f1d7adf3aa2..874397e10d9 100644 --- a/pkg/transport/proxy.go +++ b/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,