Merge pull request #9518 from gyuho/eee

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,