Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
joeshaw opened this issue May 5, 2020 · 7 comments
Closed
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@joeshaw
Copy link
Contributor

joeshaw commented May 5, 2020

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:

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
Copy link
Contributor Author

joeshaw commented May 5, 2020

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
Copy link

cc @FiloSottile

@toothrot toothrot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 11, 2020
@toothrot toothrot added this to the Backlog milestone May 11, 2020
@toothrot
Copy link
Contributor

/cc @bradfitz @rsc

@bradfitz
Copy link
Contributor

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
Copy link
Contributor Author

joeshaw commented May 11, 2020

@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.)

@joeshaw joeshaw closed this as completed May 11, 2020
@bradfitz
Copy link
Contributor

@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
Copy link
Contributor Author

joeshaw commented May 11, 2020

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

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

5 participants