diff --git a/tsweb/log.go b/tsweb/log.go index 788e46720..e7928af04 100644 --- a/tsweb/log.go +++ b/tsweb/log.go @@ -10,30 +10,46 @@ "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() } diff --git a/tsweb/tsweb.go b/tsweb/tsweb.go index ff22454f0..42cd85dd4 100644 --- a/tsweb/tsweb.go +++ b/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 } - 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) + 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.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. diff --git a/tsweb/tsweb_test.go b/tsweb/tsweb_test.go new file mode 100644 index 000000000..4c4de4550 --- /dev/null +++ b/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) + } + }) + } +}