From b819f66eb1efab85dcf5550d4f0da92fb7ab2551 Mon Sep 17 00:00:00 2001 From: Marwan Sulaiman Date: Tue, 28 Nov 2023 18:37:21 -0500 Subject: [PATCH] tsweb: propagate RequestID via context and entire request The recent addition of RequestID was only populated if the HTTP Request had returned an error. This meant that the underlying handler has no access to this request id and any logs it may have emitted were impossible to correlate to that request id. Therefore, this PR adds a middleware to generate request ids and pass them through the request context. The tsweb.StdHandler automatically populates this request id if the middleware is being used. Finally, inner handlers can use the context to retrieve that same request id and use it so that all logs and events can be correlated. Updates #2549 Signed-off-by: Marwan Sulaiman --- cmd/derper/depaware.txt | 2 + tsweb/log.go | 10 +-- tsweb/request_id.go | 63 +++++++++++++++++++ tsweb/tsweb.go | 67 ++++++-------------- tsweb/tsweb_test.go | 134 ++++++++++++++-------------------------- 5 files changed, 136 insertions(+), 140 deletions(-) create mode 100644 tsweb/request_id.go diff --git a/cmd/derper/depaware.txt b/cmd/derper/depaware.txt index 4915ceafc..5191768a2 100644 --- a/cmd/derper/depaware.txt +++ b/cmd/derper/depaware.txt @@ -18,6 +18,7 @@ tailscale.com/cmd/derper dependencies: (generated by github.com/tailscale/depawa L github.com/google/nftables/expr from github.com/google/nftables+ L github.com/google/nftables/internal/parseexprfunc from github.com/google/nftables+ L github.com/google/nftables/xt from github.com/google/nftables/expr+ + github.com/google/uuid from tailscale.com/tsweb github.com/hdevalence/ed25519consensus from tailscale.com/tka L github.com/josharian/native from github.com/mdlayher/netlink+ L 💣 github.com/jsimonetti/rtnetlink from tailscale.com/net/interfaces+ @@ -218,6 +219,7 @@ tailscale.com/cmd/derper dependencies: (generated by github.com/tailscale/depawa crypto/tls from golang.org/x/crypto/acme+ crypto/x509 from crypto/tls+ crypto/x509/pkix from crypto/x509+ + database/sql/driver from github.com/google/uuid embed from crypto/internal/nistec+ encoding from encoding/json+ encoding/asn1 from crypto/x509+ diff --git a/tsweb/log.go b/tsweb/log.go index 1049723f9..914e247f1 100644 --- a/tsweb/log.go +++ b/tsweb/log.go @@ -45,11 +45,11 @@ 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 is a unique ID for this request. If the *http.Request context + // carries this value via SetRequestID, then it will be 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"` } diff --git a/tsweb/request_id.go b/tsweb/request_id.go new file mode 100644 index 000000000..56a4f5a27 --- /dev/null +++ b/tsweb/request_id.go @@ -0,0 +1,63 @@ +// Copyright (c) Tailscale Inc & AUTHORS +// SPDX-License-Identifier: BSD-3-Clause + +package tsweb + +import ( + "context" + "net/http" + + "github.com/google/uuid" +) + +// RequestID is an opaque identifier for a HTTP request, used to correlate +// user-visible errors with backend server logs. The RequestID is typically +// threaded through an HTTP Middleware (WithRequestID) and then can be extracted +// by HTTP Handlers to include in their logs. +// +// RequestID is an opaque identifier for a HTTP request, used to correlate +// user-visible errors with backend server logs. If present in the context, the +// RequestID will be printed alongside the message text and logged in the +// AccessLogRecord. +// +// A RequestID has the format "REQ-1{ID}", and the ID should be treated as an +// opaque string. The current implementation uses a UUID. +type RequestID string + +// RequestIDHeader is a custom HTTP header that the WithRequestID middleware +// uses to determine whether to re-use a given request ID from the client +// or generate a new one. +const RequestIDHeader = "X-Tailscale-Request-Id" + +// SetRequestID is an HTTP middleware that injects a RequestID in the +// *http.Request Context. The value of that request id is either retrieved from +// the RequestIDHeader or a randomly generated one if not exists. Inner +// handlers can retrieve this ID from the RequestIDFromContext function. +func SetRequestID(h http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + id := r.Header.Get(RequestIDHeader) + if id == "" { + // REQ-1 indicates the version of the RequestID pattern. It is + // currently arbitrary but allows for forward compatible + // transitions if needed. + id = "REQ-1" + uuid.NewString() + } + ctx := withRequestID(r.Context(), RequestID(id)) + r = r.WithContext(ctx) + h.ServeHTTP(w, r) + }) +} + +type requestIDKey struct{} + +// RequestIDFromContext retrieves the RequestID from context that can be set by +// the SetRequestID function. +func RequestIDFromContext(ctx context.Context) RequestID { + val, _ := ctx.Value(requestIDKey{}).(RequestID) + return val +} + +// withRequestID sets the given request id value in the given context. +func withRequestID(ctx context.Context, rid RequestID) context.Context { + return context.WithValue(ctx, requestIDKey{}, rid) +} diff --git a/tsweb/tsweb.go b/tsweb/tsweb.go index 7128bde13..0c504e787 100644 --- a/tsweb/tsweb.go +++ b/tsweb/tsweb.go @@ -177,8 +177,7 @@ 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 - GenerateRequestID func(*http.Request) RequestID // if nil, no request IDs are generated + Now func() time.Time // if nil, defaults to time.Now // If non-nil, StatusCodeCounters maintains counters // of status codes for handled responses. @@ -204,6 +203,13 @@ type ErrorHandlerFunc func(http.ResponseWriter, *http.Request, HTTPError) // calls f. type ReturnHandlerFunc func(http.ResponseWriter, *http.Request) error +// A Middleware is a function that wraps an http.Handler to extend or modify +// its behaviour. +// +// The implementation of the wrapper is responsible for delegating its input +// request to the underlying handler, if appropriate. +type Middleware func(h http.Handler) http.Handler + // ServeHTTPReturn calls f(w, r). func (f ReturnHandlerFunc) ServeHTTPReturn(w http.ResponseWriter, r *http.Request) error { return f(w, r) @@ -240,6 +246,7 @@ func (h retHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { RequestURI: r.URL.RequestURI(), UserAgent: r.UserAgent(), Referer: r.Referer(), + RequestID: RequestIDFromContext(r.Context()), } lw := &loggingResponseWriter{ResponseWriter: w, logf: h.opts.Logf} @@ -275,11 +282,6 @@ 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 @@ -310,17 +312,15 @@ 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) + if msg.RequestID != "" { + fmt.Fprintln(lw, msg.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) + if msg.RequestID != "" { + errorMessage += "\n" + string(msg.RequestID) } // Handler returned a generic error. Serve an internal server // error, if necessary. @@ -422,45 +422,18 @@ 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 - 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 + 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 } // Error implements the error interface. -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) Error() string { return fmt.Sprintf("httperror{%d, %q, %v}", e.Code, e.Msg, e.Err) } func (e HTTPError) Unwrap() error { return e.Err } // Error returns an HTTPError containing the given information. @@ -502,8 +475,8 @@ func BrowserHeaderHandler(h http.Handler) http.Handler { // BrowserHeaderHandlerFunc wraps the provided http.HandlerFunc with a call to // AddBrowserHeaders. func BrowserHeaderHandlerFunc(h http.HandlerFunc) http.HandlerFunc { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + return func(w http.ResponseWriter, r *http.Request) { AddBrowserHeaders(w) h.ServeHTTP(w, r) - }) + } } diff --git a/tsweb/tsweb_test.go b/tsweb/tsweb_test.go index 8b1015909..54bf0d873 100644 --- a/tsweb/tsweb_test.go +++ b/tsweb/tsweb_test.go @@ -67,20 +67,17 @@ 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 - generateRequestID func(*http.Request) RequestID - wantCode int - wantLog AccessLogRecord - wantBody string + name string + rh ReturnHandler + r *http.Request + errHandler ErrorHandlerFunc + wantCode int + wantLog AccessLogRecord + wantBody string }{ { name: "handler returns 200", @@ -100,11 +97,10 @@ 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, + name: "handler returns 200 with request ID", + rh: handlerCode(200), + r: req(bgCtx, "http://example.com/"), + wantCode: 200, wantLog: AccessLogRecord{ When: startTime, Seconds: 1.0, @@ -134,11 +130,10 @@ 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, + name: "handler returns 404 with request ID", + rh: handlerCode(404), + r: req(bgCtx, "http://example.com/foo"), + wantCode: 404, wantLog: AccessLogRecord{ When: startTime, Seconds: 1.0, @@ -169,11 +164,10 @@ func TestStdHandler(t *testing.T) { }, { - 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, + name: "handler returns 404 via HTTPError with request ID", + rh: handlerErr(0, Error(404, "not found", testErr)), + r: req(withRequestID(bgCtx, exampleRequestID), "http://example.com/foo"), + wantCode: 404, wantLog: AccessLogRecord{ When: startTime, Seconds: 1.0, @@ -207,11 +201,10 @@ func TestStdHandler(t *testing.T) { }, { - 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, + name: "handler returns 404 with request ID and nil child error", + rh: handlerErr(0, Error(404, "not found", nil)), + r: req(withRequestID(bgCtx, exampleRequestID), "http://example.com/foo"), + wantCode: 404, wantLog: AccessLogRecord{ When: startTime, Seconds: 1.0, @@ -245,11 +238,10 @@ func TestStdHandler(t *testing.T) { }, { - 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, + name: "handler returns user-visible error with request ID", + rh: handlerErr(0, vizerror.New("visible error")), + r: req(withRequestID(bgCtx, exampleRequestID), "http://example.com/foo"), + wantCode: 500, wantLog: AccessLogRecord{ When: startTime, Seconds: 1.0, @@ -283,11 +275,10 @@ func TestStdHandler(t *testing.T) { }, { - 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, + 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(withRequestID(bgCtx, exampleRequestID), "http://example.com/foo"), + wantCode: 500, wantLog: AccessLogRecord{ When: startTime, Seconds: 1.0, @@ -321,11 +312,10 @@ func TestStdHandler(t *testing.T) { }, { - name: "handler returns generic error with request ID", - rh: handlerErr(0, testErr), - r: req(bgCtx, "http://example.com/foo"), - generateRequestID: setExampleRequestID, - wantCode: 500, + name: "handler returns generic error with request ID", + rh: handlerErr(0, testErr), + r: req(withRequestID(bgCtx, exampleRequestID), "http://example.com/foo"), + wantCode: 500, wantLog: AccessLogRecord{ When: startTime, Seconds: 1.0, @@ -358,11 +348,10 @@ 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, + name: "handler returns error after writing response with request ID", + rh: handlerErr(200, testErr), + r: req(withRequestID(bgCtx, exampleRequestID), "http://example.com/foo"), + wantCode: 200, wantLog: AccessLogRecord{ When: startTime, Seconds: 1.0, @@ -455,13 +444,13 @@ func TestStdHandler(t *testing.T) { }, { - 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, + name: "error handler gets run with request ID", + rh: handlerErr(0, Error(404, "not found", nil)), // status code changed in errHandler + r: req(withRequestID(bgCtx, exampleRequestID), "http://example.com/"), + 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) + requestID := RequestIDFromContext(r.Context()) + http.Error(w, fmt.Sprintf("%s with request ID %s", e.Msg, requestID), 200) }, wantLog: AccessLogRecord{ When: startTime, @@ -477,37 +466,6 @@ func TestStdHandler(t *testing.T) { }, 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", - }, } for _, test := range tests { @@ -526,7 +484,7 @@ func TestStdHandler(t *testing.T) { }) rec := noopHijacker{httptest.NewRecorder(), false} - h := StdHandler(test.rh, HandlerOptions{Logf: logf, Now: clock.Now, GenerateRequestID: test.generateRequestID, OnError: test.errHandler}) + h := StdHandler(test.rh, HandlerOptions{Logf: logf, Now: clock.Now, OnError: test.errHandler}) h.ServeHTTP(&rec, test.r) res := rec.Result() if res.StatusCode != test.wantCode {