From b5a12de28553481140374865850e1632cbb2b016 Mon Sep 17 00:00:00 2001
From: yacovm <yacovm@il.ibm.com>
Date: Tue, 20 Oct 2020 23:59:13 +0300
Subject: [PATCH] Log TLS hanshake duration

This commit adds logging to the duration of the TLS handshakes, both client and server.

Change-Id: I5f630a62362e2131882542c78d3f321aed7fc2d2
Signed-off-by: yacovm <yacovm@il.ibm.com>
---
 core/comm/creds.go      | 28 ++++++++++++++++++++++------
 core/comm/creds_test.go |  2 +-
 2 files changed, 23 insertions(+), 7 deletions(-)

diff --git a/core/comm/creds.go b/core/comm/creds.go
index db7d536496e..a62c8c46c6a 100644
--- a/core/comm/creds.go
+++ b/core/comm/creds.go
@@ -13,12 +13,16 @@ import (
 	"errors"
 	"net"
 	"sync"
+	"time"
 
 	"github.com/hyperledger/fabric/common/flogging"
 	"google.golang.org/grpc/credentials"
 )
 
 var (
+	// Logger for TLS client connections
+	tlsClientLogger = flogging.MustGetLogger("comm.tls")
+
 	ClientHandshakeNotImplError = errors.New("core/comm: Client handshakes" +
 		"are not implemented with serverCreds")
 	OverrrideHostnameNotSupportedError = errors.New(
@@ -38,6 +42,10 @@ func NewServerTransportCredentials(
 	serverConfig *TLSConfig,
 	logger *flogging.FabricLogger) credentials.TransportCredentials {
 
+	if logger == nil {
+		logger = tlsClientLogger
+	}
+
 	// NOTE: unlike the default grpc/credentials implementation, we do not
 	// clone the tls.Config which allows us to update it dynamically
 	serverConfig.config.NextProtos = alpnProtoStr
@@ -100,15 +108,14 @@ func (sc *serverCreds) ClientHandshake(context.Context,
 // ServerHandshake does the authentication handshake for servers.
 func (sc *serverCreds) ServerHandshake(rawConn net.Conn) (net.Conn, credentials.AuthInfo, error) {
 	serverConfig := sc.serverConfig.Config()
-
 	conn := tls.Server(rawConn, &serverConfig)
+	l := sc.logger.With("remote address", conn.RemoteAddr().String())
+	start := time.Now()
 	if err := conn.Handshake(); err != nil {
-		if sc.logger != nil {
-			sc.logger.With("remote address",
-				conn.RemoteAddr().String()).Errorf("TLS handshake failed with error %s", err)
-		}
+		l.Errorf("Server TLS handshake failed in %s with error %s", time.Since(start), err)
 		return nil, nil, err
 	}
+	l.Debugf("Server TLS handshake completed in %s", time.Since(start))
 	return conn, credentials.TLSInfo{State: conn.ConnectionState()}, nil
 }
 
@@ -148,7 +155,16 @@ func (dtc *DynamicClientCredentials) latestConfig() *tls.Config {
 }
 
 func (dtc *DynamicClientCredentials) ClientHandshake(ctx context.Context, authority string, rawConn net.Conn) (net.Conn, credentials.AuthInfo, error) {
-	return credentials.NewTLS(dtc.latestConfig()).ClientHandshake(ctx, authority, rawConn)
+	l := tlsClientLogger.With("remote address", rawConn.RemoteAddr().String())
+	creds := credentials.NewTLS(dtc.latestConfig())
+	start := time.Now()
+	conn, auth, err := creds.ClientHandshake(ctx, authority, rawConn)
+	if err != nil {
+		l.Errorf("Client TLS handshake failed after %s with error: %s", time.Since(start), err)
+	} else {
+		l.Debugf("Client TLS handshake completed in %s", time.Since(start))
+	}
+	return conn, auth, err
 }
 
 func (dtc *DynamicClientCredentials) ServerHandshake(rawConn net.Conn) (net.Conn, credentials.AuthInfo, error) {
diff --git a/core/comm/creds_test.go b/core/comm/creds_test.go
index f11c53f1318..7cb7b266449 100644
--- a/core/comm/creds_test.go
+++ b/core/comm/creds_test.go
@@ -93,7 +93,7 @@ func TestCreds(t *testing.T) {
 	})
 	wg.Wait()
 	assert.Contains(t, err.Error(), "protocol version not supported")
-	assert.Contains(t, recorder.Messages()[0], "TLS handshake failed with error")
+	assert.Contains(t, recorder.Messages()[1], "TLS handshake failed")
 }
 
 func TestNewTLSConfig(t *testing.T) {