From aa6fafd52f2980f745fdb4bd4d3905978c3a83eb Mon Sep 17 00:00:00 2001 From: yusing Date: Sun, 6 Oct 2024 06:06:29 +0800 Subject: [PATCH] improved tracing for debug --- internal/net/http/header_utils.go | 29 ++++-- internal/net/http/middleware/forward_auth.go | 17 ++-- internal/net/http/middleware/trace.go | 38 +++++--- mtrace.json | 95 ++++++++++++++++++++ 4 files changed, 149 insertions(+), 30 deletions(-) create mode 100644 mtrace.json diff --git a/internal/net/http/header_utils.go b/internal/net/http/header_utils.go index ab73658..ffd0f22 100644 --- a/internal/net/http/header_utils.go +++ b/internal/net/http/header_utils.go @@ -2,7 +2,6 @@ package http import ( "net/http" - "slices" ) func RemoveHop(h http.Header) { @@ -25,18 +24,30 @@ func CopyHeader(dst, src http.Header) { } } -func FilterHeaders(h http.Header, allowed []string) { - if allowed == nil { - return +func FilterHeaders(h http.Header, allowed []string) http.Header { + if len(allowed) == 0 { + return h } - for i := range allowed { - allowed[i] = http.CanonicalHeaderKey(allowed[i]) + filtered := make(http.Header) + + for i, header := range allowed { + values := h.Values(header) + if len(values) == 0 { + continue + } + filtered[http.CanonicalHeaderKey(allowed[i])] = append([]string(nil), values...) } - for key := range h { - if !slices.Contains(allowed, key) { - h.Del(key) + return filtered +} + +func HeaderToMap(h http.Header) map[string]string { + result := make(map[string]string) + for k, v := range h { + if len(v) > 0 { + result[k] = v[0] // Take the first value } } + return result } diff --git a/internal/net/http/middleware/forward_auth.go b/internal/net/http/middleware/forward_auth.go index 1e88eca..98a0743 100644 --- a/internal/net/http/middleware/forward_auth.go +++ b/internal/net/http/middleware/forward_auth.go @@ -54,7 +54,7 @@ func NewForwardAuthfunc(optsRaw OptionsRaw) (*Middleware, E.NestedError) { } // TODO: use tr from reverse proxy - tr, ok := fa.forwardAuthOpts.transport.(*http.Transport) + tr, ok := fa.transport.(*http.Transport) if ok { tr = tr.Clone() } else { @@ -81,7 +81,7 @@ func (fa *forwardAuth) forward(next http.HandlerFunc, w ResponseWriter, req *Req nil, ) if err != nil { - fa.m.AddTracef("new request err to %s", fa.Address).With("error", err) + fa.m.AddTracef("new request err to %s", fa.Address).WithError(err) w.WriteHeader(http.StatusInternalServerError) return } @@ -89,12 +89,13 @@ func (fa *forwardAuth) forward(next http.HandlerFunc, w ResponseWriter, req *Req gpHTTP.CopyHeader(faReq.Header, req.Header) gpHTTP.RemoveHop(faReq.Header) - gpHTTP.FilterHeaders(faReq.Header, fa.AuthResponseHeaders) + faReq.Header = gpHTTP.FilterHeaders(faReq.Header, fa.AuthResponseHeaders) fa.setAuthHeaders(req, faReq) + fa.m.AddTraceRequest("forward auth request", faReq) faResp, err := fa.client.Do(faReq) if err != nil { - fa.m.AddTracef("failed to call %s", fa.Address).With("error", err) + fa.m.AddTracef("failed to call %s", fa.Address).WithError(err) w.WriteHeader(http.StatusInternalServerError) return } @@ -102,19 +103,19 @@ func (fa *forwardAuth) forward(next http.HandlerFunc, w ResponseWriter, req *Req body, err := io.ReadAll(faResp.Body) if err != nil { - fa.m.AddTracef("failed to read response body from %s", fa.Address).With("error", err) + fa.m.AddTracef("failed to read response body from %s", fa.Address).WithError(err) w.WriteHeader(http.StatusInternalServerError) return } if faResp.StatusCode < http.StatusOK || faResp.StatusCode >= http.StatusMultipleChoices { - fa.m.AddTracef("status %d", faResp.StatusCode) + fa.m.AddTraceResponse("forward auth response", faResp) gpHTTP.CopyHeader(w.Header(), faResp.Header) gpHTTP.RemoveHop(w.Header()) redirectURL, err := faResp.Location() if err != nil { - fa.m.AddTracef("failed to get location from %s", fa.Address).With("error", err) + fa.m.AddTracef("failed to get location from %s", fa.Address).WithError(err) w.WriteHeader(http.StatusInternalServerError) return } else if redirectURL.String() != "" { @@ -125,7 +126,7 @@ func (fa *forwardAuth) forward(next http.HandlerFunc, w ResponseWriter, req *Req w.WriteHeader(faResp.StatusCode) if _, err = w.Write(body); err != nil { - fa.m.AddTracef("failed to write response body from %s", fa.Address).With("error", err) + fa.m.AddTracef("failed to write response body from %s", fa.Address).WithError(err) } return } diff --git a/internal/net/http/middleware/trace.go b/internal/net/http/middleware/trace.go index a9520c4..593dfcb 100644 --- a/internal/net/http/middleware/trace.go +++ b/internal/net/http/middleware/trace.go @@ -2,22 +2,22 @@ package middleware import ( "fmt" - "net/http" "sync" "time" + gpHTTP "github.com/yusing/go-proxy/internal/net/http" U "github.com/yusing/go-proxy/internal/utils" ) type Trace struct { - Time string `json:"time,omitempty"` - Caller string `json:"caller,omitempty"` - URL string `json:"url,omitempty"` - Message string `json:"msg"` - ReqHeaders http.Header `json:"req_headers,omitempty"` - RespHeaders http.Header `json:"resp_headers,omitempty"` - RespStatus int `json:"resp_status,omitempty"` - Additional map[string]any `json:"additional,omitempty"` + Time string `json:"time,omitempty"` + Caller string `json:"caller,omitempty"` + URL string `json:"url,omitempty"` + Message string `json:"msg"` + ReqHeaders map[string]string `json:"req_headers,omitempty"` + RespHeaders map[string]string `json:"resp_headers,omitempty"` + RespStatus int `json:"resp_status,omitempty"` + Additional map[string]any `json:"additional,omitempty"` } type Traces []*Trace @@ -25,7 +25,7 @@ type Traces []*Trace var traces = Traces{} var tracesMu sync.Mutex -const MaxTraceNum = 1000 +const MaxTraceNum = 100 func GetAllTrace() []*Trace { return traces @@ -36,7 +36,7 @@ func (tr *Trace) WithRequest(req *Request) *Trace { return nil } tr.URL = req.RequestURI - tr.ReqHeaders = req.Header.Clone() + tr.ReqHeaders = gpHTTP.HeaderToMap(req.Header) return tr } @@ -45,8 +45,8 @@ func (tr *Trace) WithResponse(resp *Response) *Trace { return nil } tr.URL = resp.Request.RequestURI - tr.ReqHeaders = resp.Request.Header.Clone() - tr.RespHeaders = resp.Header.Clone() + tr.ReqHeaders = gpHTTP.HeaderToMap(resp.Request.Header) + tr.RespHeaders = gpHTTP.HeaderToMap(resp.Header) tr.RespStatus = resp.StatusCode return tr } @@ -63,6 +63,18 @@ func (tr *Trace) With(what string, additional any) *Trace { return tr } +func (tr *Trace) WithError(err error) *Trace { + if tr == nil { + return nil + } + + if tr.Additional == nil { + tr.Additional = map[string]any{} + } + tr.Additional["error"] = err.Error() + return tr +} + func (m *Middleware) EnableTrace() { m.trace = true for _, child := range m.children { diff --git a/mtrace.json b/mtrace.json new file mode 100644 index 0000000..c225403 --- /dev/null +++ b/mtrace.json @@ -0,0 +1,95 @@ +[ + { + "time": "2024-10-06 05:53:16", + "caller": "authentik-server", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:16", + "caller": "authentik", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:16", + "caller": "testMRInner", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:16", + "caller": "testMR", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:16", + "caller": "gp-test", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:16", + "caller": "immich-shared", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:16", + "caller": "immich", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:16", + "caller": "authentik", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:16", + "caller": "whoami", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:16", + "caller": "it-tools", + "msg": "middleware created" + }, + { + "time": "2024-10-06 05:53:21", + "caller": "whoami.authentik.authentik[0]", + "msg": "forward auth request", + "req_headers": { + "X-Forwarded-For": "10.0.1.2", + "X-Forwarded-Host": "whoami.i.sh", + "X-Forwarded-Method": "GET", + "X-Forwarded-Proto": "https", + "X-Forwarded-Uri": "/" + } + }, + { + "time": "2024-10-06 05:53:21", + "caller": "whoami.authentik.authentik[0]", + "msg": "forward auth response", + "req_headers": { + "X-Forwarded-For": "10.0.1.2", + "X-Forwarded-Host": "whoami.i.sh", + "X-Forwarded-Method": "GET", + "X-Forwarded-Proto": "https", + "X-Forwarded-Uri": "/" + }, + "resp_headers": { + "Content-Type": "text/html; charset=utf-8", + "Date": "Sat, 05 Oct 2024 21:53:21 GMT", + "Referrer-Policy": "same-origin", + "Vary": "Accept-Encoding", + "X-Authentik-Id": "22e0c95971dc4c1b8033725c6988abc9", + "X-Content-Type-Options": "nosniff", + "X-Frame-Options": "DENY", + "X-Powered-By": "authentik" + }, + "resp_status": 404 + }, + { + "time": "2024-10-06 05:53:21", + "caller": "whoami.authentik.authentik[0]", + "msg": "failed to get location from https://authentik.i.sh/outpost.goauthentik.io/auth/traefik", + "additional": { + "error": "http: no Location header in response" + } + } +]