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 <adrian@tailscale.com>

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.

tsweb/tsweb.go

@@ -170,6 +170,7 @@ 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
+	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,6 +414,24 @@ 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.
@@ -405,11 +439,19 @@ 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
+	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 }
 

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,6 +67,8 @@ 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()
 
@@ -74,8 +77,10 @@ func TestStdHandler(t *testing.T) {
 		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)
+			}
 		})
 	}
 }