tsweb: use a ResponseWriter wrapper to log more accurately.

Also adds tests, because the logging handler is acquiring a fair
number of branches.

Signed-off-by: David Anderson <dave@natulte.net>

tsweb/log.go

@@ -10,30 +10,46 @@ import (
 	"time"
 )
 
-// Msg is a structured event log entry.
-type Msg struct {
-	Where    string        `json:"where"`
-	When     time.Time     `json:"when"`
-	Duration time.Duration `json:"duration,omitempty"`
-	Domain   string        `json:"domain,omitempty"`
-	Msg      string        `json:"msg,omitempty"`
-	Err      error         `json:"err,omitempty"`
-	HTTP     *MsgHTTP      `json:"http,omitempty"`
-	Data     interface{}   `json:"data,omitempty"`
-}
+// AccessLogRecord is a record of one HTTP request served.
+type AccessLogRecord struct {
+	// Timestamp at which request processing started.
+	When time.Time `json:"when"`
+	// Time it took to finish processing the request. It does not
+	// include the entire lifetime of the underlying connection in
+	// cases like connection hijacking, only the lifetime of the HTTP
+	// request handler.
+	Seconds float64 `json:"duration"`
 
-// MsgHTTP contains information about the processing of one HTTP
-// request.
-type MsgHTTP struct {
-	Code       int    `json:"code"`
-	Path       string `json:"path"`
+	// The client's ip:port.
 	RemoteAddr string `json:"remote_addr"`
-	UserAgent  string `json:"user_agent"`
-	Referer    string `json:"referer"`
+	// The HTTP protocol version, usually "HTTP/1.1 or HTTP/2".
+	Proto string `json:"proto"`
+	// Whether the request was received over TLS.
+	TLS bool `json:"tls"`
+	// The target hostname in the request.
+	Host string `json:"host"`
+	// The HTTP method invoked.
+	Method string `json:"method"`
+	// The unescaped request URI, including query parameters.
+	RequestURI string `json:"request_uri"`
+
+	// The client's user-agent
+	UserAgent string `json:"user_agent"`
+	// Where the client was before making this request.
+	Referer string `json:"referer"`
+
+	// The HTTP response code sent to the client.
+	Code int `json:"code"`
+	// Number of bytes sent in response body to client. If the request
+	// was hijacked, only includes bytes sent up to the point of
+	// hijacking.
+	Bytes int `json:"bytes"`
+	// Error encountered during request processing.
+	Err string `json:"err"`
 }
 
 // String returns m as a JSON string.
-func (m Msg) String() string {
+func (m AccessLogRecord) String() string {
 	if m.When.IsZero() {
 		m.When = time.Now()
 	}

tsweb/tsweb.go

@@ -6,8 +6,10 @@
 package tsweb
 
 import (
+	"bufio"
 	"bytes"
 	"context"
+	"errors"
 	"expvar"
 	"fmt"
 	"io"
@@ -155,64 +157,158 @@ type Handler interface {
 	ServeHTTPErr(http.ResponseWriter, *http.Request) error
 }
 
+// HandlerFunc is an adapter to allow the use of ordinary functions as
+// Handlers. If f is a function with the appropriate signature,
+// HandlerFunc(f) is a Handler that calls f.
+type HandlerFunc func(http.ResponseWriter, *http.Request) error
+
+func (h HandlerFunc) ServeHTTPErr(w http.ResponseWriter, r *http.Request) error {
+	return h(w, r)
+}
+
+// StdHandler converts a Handler into a standard http.Handler.
+// Handled requests are logged using logf, as are any errors. Errors
+// are handled as specified by the Handler interface.
+func StdHandler(h Handler, logf logger.Logf) http.Handler {
+	return stdHandler(h, logf, time.Now)
+}
+
+func stdHandler(h Handler, logf logger.Logf, now func() time.Time) http.Handler {
+	return handler{h, logf, now}
+}
+
 // handler is an http.Handler that wraps a Handler and handles errors.
 type handler struct {
-	h    Handler
-	logf logger.Logf
+	h       Handler
+	logf    logger.Logf
+	timeNow func() time.Time
 }
 
 // ServeHTTP implements the http.Handler interface.
 func (h handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
-	msg := Msg{
-		Where: "http",
-		When:  time.Now(),
-		HTTP: &MsgHTTP{
-			Path:       r.URL.Path,
-			RemoteAddr: r.RemoteAddr,
-			UserAgent:  r.UserAgent(),
-			Referer:    r.Referer(),
-		},
+	msg := AccessLogRecord{
+		When:       h.timeNow(),
+		RemoteAddr: r.RemoteAddr,
+		Proto:      r.Proto,
+		TLS:        r.TLS != nil,
+		Host:       r.Host,
+		Method:     r.Method,
+		RequestURI: r.URL.RequestURI(),
+		UserAgent:  r.UserAgent(),
+		Referer:    r.Referer(),
 	}
-	err := h.h.ServeHTTPErr(w, r)
-	if err == context.Canceled {
-		// No need to inform client, but still log the
-		// cancellation.
-		//
-		// TODO(bradfitz): this 499 thing is weird and
-		// undocumented. Also, shouldn't it be "err != nil &&
-		// r.Context().Err() == context.Canceled" instead?  If
-		// they just return an error, it could've been from
-		// the handler's own context cancel.
-		msg.HTTP.Code = 499 // nginx convention: Client Closed Request
-		msg.Err = err
-	} else if hErr, ok := err.(HTTPError); ok {
-		msg.HTTP.Code = hErr.Code
-		if msg.HTTP.Code == 0 {
-			msg.HTTP.Code = 500
+
+	lw := loggingResponseWriter{ResponseWriter: w, logf: h.logf}
+	err := h.h.ServeHTTPErr(&lw, r)
+	hErr, hErrOK := err.(HTTPError)
+
+	msg.Seconds = h.timeNow().Sub(msg.When).Seconds()
+	msg.Code = lw.code
+	msg.Bytes = lw.bytes
+
+	switch {
+	case lw.hijacked:
+		// Connection no longer belongs to us, just log that we
+		// switched protocols away from HTTP.
+		if msg.Code == 0 {
+			msg.Code = http.StatusSwitchingProtocols
+		}
+	case err != nil && r.Context().Err() == context.Canceled:
+		msg.Code = 499 // nginx convention: Client Closed Request
+		msg.Err = context.Canceled.Error()
+	case hErrOK:
+		// Handler asked us to send an error. Do so, if we haven't
+		// already sent a response.
+		msg.Err = hErr.Err.Error()
+		if lw.code != 0 {
+			h.logf("[unexpected] handler returned HTTPError %v, but already sent a response with code %d", hErr, lw.code)
+			break
 		}
-		msg.Err = hErr.Err
-		msg.Msg = hErr.Msg
-		http.Error(w, hErr.Msg, hErr.Code)
-	} else if err != nil {
-		msg.HTTP.Code = 500
-		msg.Err = err
-		msg.Msg = "internal server error"
-		http.Error(w, msg.Msg, msg.HTTP.Code)
+		msg.Code = hErr.Code
+		if msg.Code == 0 {
+			h.logf("[unexpected] HTTPError %v did not contain an HTTP status code, sending internal server error", hErr)
+			msg.Code = http.StatusInternalServerError
+		}
+		http.Error(&lw, hErr.Msg, msg.Code)
+	case err != nil:
+		// Handler returned a generic error. Serve an internal server
+		// error, if necessary.
+		msg.Err = err.Error()
+		if lw.code == 0 {
+			msg.Code = http.StatusInternalServerError
+			http.Error(&lw, "internal server error", msg.Code)
+		}
+	case lw.code == 0:
+		// Handler exited successfully, but didn't generate a
+		// response. Synthesize an internal server error.
+		msg.Code = http.StatusInternalServerError
+		msg.Err = "[unexpected] handler did not respond to the client"
+		http.Error(&lw, "internal server error", msg.Code)
 	}
 
+	// Cleanup below is common to all success and error paths. msg has
+	// been populated with relevant information either way.
+
 	// TODO(danderson): needed? Copied from existing code, but
 	// doesn't HTTPServer do this by itself?
-	if f, _ := w.(http.Flusher); f != nil {
+	if f, _ := w.(http.Flusher); !lw.hijacked && f != nil {
 		f.Flush()
 	}
 	h.logf("%s", msg)
 }
 
-// StdHandler converts a Handler into a standard http.Handler.
-// Handled requests and any errors returned by h are logged using
-// logf. Errors are handled as specified by the Handler interface.
-func StdHandler(h Handler, logf logger.Logf) http.Handler {
-	return handler{h, logf}
+// loggingResponseWriter wraps a ResponseWriter and record the HTTP
+// response code that gets sent, if any.
+type loggingResponseWriter struct {
+	http.ResponseWriter
+	code     int
+	bytes    int
+	hijacked bool
+	logf     logger.Logf
+}
+
+// WriteHeader implements http.Handler.
+func (l *loggingResponseWriter) WriteHeader(statusCode int) {
+	if l.code != 0 {
+		l.logf("[unexpected] HTTP handler set statusCode twice (%d and %d)", l.code, statusCode)
+		return
+	}
+	l.code = statusCode
+	l.ResponseWriter.WriteHeader(statusCode)
+}
+
+// Write implements http.Handler.
+func (l *loggingResponseWriter) Write(bs []byte) (int, error) {
+	if l.code == 0 {
+		l.code = 200
+	}
+	n, err := l.ResponseWriter.Write(bs)
+	l.bytes += n
+	return n, err
+}
+
+// Hijack implements http.Hijacker. Note that hijacking can still fail
+// because the wrapped ResponseWriter is not required to implement
+// Hijacker, as this breaks HTTP/2.
+func (l *loggingResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+	h, ok := l.ResponseWriter.(http.Hijacker)
+	if !ok {
+		return nil, nil, errors.New("ResponseWriter is not a Hijacker")
+	}
+	conn, buf, err := h.Hijack()
+	if err == nil {
+		l.hijacked = true
+	}
+	return conn, buf, err
+}
+
+func (l loggingResponseWriter) Flush() {
+	f, _ := l.ResponseWriter.(http.Flusher)
+	if f == nil {
+		l.logf("[unexpected] tried to Flush a ResponseWriter that can't flush")
+		return
+	}
+	f.Flush()
 }
 
 // HTTPError is an error with embedded HTTP response information.

tsweb/tsweb_test.go

@@ -0,0 +1,254 @@
+// Copyright (c) 2020 Tailscale Inc & AUTHORS All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package tsweb
+
+import (
+	"bufio"
+	"context"
+	"errors"
+	"net"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+	"time"
+
+	"github.com/google/go-cmp/cmp"
+	"tailscale.com/testy"
+)
+
+type noopHijacker struct {
+	*httptest.ResponseRecorder
+	hijacked bool
+}
+
+func (h *noopHijacker) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+	// Hijack "successfully" but don't bother returning a conn.
+	h.hijacked = true
+	return nil, nil, nil
+}
+
+func TestStdHandler(t *testing.T) {
+	var (
+		handlerCode = func(code int) Handler {
+			return HandlerFunc(func(w http.ResponseWriter, r *http.Request) error {
+				w.WriteHeader(code)
+				return nil
+			})
+		}
+		handlerErr = func(code int, err error) Handler {
+			return HandlerFunc(func(w http.ResponseWriter, r *http.Request) error {
+				if code != 0 {
+					w.WriteHeader(code)
+				}
+				return err
+			})
+		}
+
+		req = func(ctx context.Context, url string) *http.Request {
+			ret, err := http.NewRequestWithContext(ctx, "GET", url, nil)
+			if err != nil {
+				panic(err)
+			}
+			return ret
+		}
+
+		testErr = errors.New("test error")
+		bgCtx   = context.Background()
+		// canceledCtx, cancel = context.WithCancel(bgCtx)
+		clock = testy.Clock{
+			Start: time.Now(),
+			Step:  time.Second,
+		}
+	)
+	// cancel()
+
+	tests := []struct {
+		name     string
+		h        Handler
+		r        *http.Request
+		wantCode int
+		wantLog  AccessLogRecord
+	}{
+		{
+			name:     "handler returns 200",
+			h:        handlerCode(200),
+			r:        req(bgCtx, "http://example.com/"),
+			wantCode: 200,
+			wantLog: AccessLogRecord{
+				When:       clock.Start,
+				Seconds:    1.0,
+				Proto:      "HTTP/1.1",
+				TLS:        false,
+				Host:       "example.com",
+				Method:     "GET",
+				Code:       200,
+				RequestURI: "/",
+			},
+		},
+
+		{
+			name:     "handler returns 404",
+			h:        handlerCode(404),
+			r:        req(bgCtx, "http://example.com/foo"),
+			wantCode: 404,
+			wantLog: AccessLogRecord{
+				When:       clock.Start,
+				Seconds:    1.0,
+				Proto:      "HTTP/1.1",
+				Host:       "example.com",
+				Method:     "GET",
+				RequestURI: "/foo",
+				Code:       404,
+			},
+		},
+
+		{
+			name:     "handler returns 404 via HTTPError",
+			h:        handlerErr(0, Error(404, "not found", testErr)),
+			r:        req(bgCtx, "http://example.com/foo"),
+			wantCode: 404,
+			wantLog: AccessLogRecord{
+				When:       clock.Start,
+				Seconds:    1.0,
+				Proto:      "HTTP/1.1",
+				Host:       "example.com",
+				Method:     "GET",
+				RequestURI: "/foo",
+				Err:        testErr.Error(),
+				Code:       404,
+			},
+		},
+
+		{
+			name:     "handler returns generic error",
+			h:        handlerErr(0, testErr),
+			r:        req(bgCtx, "http://example.com/foo"),
+			wantCode: 500,
+			wantLog: AccessLogRecord{
+				When:       clock.Start,
+				Seconds:    1.0,
+				Proto:      "HTTP/1.1",
+				Host:       "example.com",
+				Method:     "GET",
+				RequestURI: "/foo",
+				Err:        testErr.Error(),
+				Code:       500,
+			},
+		},
+
+		{
+			name:     "handler returns error after writing response",
+			h:        handlerErr(200, testErr),
+			r:        req(bgCtx, "http://example.com/foo"),
+			wantCode: 200,
+			wantLog: AccessLogRecord{
+				When:       clock.Start,
+				Seconds:    1.0,
+				Proto:      "HTTP/1.1",
+				Host:       "example.com",
+				Method:     "GET",
+				RequestURI: "/foo",
+				Err:        testErr.Error(),
+				Code:       200,
+			},
+		},
+
+		{
+			name:     "handler returns HTTPError after writing response",
+			h:        handlerErr(200, Error(404, "not found", testErr)),
+			r:        req(bgCtx, "http://example.com/foo"),
+			wantCode: 200,
+			wantLog: AccessLogRecord{
+				When:       clock.Start,
+				Seconds:    1.0,
+				Proto:      "HTTP/1.1",
+				Host:       "example.com",
+				Method:     "GET",
+				RequestURI: "/foo",
+				Err:        testErr.Error(),
+				Code:       200,
+			},
+		},
+
+		{
+			name:     "handler does nothing",
+			h:        HandlerFunc(func(http.ResponseWriter, *http.Request) error { return nil }),
+			r:        req(bgCtx, "http://example.com/foo"),
+			wantCode: 500,
+			wantLog: AccessLogRecord{
+				When:       clock.Start,
+				Seconds:    1.0,
+				Proto:      "HTTP/1.1",
+				Host:       "example.com",
+				Method:     "GET",
+				RequestURI: "/foo",
+				Code:       500,
+				Err:        "[unexpected] handler did not respond to the client",
+			},
+		},
+
+		{
+			name: "handler hijacks conn",
+			h: HandlerFunc(func(w http.ResponseWriter, r *http.Request) error {
+				_, _, err := w.(http.Hijacker).Hijack()
+				if err != nil {
+					t.Errorf("couldn't hijack: %v", err)
+				}
+				return err
+			}),
+			r:        req(bgCtx, "http://example.com/foo"),
+			wantCode: 0,
+			wantLog: AccessLogRecord{
+				When:    clock.Start,
+				Seconds: 1.0,
+
+				Proto:      "HTTP/1.1",
+				Host:       "example.com",
+				Method:     "GET",
+				RequestURI: "/foo",
+				Code:       101,
+			},
+		},
+	}
+
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			var logs []AccessLogRecord
+			logf := func(fmt string, args ...interface{}) {
+				if fmt == "%s" {
+					logs = append(logs, args[0].(AccessLogRecord))
+				}
+				t.Logf(fmt, args...)
+			}
+
+			clock.Reset()
+
+			rec := noopHijacker{httptest.NewRecorder(), false}
+			// ResponseRecorder defaults Code to 200, grump.
+			rec.Code = 0
+			h := stdHandler(test.h, logf, clock.Now)
+			h.ServeHTTP(&rec, test.r)
+			if rec.Code != test.wantCode {
+				t.Errorf("HTTP code = %v, want %v", rec.Code, test.wantCode)
+			}
+			if !rec.hijacked && !rec.Flushed {
+				t.Errorf("handler didn't flush")
+			}
+			if len(logs) != 1 {
+				t.Errorf("handler didn't write a request log")
+				return
+			}
+			errTransform := cmp.Transformer("err", func(e error) string {
+				if e == nil {
+					return ""
+				}
+				return e.Error()
+			})
+			if diff := cmp.Diff(logs[0], test.wantLog, errTransform); diff != "" {
+				t.Errorf("handler wrote incorrect request log (-got+want):\n%s", diff)
+			}
+		})
+	}
+}