Log TLS connection errors

Add an error level log message when
the GRPCServer rejects TLS client
connections

FAB-11855 #done

Change-Id: I8191670c5e2237bcbab200eab3547e2be0d5f16d
Signed-off-by: Gari Singh <[email protected]>

core/comm/config.go

@@ -11,6 +11,7 @@ import (
 	"crypto/x509"
 	"time"
 
+	"github.com/hyperledger/fabric/common/flogging"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/keepalive"
 )
@@ -56,6 +57,8 @@ type ServerConfig struct {
 	// UnaryInterceptors specifies a list of interceptors to apply to unary
 	// RPCs.  They are executed in order.
 	UnaryInterceptors []grpc.UnaryServerInterceptor
+	// Logger specifies the logger the server will use
+	Logger *flogging.FabricLogger
 }
 
 // ClientConfig defines the parameters for configuring a GRPCClient instance

core/comm/creds.go

@@ -11,6 +11,7 @@ import (
 	"errors"
 	"net"
 
+	"github.com/hyperledger/fabric/common/flogging"
 	"golang.org/x/net/context"
 	"google.golang.org/grpc/credentials"
 )
@@ -29,19 +30,25 @@ var (
 
 // NewServerTransportCredentials returns a new initialized
 // grpc/credentials.TransportCredentials
-func NewServerTransportCredentials(serverConfig *tls.Config) credentials.TransportCredentials {
+func NewServerTransportCredentials(
+	serverConfig *tls.Config,
+	logger *flogging.FabricLogger) credentials.TransportCredentials {
+
 	// NOTE: unlike the default grpc/credentials implementation, we do not
 	// clone the tls.Config which allows us to update it dynamically
 	serverConfig.NextProtos = alpnProtoStr
 	// override TLS version and ensure it is 1.2
 	serverConfig.MinVersion = tls.VersionTLS12
 	serverConfig.MaxVersion = tls.VersionTLS12
-	return &serverCreds{serverConfig}
+	return &serverCreds{
+		serverConfig: serverConfig,
+		logger:       logger}
 }
 
 // serverCreds is an implementation of grpc/credentials.TransportCredentials.
 type serverCreds struct {
 	serverConfig *tls.Config
+	logger       *flogging.FabricLogger
 }
 
 // ClientHandShake is not implemented for `serverCreds`.
@@ -54,6 +61,10 @@ func (sc *serverCreds) ClientHandshake(context.Context,
 func (sc *serverCreds) ServerHandshake(rawConn net.Conn) (net.Conn, credentials.AuthInfo, error) {
 	conn := tls.Server(rawConn, sc.serverConfig)
 	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)
+		}
 		return nil, nil, err
 	}
 	return conn, credentials.TLSInfo{State: conn.ConnectionState()}, nil
@@ -69,7 +80,7 @@ func (sc *serverCreds) Info() credentials.ProtocolInfo {
 
 // Clone makes a copy of this TransportCredentials.
 func (sc *serverCreds) Clone() credentials.TransportCredentials {
-	creds := NewServerTransportCredentials(sc.serverConfig)
+	creds := NewServerTransportCredentials(sc.serverConfig, sc.logger)
 	return creds
 }
 

core/comm/creds_test.go

@@ -7,25 +7,100 @@ SPDX-License-Identifier: Apache-2.0
 package comm_test
 
 import (
+	"bytes"
 	"crypto/tls"
+	"crypto/x509"
+	"fmt"
+	"io/ioutil"
+	"net"
+	"path/filepath"
 	"testing"
 
 	"google.golang.org/grpc/credentials"
 
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/core/comm"
 	"github.com/stretchr/testify/assert"
 )
 
 func TestCreds(t *testing.T) {
 	t.Parallel()
+
+	caPEM, err := ioutil.ReadFile(filepath.Join("testdata", "certs", "Org1-cert.pem"))
+	if err != nil {
+		t.Fatalf("failed to read root certificate: %v", err)
+	}
+	certPool := x509.NewCertPool()
+	ok := certPool.AppendCertsFromPEM(caPEM)
+	if !ok {
+		t.Fatalf("failed to create certPool")
+	}
+	cert, err := tls.LoadX509KeyPair(
+		filepath.Join("testdata", "certs", "Org1-server1-cert.pem"),
+		filepath.Join("testdata", "certs", "Org1-server1-key.pem"))
+	if err != nil {
+		t.Fatalf("failed to load TLS certificate [%s]", err)
+	}
+	tlsConfig := &tls.Config{
+		Certificates: []tls.Certificate{cert}}
+
+	buf := &bytes.Buffer{}
+	conf := flogging.Config{
+		Writer: buf}
+	logging, err := flogging.New(conf)
+	if err != nil {
+		t.Fatalf("error creating logger [%s]", err)
+	}
+	logger := logging.Logger("creds")
 	var creds credentials.TransportCredentials
-	creds = comm.NewServerTransportCredentials(&tls.Config{})
-	_, _, err := creds.ClientHandshake(nil, "", nil)
+	creds = comm.NewServerTransportCredentials(tlsConfig, logger)
+	_, _, err = creds.ClientHandshake(nil, "", nil)
 	assert.EqualError(t, err, comm.ClientHandshakeNotImplError.Error())
 	err = creds.OverrideServerName("")
 	assert.EqualError(t, err, comm.OverrrideHostnameNotSupportedError.Error())
 	clone := creds.Clone()
 	assert.Equal(t, creds, clone)
 	assert.Equal(t, "1.2", creds.Info().SecurityVersion)
 	assert.Equal(t, "tls", creds.Info().SecurityProtocol)
+
+	lis, err := net.Listen("tcp", "localhost:0")
+	if err != nil {
+		t.Fatalf("failed to start listener [%s]", err)
+	}
+	defer lis.Close()
+
+	go func() {
+		conn, err := lis.Accept()
+		if err != nil {
+			t.Logf("failed to accept connection [%s]", err)
+		}
+		_, _, err = creds.ServerHandshake(conn)
+		if err != nil {
+			t.Logf("ServerHandshake error [%s]", err)
+		}
+		conn, err = lis.Accept()
+		if err != nil {
+			t.Logf("failed to accept connection [%s]", err)
+		}
+		_, _, err = creds.ServerHandshake(conn)
+		if err != nil {
+			t.Logf("ServerHandshake error [%s]", err)
+		}
+	}()
+
+	_, port, err := net.SplitHostPort(lis.Addr().String())
+	if err != nil {
+		t.Fatalf("failed to get server port [%s]", err)
+	}
+	_, err = tls.Dial("tcp", fmt.Sprintf("localhost:%s", port),
+		&tls.Config{RootCAs: certPool})
+	assert.NoError(t, err)
+
+	_, err = tls.Dial("tcp", fmt.Sprintf("localhost:%s", port),
+		&tls.Config{
+			RootCAs:    certPool,
+			MaxVersion: tls.VersionTLS10})
+	assert.Contains(t, err.Error(), "protocol version not supported")
+	assert.Contains(t, buf.String(), "TLS handshake failed with error")
+
 }

core/comm/server.go

@@ -112,7 +112,8 @@ func NewGRPCServerFromListener(listener net.Listener, serverConfig ServerConfig)
 			}
 
 			// create credentials and add to server options
-			creds := NewServerTransportCredentials(grpcServer.tlsConfig)
+			creds := NewServerTransportCredentials(grpcServer.tlsConfig,
+				serverConfig.Logger)
 			serverOpts = append(serverOpts, grpc.Creds(creds))
 		} else {
 			return nil, errors.New("serverConfig.SecOpts must contain both Key and " +

peer/node/start.go

@@ -20,6 +20,7 @@ import (
 	ccdef "github.com/hyperledger/fabric/common/chaincode"
 	"github.com/hyperledger/fabric/common/crypto/tlsgen"
 	"github.com/hyperledger/fabric/common/deliver"
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/common/localmsp"
 	"github.com/hyperledger/fabric/common/policies"
 	"github.com/hyperledger/fabric/common/viperutil"
@@ -195,6 +196,7 @@ func serve(args []string) error {
 	if err != nil {
 		logger.Fatalf("Error loading secure config for peer (%s)", err)
 	}
+	serverConfig.Logger = flogging.MustGetLogger("core/comm").With("server", "PeerServer")
 	peerServer, err := peer.NewPeerServer(listenAddr, serverConfig)
 	if err != nil {
 		logger.Fatalf("Failed to create peer server (%s)", err)
@@ -456,6 +458,9 @@ func createChaincodeServer(ca tlsgen.CA, peerHostname string) (srv *comm.GRPCSer
 		return nil, "", err
 	}
 
+	// set the logger for the server
+	config.Logger = flogging.MustGetLogger("core/comm").With("server", "ChaincodeServer")
+
 	// Override TLS configuration if TLS is applicable
 	if config.SecOpts.UseTLS {
 		// Create a self-signed TLS certificate with a SAN that matches the computed chaincode endpoint
@@ -649,6 +654,7 @@ func startAdminServer(peerListenAddr string, peerServer *grpc.Server) {
 	if separateLsnrForAdmin {
 		logger.Info("Creating gRPC server for admin service on", adminListenAddress)
 		serverConfig, err := peer.GetServerConfig()
+		serverConfig.Logger = flogging.MustGetLogger("core/comm").With("server", "AdminServer")
 		if err != nil {
 			logger.Fatalf("Error loading secure config for admin service (%s)", err)
 		}