Log TLS handshake duration

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

Change-Id: Ia54551b874db8356c3332b456e59f58b7f428bfe
Signed-off-by: yacovm <yacovm@il.ibm.com>

internal/pkg/comm/creds.go

@@ -13,6 +13,7 @@ import (
 	"errors"
 	"net"
 	"sync"
+	"time"
 
 	"github.com/hyperledger/fabric/common/flogging"
 	"google.golang.org/grpc/credentials"
@@ -25,6 +26,9 @@ var (
 
 	// alpnProtoStr are the specified application level protocols for gRPC.
 	alpnProtoStr = []string{"h2"}
+
+	// Logger for TLS client connections
+	tlsClientLogger = flogging.MustGetLogger("comm.tls")
 )
 
 // NewServerTransportCredentials returns a new initialized
@@ -36,6 +40,11 @@ func NewServerTransportCredentials(
 	// clone the tls.Config which allows us to update it dynamically
 	serverConfig.config.NextProtos = alpnProtoStr
 	serverConfig.config.MinVersion = tls.VersionTLS12
+
+	if logger == nil {
+		logger = tlsClientLogger
+	}
+
 	return &serverCreds{
 		serverConfig: serverConfig,
 		logger:       logger}
@@ -94,13 +103,13 @@ func (sc *serverCreds) ServerHandshake(rawConn net.Conn) (net.Conn, credentials.
 	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
 }
 
@@ -139,7 +148,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) {

internal/pkg/comm/creds_test.go

@@ -16,6 +16,8 @@ import (
 	"sync"
 	"testing"
 
+	"github.com/stretchr/testify/require"
+
 	"github.com/hyperledger/fabric/common/flogging/floggingtest"
 	"github.com/hyperledger/fabric/internal/pkg/comm"
 	"github.com/stretchr/testify/assert"
@@ -94,8 +96,8 @@ func TestCreds(t *testing.T) {
 		MaxVersion: tls.VersionTLS10,
 	})
 	wg.Wait()
-	assert.Contains(t, err.Error(), "protocol version not supported")
-	assert.Contains(t, recorder.Messages()[0], "TLS handshake failed with error")
+	require.Contains(t, err.Error(), "protocol version not supported")
+	require.Contains(t, recorder.Messages()[1], "TLS handshake failed")
 }
 
 func TestNewTLSConfig(t *testing.T) {