refactor(netx): move tlshandshaker logger to netxlite (#402)

Part of https://github.com/ooni/probe/issues/1505

internal/netxlite/tlshandshaker.go

@@ -5,6 +5,8 @@ import (
 	"crypto/tls"
 	"net"
 	"time"
+
+	"github.com/ooni/probe-cli/v3/internal/engine/netx/tlsx"
 )
 
 // TLSHandshaker is the generic TLS handshaker.
@@ -44,3 +46,37 @@ func (h *TLSHandshakerStdlib) Handshake(
 
 // DefaultTLSHandshaker is the default TLS handshaker.
 var DefaultTLSHandshaker = &TLSHandshakerStdlib{}
+
+// TLSHandshakerLogger is a TLSHandshaker with logging.
+type TLSHandshakerLogger struct {
+	// TLSHandshaker is the underlying handshaker.
+	TLSHandshaker TLSHandshaker
+
+	// Logger is the underlying logger.
+	Logger Logger
+}
+
+// Handshake implements Handshaker.Handshake
+func (h *TLSHandshakerLogger) Handshake(
+	ctx context.Context, conn net.Conn, config *tls.Config,
+) (net.Conn, tls.ConnectionState, error) {
+	h.Logger.Debugf(
+		"tls {sni=%s next=%+v}...", config.ServerName, config.NextProtos)
+	start := time.Now()
+	tlsconn, state, err := h.TLSHandshaker.Handshake(ctx, conn, config)
+	elapsed := time.Since(start)
+	if err != nil {
+		h.Logger.Debugf(
+			"tls {sni=%s next=%+v}... %s in %s", config.ServerName,
+			config.NextProtos, err, elapsed)
+		return nil, tls.ConnectionState{}, err
+	}
+	h.Logger.Debugf(
+		"tls {sni=%s next=%+v}... ok in %s {next=%s cipher=%s v=%s}",
+		config.ServerName, config.NextProtos, elapsed, state.NegotiatedProtocol,
+		tlsx.CipherSuiteString(state.CipherSuite),
+		tlsx.VersionString(state.Version))
+	return tlsconn, state, nil
+}
+
+var _ TLSHandshaker = &TLSHandshakerLogger{}

internal/netxlite/tlshandshaker_test.go

@@ -3,14 +3,17 @@ package netxlite
 import (
 	"context"
 	"crypto/tls"
+	"errors"
 	"io"
 	"net"
 	"net/http"
 	"net/http/httptest"
 	"net/url"
+	"reflect"
 	"testing"
 	"time"
 
+	"github.com/apex/log"
 	"github.com/ooni/probe-cli/v3/internal/netxmocks"
 )
 
@@ -79,3 +82,60 @@ func TestTLSHandshakerStdlibSuccess(t *testing.T) {
 		t.Fatal("unexpected TLS version")
 	}
 }
+
+func TestTLSHandshakerLoggerSuccess(t *testing.T) {
+	th := &TLSHandshakerLogger{
+		TLSHandshaker: &netxmocks.TLSHandshaker{
+			MockHandshake: func(ctx context.Context, conn net.Conn, config *tls.Config) (net.Conn, tls.ConnectionState, error) {
+				return tls.Client(conn, config), tls.ConnectionState{}, nil
+			},
+		},
+		Logger: log.Log,
+	}
+	conn := &netxmocks.Conn{
+		MockClose: func() error {
+			return nil
+		},
+	}
+	config := &tls.Config{}
+	ctx := context.Background()
+	tlsConn, connState, err := th.Handshake(ctx, conn, config)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if err := tlsConn.Close(); err != nil {
+		t.Fatal(err)
+	}
+	if !reflect.ValueOf(connState).IsZero() {
+		t.Fatal("expected zero ConnectionState here")
+	}
+}
+
+func TestTLSHandshakerLoggerFailure(t *testing.T) {
+	expected := errors.New("mocked error")
+	th := &TLSHandshakerLogger{
+		TLSHandshaker: &netxmocks.TLSHandshaker{
+			MockHandshake: func(ctx context.Context, conn net.Conn, config *tls.Config) (net.Conn, tls.ConnectionState, error) {
+				return nil, tls.ConnectionState{}, expected
+			},
+		},
+		Logger: log.Log,
+	}
+	conn := &netxmocks.Conn{
+		MockClose: func() error {
+			return nil
+		},
+	}
+	config := &tls.Config{}
+	ctx := context.Background()
+	tlsConn, connState, err := th.Handshake(ctx, conn, config)
+	if !errors.Is(err, expected) {
+		t.Fatal("not the error we expected", err)
+	}
+	if tlsConn != nil {
+		t.Fatal("expected nil conn here")
+	}
+	if !reflect.ValueOf(connState).IsZero() {
+		t.Fatal("expected zero ConnectionState here")
+	}
+}