diff --git a/proxy/internal/accesslog/middleware.go b/proxy/internal/accesslog/middleware.go index b5d1c0e9d..12828d50e 100644 --- a/proxy/internal/accesslog/middleware.go +++ b/proxy/internal/accesslog/middleware.go @@ -13,20 +13,21 @@ import ( func (l *Logger) Middleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - l.logger.Debugf("access log middleware invoked for %s %s", r.Method, r.URL.Path) + // Generate request ID early so it can be used by error pages and log correlation. + requestID := xid.New().String() + + l.logger.Debugf("request: request_id=%s method=%s host=%s path=%s", requestID, r.Method, r.Host, r.URL.Path) + // Use a response writer wrapper so we can access the status code later. sw := &statusWriter{ w: w, - status: http.StatusOK, // Default status is OK unless otherwise modified. + status: http.StatusOK, } // Get the source IP before passing the request on as the proxy will modify // headers that we wish to use to gather that information on the request. sourceIp := extractSourceIP(r) - // Generate request ID early so it can be used by error pages. - requestID := xid.New().String() - // Create a mutable struct to capture data from downstream handlers. // We pass a pointer in the context - the pointer itself flows down immutably, // but the struct it points to can be mutated by inner handlers. @@ -57,6 +58,9 @@ func (l *Logger) Middleware(next http.Handler) http.Handler { UserId: auth.UserFromContext(r.Context()), AuthSuccess: sw.status != http.StatusUnauthorized && sw.status != http.StatusForbidden, } + l.logger.Debugf("response: request_id=%s method=%s host=%s path=%s status=%d duration=%dms source=%s origin=%s service=%s account=%s", + requestID, r.Method, host, r.URL.Path, sw.status, duration.Milliseconds(), sourceIp, capturedData.GetOrigin(), capturedData.GetServiceId(), capturedData.GetAccountId()) + l.log(r.Context(), entry) }) } diff --git a/proxy/internal/auth/middleware.go b/proxy/internal/auth/middleware.go index 917672c2d..edffc22cf 100644 --- a/proxy/internal/auth/middleware.go +++ b/proxy/internal/auth/middleware.go @@ -13,7 +13,7 @@ import ( "google.golang.org/grpc" "github.com/netbirdio/netbird/proxy/auth" - + "github.com/netbirdio/netbird/proxy/internal/proxy" "github.com/netbirdio/netbird/proxy/web" "github.com/netbirdio/netbird/shared/management/proto" ) @@ -99,7 +99,9 @@ func (mw *Middleware) Protect(next http.Handler) http.Handler { if token != "" { userid, _, err := auth.ValidateSessionJWT(token, host, config.SessionPublicKey) if err != nil { - // TODO: log, this should never fail. + if cd := proxy.CapturedDataFromContext(r.Context()); cd != nil { + cd.SetOrigin(proxy.OriginAuth) + } http.Error(w, err.Error(), http.StatusBadRequest) return } @@ -125,6 +127,9 @@ func (mw *Middleware) Protect(next http.Handler) http.Handler { methods[scheme.Type().String()] = promptData } + if cd := proxy.CapturedDataFromContext(r.Context()); cd != nil { + cd.SetOrigin(proxy.OriginAuth) + } web.ServeHTTP(w, r, map[string]any{"methods": methods}) }) } diff --git a/proxy/internal/proxy/context.go b/proxy/internal/proxy/context.go index 4131a4ae6..a60d14b0b 100644 --- a/proxy/internal/proxy/context.go +++ b/proxy/internal/proxy/context.go @@ -15,6 +15,33 @@ const ( capturedDataKey requestContextKey = "capturedData" ) +// ResponseOrigin indicates where a response was generated. +type ResponseOrigin int + +const ( + // OriginBackend means the response came from the backend service. + OriginBackend ResponseOrigin = iota + // OriginNoRoute means the proxy had no matching host or path. + OriginNoRoute + // OriginProxyError means the proxy failed to reach the backend. + OriginProxyError + // OriginAuth means the proxy intercepted the request for authentication. + OriginAuth +) + +func (o ResponseOrigin) String() string { + switch o { + case OriginNoRoute: + return "no_route" + case OriginProxyError: + return "proxy_error" + case OriginAuth: + return "auth" + default: + return "backend" + } +} + // CapturedData is a mutable struct that allows downstream handlers // to pass data back up the middleware chain. type CapturedData struct { @@ -22,6 +49,7 @@ type CapturedData struct { RequestID string ServiceId string AccountId types.AccountID + Origin ResponseOrigin } // GetRequestID safely gets the request ID @@ -59,6 +87,20 @@ func (c *CapturedData) GetAccountId() types.AccountID { return c.AccountId } +// SetOrigin safely sets the response origin +func (c *CapturedData) SetOrigin(origin ResponseOrigin) { + c.mu.Lock() + defer c.mu.Unlock() + c.Origin = origin +} + +// GetOrigin safely gets the response origin +func (c *CapturedData) GetOrigin() ResponseOrigin { + c.mu.RLock() + defer c.mu.RUnlock() + return c.Origin +} + // WithCapturedData adds a CapturedData struct to the context func WithCapturedData(ctx context.Context, data *CapturedData) context.Context { return context.WithValue(ctx, capturedDataKey, data) diff --git a/proxy/internal/proxy/reverseproxy.go b/proxy/internal/proxy/reverseproxy.go index 6dafabb9f..99954fe4c 100644 --- a/proxy/internal/proxy/reverseproxy.go +++ b/proxy/internal/proxy/reverseproxy.go @@ -48,6 +48,9 @@ func NewReverseProxy(transport http.RoundTripper, forwardedProto string, logger func (p *ReverseProxy) ServeHTTP(w http.ResponseWriter, r *http.Request) { result, exists := p.findTargetForRequest(r) if !exists { + if cd := CapturedDataFromContext(r.Context()); cd != nil { + cd.SetOrigin(OriginNoRoute) + } requestID := getRequestID(r) web.ServeErrorPage(w, r, http.StatusNotFound, "Service Not Found", "The requested service could not be found. Please check the URL, try refreshing, or check if the peer is running. If that doesn't work, see our documentation for help.", @@ -156,8 +159,15 @@ func extractForwardedPort(host, resolvedProto string) string { // proxyErrorHandler handles errors from the reverse proxy and serves // user-friendly error pages instead of raw error responses. func proxyErrorHandler(w http.ResponseWriter, r *http.Request, err error) { + if cd := CapturedDataFromContext(r.Context()); cd != nil { + cd.SetOrigin(OriginProxyError) + } requestID := getRequestID(r) title, message, code, status := classifyProxyError(err) + + log.Warnf("proxy error: request_id=%s method=%s host=%s path=%s status=%d title=%q err=%v", + requestID, r.Method, r.Host, r.URL.Path, code, title, err) + web.ServeErrorPage(w, r, code, title, message, requestID, status) } diff --git a/proxy/internal/proxy/servicemapping.go b/proxy/internal/proxy/servicemapping.go index 9b45a3c3d..4e55c8dc4 100644 --- a/proxy/internal/proxy/servicemapping.go +++ b/proxy/internal/proxy/servicemapping.go @@ -35,7 +35,6 @@ func (p *ReverseProxy) findTargetForRequest(req *http.Request) (targetResult, bo host = h } - p.logger.Debugf("looking for mapping for host: %s, path: %s", host, req.URL.Path) m, exists := p.mappings[host] if !exists { p.logger.Debugf("no mapping found for host: %s", host) diff --git a/proxy/internal/roundtrip/netbird.go b/proxy/internal/roundtrip/netbird.go index 500801a97..7b1e5e40e 100644 --- a/proxy/internal/roundtrip/netbird.go +++ b/proxy/internal/roundtrip/netbird.go @@ -363,15 +363,19 @@ func (n *NetBird) RoundTrip(req *http.Request) (*http.Response, error) { } } - n.logger.WithFields(log.Fields{ - "account_id": accountID, - "host": req.Host, - "url": req.URL.String(), - "requestURI": req.RequestURI, - "method": req.Method, - }).Debug("running roundtrip for peer connection") + start := time.Now() + resp, err := transport.RoundTrip(req) + duration := time.Since(start) - return transport.RoundTrip(req) + if err != nil { + n.logger.Debugf("roundtrip: method=%s host=%s url=%s account=%s duration=%s err=%v", + req.Method, req.Host, req.URL.String(), accountID, duration.Truncate(time.Millisecond), err) + return nil, err + } + + n.logger.Debugf("roundtrip: method=%s host=%s url=%s account=%s status=%d duration=%s", + req.Method, req.Host, req.URL.String(), accountID, resp.StatusCode, duration.Truncate(time.Millisecond)) + return resp, nil } // StopAll stops all clients.