net/http: TLS handshake errors are not (reasonably) accessible for servers

[joeshaw]

What version of Go are you using (go version)?

$ go version
go version go1.14.2 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

Description of the issue

The current http server implementation makes it very cumbersome to access TLS handshake errors. I would like to be able to see them in order to add metrics and alerting to my service. (A recent misconfiguration caused all connections to fail, and we were unable to alert on these kinds of errors.)

Today, TLS handshake errors are reported by logging to the http.Server ErrorLog logger, if it is set. (Otherwise it goes to the standard logger.)

The line in question:

go/src/net/http/server.go

Line 1798 in 9b18968

c.server.logf("http: TLS handshake error from %s: %v", c.rwc.RemoteAddr(), err)

c.server.logf("http: TLS handshake error from %s: %v", c.rwc.RemoteAddr(), err)

And the implementation of logf:

go/src/net/http/server.go

Lines 3062 to 3080 in 9b18968

	func (s *Server) logf(format string, args ...interface{}) {
	if s.ErrorLog != nil {
	s.ErrorLog.Printf(format, args...)
	} else {
	log.Printf(format, args...)
	}
	}
	// logf prints to the ErrorLog of the *Server associated with request r
	// via ServerContextKey. If there's no associated server, or if ErrorLog
	// is nil, logging is done via the log package's standard logger.
	func logf(r *Request, format string, args ...interface{}) {
	s, _ := r.Context().Value(ServerContextKey).(*Server)
	if s != nil && s.ErrorLog != nil {
	s.ErrorLog.Printf(format, args...)
	} else {
	log.Printf(format, args...)
	}
	}

func (s *Server) logf(format string, args ...interface{}) {
	if s.ErrorLog != nil {
		s.ErrorLog.Printf(format, args...)
	} else {
		log.Printf(format, args...)
	}
}

ErrorLog is a *log.Logger, which is a struct and not an interface. It wraps an io.Writer. So in order to capture TLS handshake errors, one must write an io.Writer wrapper that searches for the string TLS handshake error. I think (but am not sure) that error messages are not covered by the Go 1 compatibility guarantee, so this method is both ugly and fragile.

It would be nice if there were another way to get notified of TLS handshake errors. This could be implemented as an optional callback function on the http.Server or tls.Config structs, or as a channel on http.Server. It may make sense to generalize it to more HTTP server errors, but we could start with handshake errors.

Reproducing the issue

An easy way to illustrate this in action is to start up a TLS HTTP server (http.ListenAndServeTLS) and then run nc localhost 1234 </dev/null. On the server you'll get a log line like 2020/05/05 11:41:59 http: TLS handshake error from 127.0.0.1:63162: EOF

[joeshaw]

This is basically the code I wrote to implement it:

func NewLogAdapter(m *Metric) *log.Logger {
	return log.New(&writerAdapter{os.Stderr, m}, "", log.LstdFlags)
}

type writerAdapter struct {
	io.Writer
	metric *Metric
}

// From https://github.com/golang/go/blob/9b189686a53d7fec7deb93d7521531157aa023cb/src/net/http/server.go#L1798
var tlsHandshakeError = []byte("http: TLS handshake error")

func (a *writerAdapter) Write(data []byte) (int, error) {
	if bytes.Contains(data, tlsHandshakeError) {
		a.metric.Inc()
	}
	return a.Writer.Write(data)
}

[networkimprov]

cc @FiloSottile

[toothrot]

/cc @bradfitz @rsc

[bradfitz]

You can implement & give your own net.Listener to https://golang.org/pkg/net/http/#Server.Serve and have your Listener do the TLS handshakes & error logging.

[joeshaw]

@bradfitz Thanks for the suggestion (though not the subtweet). It didn't occur to me to perform the handshake after the Accept(). That code looks something like this:

func (s *Server) ListenAndServeTLS(certFile, keyFile string) error {
	addr := s.Addr
	if addr == "" {
		addr = ":https"
	}

	tcpListener, err := net.Listen("tcp", addr)
	if err != nil {
		return err
	}
	defer tcpListener.Close()

	cfg := &tls.Config{}
	if s.TLSConfig != nil {
		cfg = s.TLSConfig.Clone()
	}

	cfg.Certificates = make([]tls.Certificate, 1)
	cfg.Certificates[0], err = tls.LoadX509KeyPair(certFile, keyFile)
	if err != nil {
		return err
	}

	tlsListener := tls.NewListener(tcpListener, cfg)

	return s.Serve(&listener{
		Listener:           tlsListener,
		onHandshakeFailure: s.OnHandshakeFailure,
	})
}

type listener struct {
	net.Listener
	onHandshakeFailure func(error)
}

func (l *listener) Accept() (net.Conn, error) {
	c, err := l.Listener.Accept()
	if err != nil {
		return c, err
	}

	// tls.Conn tracks the handshake state so that multiple calls to
	// Handshake() are no-ops.  Inside the net/http server machinery
	// Handshake() is called again (and failures logged), so we don't
	// need to error out here, just track the failure.
	if err := c.(*tls.Conn).Handshake(); err != nil {
		l.onHandshakeFailure(err)
	}

	return c, nil
}

(I already had my own *http.Server wrapper, so adding an OnHandshakeFailure field was easy.)

[bradfitz]

@joeshaw, sorry, that tweet was actually from something last week. I kept delaying posting it so people wouldn't connect dots. But honestly it does come up all the time. This isn't one of the egregious cases that prompted the original tweet, though. For one, this bug report was well written and researched and polite, which is not always the case.

[joeshaw]

Haha, ok, sorry for overreacting. I do appreciate the suggestion and agree it's definitely an improvement over abusing ErrorLog.