Improve logging requests

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)
 	})
 }

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})
 	})
 }

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)

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)
 }
 

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)

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.