From f75a36f9bcc27865bf0b80f9d4ca746714e407fc Mon Sep 17 00:00:00 2001 From: Adrian Dewhurst Date: Fri, 11 Aug 2023 16:41:58 -0400 Subject: [PATCH] tsweb: add request ID for errors If an optional request ID generating func is supplied to StdHandler, then requests that return an error will be logged with a request ID that is also shown as part of the response. Updates tailscale/corp#2549 Change-Id: Ic7499706df42f95b6878d44d4aab253e2fc6a69b Signed-off-by: Adrian Dewhurst --- tsweb/log.go | 6 ++ tsweb/tsweb.go | 56 +++++++++-- tsweb/tsweb_test.go | 238 ++++++++++++++++++++++++++++++++++++++++++-- 3 files changed, 286 insertions(+), 14 deletions(-) diff --git a/tsweb/log.go b/tsweb/log.go index 059461ba7..1049723f9 100644 --- a/tsweb/log.go +++ b/tsweb/log.go @@ -45,6 +45,12 @@ type AccessLogRecord struct { Bytes int `json:"bytes,omitempty"` // Error encountered during request processing. Err string `json:"err,omitempty"` + // RequestID is a unique ID for this request. When a request fails due to an + // error, the ID is generated and displayed to the client immediately after + // the error text, as well as logged here. This makes it easier to correlate + // support requests with server logs. If a RequestID generator is not + // configured, RequestID will be empty. + RequestID RequestID `json:"request_id,omitempty"` } // String returns m as a JSON string. diff --git a/tsweb/tsweb.go b/tsweb/tsweb.go index c4e042aa1..fff285f70 100644 --- a/tsweb/tsweb.go +++ b/tsweb/tsweb.go @@ -169,7 +169,8 @@ type ReturnHandler interface { type HandlerOptions struct { QuietLoggingIfSuccessful bool // if set, do not log successfully handled HTTP requests (200 and 304 status codes) Logf logger.Logf - Now func() time.Time // if nil, defaults to time.Now + Now func() time.Time // if nil, defaults to time.Now + GenerateRequestID func(*http.Request) RequestID // if nil, no request IDs are generated // If non-nil, StatusCodeCounters maintains counters // of status codes for handled responses. @@ -266,6 +267,11 @@ func (h retHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { msg.Code = 499 // nginx convention: Client Closed Request msg.Err = context.Canceled.Error() case hErrOK: + if hErr.RequestID == "" && h.opts.GenerateRequestID != nil { + hErr.RequestID = h.opts.GenerateRequestID(r) + } + msg.RequestID = hErr.RequestID + // Handler asked us to send an error. Do so, if we haven't // already sent a response. msg.Err = hErr.Msg @@ -296,14 +302,24 @@ func (h retHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } lw.WriteHeader(msg.Code) fmt.Fprintln(lw, hErr.Msg) + if hErr.RequestID != "" { + fmt.Fprintln(lw, hErr.RequestID) + } } case err != nil: + const internalServerError = "internal server error" + + errorMessage := internalServerError + if h.opts.GenerateRequestID != nil { + msg.RequestID = h.opts.GenerateRequestID(r) + errorMessage = errorMessage + "\n" + string(msg.RequestID) + } // 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) + http.Error(lw, errorMessage, msg.Code) } } @@ -398,18 +414,44 @@ func (l loggingResponseWriter) Flush() { f.Flush() } +// RequestID is an opaque identifier for a HTTP request, used to correlate +// user-visible errors with backend server logs. If present in a HTTPError, the +// RequestID will be printed alongside the message text and logged in the +// AccessLogRecord. If an HTTPError has no RequestID (or a non-HTTPError error +// is returned), but the StdHandler has a RequestID generator function, then a +// RequestID will be generated before responding to the client and logging the +// error. +// +// In the event that there is no ErrorHandlerFunc and a non-HTTPError is +// returned to a StdHandler, the response body will be formatted like +// "internal server error\n{RequestID}\n". +// +// There is no particular format required for a RequestID, but ideally it should +// be obvious to an end-user that it is something to record for support +// purposes. One possible example for a RequestID format is: +// REQ-{server identifier}-{timestamp}-{random hex string}. +type RequestID string + // HTTPError is an error with embedded HTTP response information. // // It is the error type to be (optionally) used by Handler.ServeHTTPReturn. type HTTPError struct { - Code int // HTTP response code to send to client; 0 means 500 - Msg string // Response body to send to client - Err error // Detailed error to log on the server - Header http.Header // Optional set of HTTP headers to set in the response + Code int // HTTP response code to send to client; 0 means 500 + Msg string // Response body to send to client + Err error // Detailed error to log on the server + RequestID RequestID // Optional identifier to connect client-visible errors with server logs + Header http.Header // Optional set of HTTP headers to set in the response } // Error implements the error interface. -func (e HTTPError) Error() string { return fmt.Sprintf("httperror{%d, %q, %v}", e.Code, e.Msg, e.Err) } +func (e HTTPError) Error() string { + if e.RequestID != "" { + return fmt.Sprintf("httperror{%d, %q, %v, RequestID=%q}", e.Code, e.Msg, e.Err, e.RequestID) + } else { + // Backwards compatibility + return fmt.Sprintf("httperror{%d, %q, %v}", e.Code, e.Msg, e.Err) + } +} func (e HTTPError) Unwrap() error { return e.Err } diff --git a/tsweb/tsweb_test.go b/tsweb/tsweb_test.go index 8a3b0d974..8b1015909 100644 --- a/tsweb/tsweb_test.go +++ b/tsweb/tsweb_test.go @@ -38,6 +38,7 @@ func (f handlerFunc) ServeHTTPReturn(w http.ResponseWriter, r *http.Request) err } func TestStdHandler(t *testing.T) { + const exampleRequestID = "example-request-id" var ( handlerCode = func(code int) ReturnHandler { return handlerFunc(func(w http.ResponseWriter, r *http.Request) error { @@ -66,16 +67,20 @@ func TestStdHandler(t *testing.T) { bgCtx = context.Background() // canceledCtx, cancel = context.WithCancel(bgCtx) startTime = time.Unix(1687870000, 1234) + + setExampleRequestID = func(_ *http.Request) RequestID { return exampleRequestID } ) // cancel() tests := []struct { - name string - rh ReturnHandler - r *http.Request - errHandler ErrorHandlerFunc - wantCode int - wantLog AccessLogRecord + name string + rh ReturnHandler + r *http.Request + errHandler ErrorHandlerFunc + generateRequestID func(*http.Request) RequestID + wantCode int + wantLog AccessLogRecord + wantBody string }{ { name: "handler returns 200", @@ -94,6 +99,24 @@ func TestStdHandler(t *testing.T) { }, }, + { + name: "handler returns 200 with request ID", + rh: handlerCode(200), + r: req(bgCtx, "http://example.com/"), + generateRequestID: setExampleRequestID, + wantCode: 200, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + TLS: false, + Host: "example.com", + Method: "GET", + Code: 200, + RequestURI: "/", + }, + }, + { name: "handler returns 404", rh: handlerCode(404), @@ -110,6 +133,23 @@ func TestStdHandler(t *testing.T) { }, }, + { + name: "handler returns 404 with request ID", + rh: handlerCode(404), + r: req(bgCtx, "http://example.com/foo"), + generateRequestID: setExampleRequestID, + wantCode: 404, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + Host: "example.com", + Method: "GET", + RequestURI: "/foo", + Code: 404, + }, + }, + { name: "handler returns 404 via HTTPError", rh: handlerErr(0, Error(404, "not found", testErr)), @@ -125,6 +165,27 @@ func TestStdHandler(t *testing.T) { Err: "not found: " + testErr.Error(), Code: 404, }, + wantBody: "not found\n", + }, + + { + name: "handler returns 404 via HTTPError with request ID", + rh: handlerErr(0, Error(404, "not found", testErr)), + r: req(bgCtx, "http://example.com/foo"), + generateRequestID: setExampleRequestID, + wantCode: 404, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + Host: "example.com", + Method: "GET", + RequestURI: "/foo", + Err: "not found: " + testErr.Error(), + Code: 404, + RequestID: exampleRequestID, + }, + wantBody: "not found\n" + exampleRequestID + "\n", }, { @@ -142,6 +203,27 @@ func TestStdHandler(t *testing.T) { Err: "not found", Code: 404, }, + wantBody: "not found\n", + }, + + { + name: "handler returns 404 with request ID and nil child error", + rh: handlerErr(0, Error(404, "not found", nil)), + r: req(bgCtx, "http://example.com/foo"), + generateRequestID: setExampleRequestID, + wantCode: 404, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + Host: "example.com", + Method: "GET", + RequestURI: "/foo", + Err: "not found", + Code: 404, + RequestID: exampleRequestID, + }, + wantBody: "not found\n" + exampleRequestID + "\n", }, { @@ -159,6 +241,27 @@ func TestStdHandler(t *testing.T) { Err: "visible error", Code: 500, }, + wantBody: "visible error\n", + }, + + { + name: "handler returns user-visible error with request ID", + rh: handlerErr(0, vizerror.New("visible error")), + r: req(bgCtx, "http://example.com/foo"), + generateRequestID: setExampleRequestID, + wantCode: 500, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + Host: "example.com", + Method: "GET", + RequestURI: "/foo", + Err: "visible error", + Code: 500, + RequestID: exampleRequestID, + }, + wantBody: "visible error\n" + exampleRequestID + "\n", }, { @@ -176,6 +279,27 @@ func TestStdHandler(t *testing.T) { Err: "visible error", Code: 500, }, + wantBody: "visible error\n", + }, + + { + name: "handler returns user-visible error wrapped by private error with request ID", + rh: handlerErr(0, fmt.Errorf("private internal error: %w", vizerror.New("visible error"))), + r: req(bgCtx, "http://example.com/foo"), + generateRequestID: setExampleRequestID, + wantCode: 500, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + Host: "example.com", + Method: "GET", + RequestURI: "/foo", + Err: "visible error", + Code: 500, + RequestID: exampleRequestID, + }, + wantBody: "visible error\n" + exampleRequestID + "\n", }, { @@ -193,6 +317,27 @@ func TestStdHandler(t *testing.T) { Err: testErr.Error(), Code: 500, }, + wantBody: "internal server error\n", + }, + + { + name: "handler returns generic error with request ID", + rh: handlerErr(0, testErr), + r: req(bgCtx, "http://example.com/foo"), + generateRequestID: setExampleRequestID, + wantCode: 500, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + Host: "example.com", + Method: "GET", + RequestURI: "/foo", + Err: testErr.Error(), + Code: 500, + RequestID: exampleRequestID, + }, + wantBody: "internal server error\n" + exampleRequestID + "\n", }, { @@ -212,6 +357,25 @@ func TestStdHandler(t *testing.T) { }, }, + { + name: "handler returns error after writing response with request ID", + rh: handlerErr(200, testErr), + r: req(bgCtx, "http://example.com/foo"), + generateRequestID: setExampleRequestID, + wantCode: 200, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + Host: "example.com", + Method: "GET", + RequestURI: "/foo", + Err: testErr.Error(), + Code: 200, + RequestID: exampleRequestID, + }, + }, + { name: "handler returns HTTPError after writing response", rh: handlerErr(200, Error(404, "not found", testErr)), @@ -267,6 +431,7 @@ func TestStdHandler(t *testing.T) { Code: 101, }, }, + { name: "error handler gets run", rh: handlerErr(0, Error(404, "not found", nil)), // status code changed in errHandler @@ -286,6 +451,62 @@ func TestStdHandler(t *testing.T) { Err: "not found", RequestURI: "/", }, + wantBody: "not found\n", + }, + + { + name: "error handler gets run with request ID", + rh: handlerErr(0, Error(404, "not found", nil)), // status code changed in errHandler + r: req(bgCtx, "http://example.com/"), + generateRequestID: setExampleRequestID, + wantCode: 200, + errHandler: func(w http.ResponseWriter, r *http.Request, e HTTPError) { + http.Error(w, fmt.Sprintf("%s with request ID %s", e.Msg, e.RequestID), 200) + }, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + TLS: false, + Host: "example.com", + Method: "GET", + Code: 404, + Err: "not found", + RequestURI: "/", + RequestID: exampleRequestID, + }, + wantBody: "not found with request ID " + exampleRequestID + "\n", + }, + + { + name: "request ID can use information from request", + rh: handlerErr(0, Error(400, "bad request", nil)), + r: func() *http.Request { + r := req(bgCtx, "http://example.com/") + r.AddCookie(&http.Cookie{Name: "want_request_id", Value: "asdf1234"}) + return r + }(), + generateRequestID: func(r *http.Request) RequestID { + c, _ := r.Cookie("want_request_id") + if c == nil { + return "" + } + return RequestID(c.Value) + }, + wantCode: 400, + wantLog: AccessLogRecord{ + When: startTime, + Seconds: 1.0, + Proto: "HTTP/1.1", + TLS: false, + Host: "example.com", + RequestURI: "/", + Method: "GET", + Code: 400, + Err: "bad request", + RequestID: "asdf1234", + }, + wantBody: "bad request\nasdf1234\n", }, } @@ -305,7 +526,7 @@ func TestStdHandler(t *testing.T) { }) rec := noopHijacker{httptest.NewRecorder(), false} - h := StdHandler(test.rh, HandlerOptions{Logf: logf, Now: clock.Now, OnError: test.errHandler}) + h := StdHandler(test.rh, HandlerOptions{Logf: logf, Now: clock.Now, GenerateRequestID: test.generateRequestID, OnError: test.errHandler}) h.ServeHTTP(&rec, test.r) res := rec.Result() if res.StatusCode != test.wantCode { @@ -324,6 +545,9 @@ func TestStdHandler(t *testing.T) { if diff := cmp.Diff(logs[0], test.wantLog, errTransform); diff != "" { t.Errorf("handler wrote incorrect request log (-got+want):\n%s", diff) } + if diff := cmp.Diff(rec.Body.String(), test.wantBody); diff != "" { + t.Errorf("handler wrote incorrect body (-got+want):\n%s", diff) + } }) } }