Merge pull request etcd-io#18313 from ahrtr/log_20240712

Differentiate the warning message for rejected client and peer connections

server/embed/config_logging.go

@@ -165,35 +165,38 @@ func (cfg *Config) setupLogging() error {
 			return err
 		}
 
-		logTLSHandshakeFailure := func(conn *tls.Conn, err error) {
-			state := conn.ConnectionState()
-			remoteAddr := conn.RemoteAddr().String()
-			serverName := state.ServerName
-			if len(state.PeerCertificates) > 0 {
-				cert := state.PeerCertificates[0]
-				ips := make([]string, len(cert.IPAddresses))
-				for i := range cert.IPAddresses {
-					ips[i] = cert.IPAddresses[i].String()
+		logTLSHandshakeFailureFunc := func(msg string) func(conn *tls.Conn, err error) {
+			return func(conn *tls.Conn, err error) {
+				state := conn.ConnectionState()
+				remoteAddr := conn.RemoteAddr().String()
+				serverName := state.ServerName
+				if len(state.PeerCertificates) > 0 {
+					cert := state.PeerCertificates[0]
+					ips := make([]string, len(cert.IPAddresses))
+					for i := range cert.IPAddresses {
+						ips[i] = cert.IPAddresses[i].String()
+					}
+					cfg.logger.Warn(
+						msg,
+						zap.String("remote-addr", remoteAddr),
+						zap.String("server-name", serverName),
+						zap.Strings("ip-addresses", ips),
+						zap.Strings("dns-names", cert.DNSNames),
+						zap.Error(err),
+					)
+				} else {
+					cfg.logger.Warn(
+						msg,
+						zap.String("remote-addr", remoteAddr),
+						zap.String("server-name", serverName),
+						zap.Error(err),
+					)
 				}
-				cfg.logger.Warn(
-					"rejected connection",
-					zap.String("remote-addr", remoteAddr),
-					zap.String("server-name", serverName),
-					zap.Strings("ip-addresses", ips),
-					zap.Strings("dns-names", cert.DNSNames),
-					zap.Error(err),
-				)
-			} else {
-				cfg.logger.Warn(
-					"rejected connection",
-					zap.String("remote-addr", remoteAddr),
-					zap.String("server-name", serverName),
-					zap.Error(err),
-				)
 			}
 		}
-		cfg.ClientTLSInfo.HandshakeFailure = logTLSHandshakeFailure
-		cfg.PeerTLSInfo.HandshakeFailure = logTLSHandshakeFailure
+
+		cfg.ClientTLSInfo.HandshakeFailure = logTLSHandshakeFailureFunc("rejected connection on client endpoint")
+		cfg.PeerTLSInfo.HandshakeFailure = logTLSHandshakeFailureFunc("rejected connection on peer endpoint")
 
 	default:
 		return fmt.Errorf("unknown logger option %q", cfg.Logger)

tests/e2e/zap_logging_test.go

@@ -20,6 +20,8 @@ import (
 	"testing"
 	"time"
 
+	"github.com/stretchr/testify/require"
+
 	"go.etcd.io/etcd/tests/v3/framework/e2e"
 )
 
@@ -73,3 +75,84 @@ type logEntry struct {
 	Caller    string `json:"caller"`
 	Message   string `json:"msg"`
 }
+
+func TestConnectionRejectMessage(t *testing.T) {
+	e2e.SkipInShortMode(t)
+
+	testCases := []struct {
+		name           string
+		url            string
+		expectedErrMsg string
+	}{
+		{
+			name:           "reject client connection",
+			url:            "https://127.0.0.1:2379/version",
+			expectedErrMsg: "rejected connection on client endpoint",
+		},
+		{
+			name:           "reject peer connection",
+			url:            "https://127.0.0.1:2380/members",
+			expectedErrMsg: "rejected connection on peer endpoint",
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			commonArgs := []string{
+				e2e.BinPath.Etcd,
+				"--name", "etcd1",
+				"--listen-client-urls", "https://127.0.0.1:2379",
+				"--advertise-client-urls", "https://127.0.0.1:2379",
+				"--cert-file", e2e.CertPath,
+				"--key-file", e2e.PrivateKeyPath,
+				"--trusted-ca-file", e2e.CaPath,
+				"--listen-peer-urls", "https://127.0.0.1:2380",
+				"--initial-advertise-peer-urls", "https://127.0.0.1:2380",
+				"--initial-cluster", "etcd1=https://127.0.0.1:2380",
+				"--peer-cert-file", e2e.CertPath,
+				"--peer-key-file", e2e.PrivateKeyPath,
+				"--peer-trusted-ca-file", e2e.CaPath,
+			}
+
+			t.Log("Starting an etcd process and wait for it to get ready.")
+			p, err := e2e.SpawnCmd(commonArgs, nil)
+			require.NoError(t, err)
+			err = e2e.WaitReadyExpectProc(context.TODO(), p, e2e.EtcdServerReadyLines)
+			require.NoError(t, err)
+			defer func() {
+				p.Stop()
+				p.Close()
+			}()
+
+			t.Log("Starting a separate goroutine to verify the expected output.")
+			startedCh := make(chan struct{}, 1)
+			doneCh := make(chan struct{}, 1)
+			go func() {
+				startedCh <- struct{}{}
+				verr := e2e.WaitReadyExpectProc(context.TODO(), p, []string{tc.expectedErrMsg})
+				require.NoError(t, verr)
+				doneCh <- struct{}{}
+			}()
+
+			// wait for the goroutine to get started
+			<-startedCh
+
+			t.Log("Running curl command to trigger the corresponding warning message.")
+			curlCmdArgs := []string{"curl", "--connect-timeout", "1", "-k", tc.url}
+			curlCmd, err := e2e.SpawnCmd(curlCmdArgs, nil)
+			require.NoError(t, err)
+
+			defer func() {
+				curlCmd.Stop()
+				curlCmd.Close()
+			}()
+
+			t.Log("Waiting for the result.")
+			select {
+			case <-doneCh:
+			case <-time.After(5 * time.Second):
+				t.Fatal("Timed out waiting for the result")
+			}
+		})
+	}
+}