diff options
author | Kévin Dunglas <[email protected]> | 2024-09-13 19:16:37 +0200 |
---|---|---|
committer | GitHub <[email protected]> | 2024-09-13 11:16:37 -0600 |
commit | f4bf4e0097853438eb69c573bbaa0581e9b9c02d (patch) | |
tree | 2c01222faa34d3c95072094a2f80c41b1563c19e /modules/caddyhttp | |
parent | 21f9c20a04ec5c2ac430daa8e4ba8fbdef67f773 (diff) | |
download | caddy-f4bf4e0097853438eb69c573bbaa0581e9b9c02d.tar.gz caddy-f4bf4e0097853438eb69c573bbaa0581e9b9c02d.zip |
perf: use zap's Check() to prevent useless allocs (#6560)
* perf: use zap's Check() to prevent useless allocs
* fix
* fix
* fix
* fix
* restore previous replacer behavior
* fix linter
Diffstat (limited to 'modules/caddyhttp')
22 files changed, 516 insertions, 247 deletions
diff --git a/modules/caddyhttp/caddyauth/caddyauth.go b/modules/caddyhttp/caddyauth/caddyauth.go index c60de880b..f799d7a0c 100644 --- a/modules/caddyhttp/caddyauth/caddyauth.go +++ b/modules/caddyhttp/caddyauth/caddyauth.go @@ -19,6 +19,7 @@ import ( "net/http" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/modules/caddyhttp" @@ -76,9 +77,9 @@ func (a Authentication) ServeHTTP(w http.ResponseWriter, r *http.Request, next c for provName, prov := range a.Providers { user, authed, err = prov.Authenticate(w, r) if err != nil { - a.logger.Error("auth provider returned error", - zap.String("provider", provName), - zap.Error(err)) + if c := a.logger.Check(zapcore.ErrorLevel, "auth provider returned error"); c != nil { + c.Write(zap.String("provider", provName), zap.Error(err)) + } continue } if authed { diff --git a/modules/caddyhttp/fileserver/browse.go b/modules/caddyhttp/fileserver/browse.go index f5cc16b42..a19b4e17a 100644 --- a/modules/caddyhttp/fileserver/browse.go +++ b/modules/caddyhttp/fileserver/browse.go @@ -33,6 +33,7 @@ import ( "time" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/modules/caddyhttp" @@ -68,9 +69,9 @@ type Browse struct { } func (fsrv *FileServer) serveBrowse(fileSystem fs.FS, root, dirPath string, w http.ResponseWriter, r *http.Request, next caddyhttp.Handler) error { - fsrv.logger.Debug("browse enabled; listing directory contents", - zap.String("path", dirPath), - zap.String("root", root)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "browse enabled; listing directory contents"); c != nil { + c.Write(zap.String("path", dirPath), zap.String("root", root)) + } // Navigation on the client-side gets messed up if the // URL doesn't end in a trailing slash because hrefs to @@ -92,7 +93,9 @@ func (fsrv *FileServer) serveBrowse(fileSystem fs.FS, root, dirPath string, w ht origReq := r.Context().Value(caddyhttp.OriginalRequestCtxKey).(http.Request) if r.URL.Path == "" || path.Base(origReq.URL.Path) == path.Base(r.URL.Path) { if !strings.HasSuffix(origReq.URL.Path, "/") { - fsrv.logger.Debug("redirecting to trailing slash to preserve hrefs", zap.String("request_path", r.URL.Path)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "redirecting to trailing slash to preserve hrefs"); c != nil { + c.Write(zap.String("request_path", r.URL.Path)) + } return redirect(w, r, origReq.URL.Path+"/") } } diff --git a/modules/caddyhttp/fileserver/browsetplcontext.go b/modules/caddyhttp/fileserver/browsetplcontext.go index 0251bc581..37e1cc3dd 100644 --- a/modules/caddyhttp/fileserver/browsetplcontext.go +++ b/modules/caddyhttp/fileserver/browsetplcontext.go @@ -28,6 +28,7 @@ import ( "github.com/dustin/go-humanize" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/modules/caddyhttp" @@ -57,9 +58,9 @@ func (fsrv *FileServer) directoryListing(ctx context.Context, fileSystem fs.FS, info, err := entry.Info() if err != nil { - fsrv.logger.Error("could not get info about directory entry", - zap.String("name", entry.Name()), - zap.String("root", root)) + if c := fsrv.logger.Check(zapcore.ErrorLevel, "could not get info about directory entry"); c != nil { + c.Write(zap.String("name", entry.Name()), zap.String("root", root)) + } continue } diff --git a/modules/caddyhttp/fileserver/matcher.go b/modules/caddyhttp/fileserver/matcher.go index c315b8e38..6ab2180ad 100644 --- a/modules/caddyhttp/fileserver/matcher.go +++ b/modules/caddyhttp/fileserver/matcher.go @@ -33,6 +33,7 @@ import ( "github.com/google/cel-go/common/types/ref" "github.com/google/cel-go/parser" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/caddyconfig/caddyfile" @@ -326,7 +327,9 @@ func (m MatchFile) selectFile(r *http.Request) (matched bool) { fileSystem, ok := m.fsmap.Get(fsName) if !ok { - m.logger.Error("use of unregistered filesystem", zap.String("fs", fsName)) + if c := m.logger.Check(zapcore.ErrorLevel, "use of unregistered filesystem"); c != nil { + c.Write(zap.String("fs", fsName)) + } return false } type matchCandidate struct { @@ -356,7 +359,10 @@ func (m MatchFile) selectFile(r *http.Request) (matched bool) { return val, nil }) if err != nil { - m.logger.Error("evaluating placeholders", zap.Error(err)) + if c := m.logger.Check(zapcore.ErrorLevel, "evaluating placeholders"); c != nil { + c.Write(zap.Error(err)) + } + expandedFile = file // "oh well," I guess? } @@ -379,7 +385,9 @@ func (m MatchFile) selectFile(r *http.Request) (matched bool) { } else { globResults, err = fs.Glob(fileSystem, fullPattern) if err != nil { - m.logger.Error("expanding glob", zap.Error(err)) + if c := m.logger.Check(zapcore.ErrorLevel, "expanding glob"); c != nil { + c.Write(zap.Error(err)) + } } } diff --git a/modules/caddyhttp/fileserver/staticfiles.go b/modules/caddyhttp/fileserver/staticfiles.go index 2dd237ae7..4ae69b647 100644 --- a/modules/caddyhttp/fileserver/staticfiles.go +++ b/modules/caddyhttp/fileserver/staticfiles.go @@ -31,6 +31,7 @@ import ( "strings" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/modules/caddyhttp" @@ -286,11 +287,14 @@ func (fsrv *FileServer) ServeHTTP(w http.ResponseWriter, r *http.Request, next c // remove any trailing `/` as it breaks fs.ValidPath() in the stdlib filename := strings.TrimSuffix(caddyhttp.SanitizedPathJoin(root, r.URL.Path), "/") - fsrv.logger.Debug("sanitized path join", - zap.String("site_root", root), - zap.String("fs", fsName), - zap.String("request_path", r.URL.Path), - zap.String("result", filename)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "sanitized path join"); c != nil { + c.Write( + zap.String("site_root", root), + zap.String("fs", fsName), + zap.String("request_path", r.URL.Path), + zap.String("result", filename), + ) + } // get information about the file info, err := fs.Stat(fileSystem, filename) @@ -313,9 +317,12 @@ func (fsrv *FileServer) ServeHTTP(w http.ResponseWriter, r *http.Request, next c indexPath := caddyhttp.SanitizedPathJoin(filename, indexPage) if fileHidden(indexPath, filesToHide) { // pretend this file doesn't exist - fsrv.logger.Debug("hiding index file", - zap.String("filename", indexPath), - zap.Strings("files_to_hide", filesToHide)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "hiding index file"); c != nil { + c.Write( + zap.String("filename", indexPath), + zap.Strings("files_to_hide", filesToHide), + ) + } continue } @@ -335,7 +342,9 @@ func (fsrv *FileServer) ServeHTTP(w http.ResponseWriter, r *http.Request, next c info = indexInfo filename = indexPath implicitIndexFile = true - fsrv.logger.Debug("located index file", zap.String("filename", filename)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "located index file"); c != nil { + c.Write(zap.String("filename", filename)) + } break } } @@ -343,9 +352,12 @@ func (fsrv *FileServer) ServeHTTP(w http.ResponseWriter, r *http.Request, next c // if still referencing a directory, delegate // to browse or return an error if info.IsDir() { - fsrv.logger.Debug("no index file in directory", - zap.String("path", filename), - zap.Strings("index_filenames", fsrv.IndexNames)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "no index file in directory"); c != nil { + c.Write( + zap.String("path", filename), + zap.Strings("index_filenames", fsrv.IndexNames), + ) + } if fsrv.Browse != nil && !fileHidden(filename, filesToHide) { return fsrv.serveBrowse(fileSystem, root, filename, w, r, next) } @@ -355,9 +367,12 @@ func (fsrv *FileServer) ServeHTTP(w http.ResponseWriter, r *http.Request, next c // one last check to ensure the file isn't hidden (we might // have changed the filename from when we last checked) if fileHidden(filename, filesToHide) { - fsrv.logger.Debug("hiding file", - zap.String("filename", filename), - zap.Strings("files_to_hide", filesToHide)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "hiding file"); c != nil { + c.Write( + zap.String("filename", filename), + zap.Strings("files_to_hide", filesToHide), + ) + } return fsrv.notFound(w, r, next) } @@ -375,15 +390,21 @@ func (fsrv *FileServer) ServeHTTP(w http.ResponseWriter, r *http.Request, next c if path.Base(origReq.URL.Path) == path.Base(r.URL.Path) { if implicitIndexFile && !strings.HasSuffix(origReq.URL.Path, "/") { to := origReq.URL.Path + "/" - fsrv.logger.Debug("redirecting to canonical URI (adding trailing slash for directory)", - zap.String("from_path", origReq.URL.Path), - zap.String("to_path", to)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "redirecting to canonical URI (adding trailing slash for directory"); c != nil { + c.Write( + zap.String("from_path", origReq.URL.Path), + zap.String("to_path", to), + ) + } return redirect(w, r, to) } else if !implicitIndexFile && strings.HasSuffix(origReq.URL.Path, "/") { to := origReq.URL.Path[:len(origReq.URL.Path)-1] - fsrv.logger.Debug("redirecting to canonical URI (removing trailing slash for file)", - zap.String("from_path", origReq.URL.Path), - zap.String("to_path", to)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "redirecting to canonical URI (removing trailing slash for file"); c != nil { + c.Write( + zap.String("from_path", origReq.URL.Path), + zap.String("to_path", to), + ) + } return redirect(w, r, to) } } @@ -411,13 +432,19 @@ func (fsrv *FileServer) ServeHTTP(w http.ResponseWriter, r *http.Request, next c compressedFilename := filename + precompress.Suffix() compressedInfo, err := fs.Stat(fileSystem, compressedFilename) if err != nil || compressedInfo.IsDir() { - fsrv.logger.Debug("precompressed file not accessible", zap.String("filename", compressedFilename), zap.Error(err)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "precompressed file not accessible"); c != nil { + c.Write(zap.String("filename", compressedFilename), zap.Error(err)) + } continue } - fsrv.logger.Debug("opening compressed sidecar file", zap.String("filename", compressedFilename), zap.Error(err)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "opening compressed sidecar file"); c != nil { + c.Write(zap.String("filename", compressedFilename), zap.Error(err)) + } file, err = fsrv.openFile(fileSystem, compressedFilename, w) if err != nil { - fsrv.logger.Warn("opening precompressed file failed", zap.String("filename", compressedFilename), zap.Error(err)) + if c := fsrv.logger.Check(zapcore.WarnLevel, "opening precompressed file failed"); c != nil { + c.Write(zap.String("filename", compressedFilename), zap.Error(err)) + } if caddyErr, ok := err.(caddyhttp.HandlerError); ok && caddyErr.StatusCode == http.StatusServiceUnavailable { return err } @@ -448,7 +475,9 @@ func (fsrv *FileServer) ServeHTTP(w http.ResponseWriter, r *http.Request, next c // no precompressed file found, use the actual file if file == nil { - fsrv.logger.Debug("opening file", zap.String("filename", filename)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "opening file"); c != nil { + c.Write(zap.String("filename", filename)) + } // open the file file, err = fsrv.openFile(fileSystem, filename, w) @@ -548,10 +577,14 @@ func (fsrv *FileServer) openFile(fileSystem fs.FS, filename string, w http.Respo if err != nil { err = fsrv.mapDirOpenError(fileSystem, err, filename) if errors.Is(err, fs.ErrNotExist) { - fsrv.logger.Debug("file not found", zap.String("filename", filename), zap.Error(err)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "file not found"); c != nil { + c.Write(zap.String("filename", filename), zap.Error(err)) + } return nil, caddyhttp.Error(http.StatusNotFound, err) } else if errors.Is(err, fs.ErrPermission) { - fsrv.logger.Debug("permission denied", zap.String("filename", filename), zap.Error(err)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "permission denied"); c != nil { + c.Write(zap.String("filename", filename), zap.Error(err)) + } return nil, caddyhttp.Error(http.StatusForbidden, err) } // maybe the server is under load and ran out of file descriptors? @@ -559,7 +592,9 @@ func (fsrv *FileServer) openFile(fileSystem fs.FS, filename string, w http.Respo //nolint:gosec backoff := weakrand.Intn(maxBackoff-minBackoff) + minBackoff w.Header().Set("Retry-After", strconv.Itoa(backoff)) - fsrv.logger.Debug("retry after backoff", zap.String("filename", filename), zap.Int("backoff", backoff), zap.Error(err)) + if c := fsrv.logger.Check(zapcore.DebugLevel, "retry after backoff"); c != nil { + c.Write(zap.String("filename", filename), zap.Int("backoff", backoff), zap.Error(err)) + } return nil, caddyhttp.Error(http.StatusServiceUnavailable, err) } return file, nil diff --git a/modules/caddyhttp/intercept/intercept.go b/modules/caddyhttp/intercept/intercept.go index 720a09333..29889dcc0 100644 --- a/modules/caddyhttp/intercept/intercept.go +++ b/modules/caddyhttp/intercept/intercept.go @@ -23,6 +23,7 @@ import ( "sync" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/caddyconfig/caddyfile" @@ -165,7 +166,9 @@ func (ir Intercept) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddy } repl.Set("http.intercept.status_code", rec.Status()) - ir.logger.Debug("handling response", zap.Int("handler", rec.handlerIndex)) + if c := ir.logger.Check(zapcore.DebugLevel, "handling response"); c != nil { + c.Write(zap.Int("handler", rec.handlerIndex)) + } // pass the request through the response handler routes return rec.handler.Routes.Compile(next).ServeHTTP(w, r) diff --git a/modules/caddyhttp/ip_matchers.go b/modules/caddyhttp/ip_matchers.go index 2e735cb69..99eb39dff 100644 --- a/modules/caddyhttp/ip_matchers.go +++ b/modules/caddyhttp/ip_matchers.go @@ -26,6 +26,7 @@ import ( "github.com/google/cel-go/cel" "github.com/google/cel-go/common/types/ref" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/caddyconfig/caddyfile" @@ -150,12 +151,17 @@ func (m MatchRemoteIP) Match(r *http.Request) bool { address := r.RemoteAddr clientIP, zoneID, err := parseIPZoneFromString(address) if err != nil { - m.logger.Error("getting remote IP", zap.Error(err)) + if c := m.logger.Check(zapcore.ErrorLevel, "getting remote "); c != nil { + c.Write(zap.Error(err)) + } + return false } matches, zoneFilter := matchIPByCidrZones(clientIP, zoneID, m.cidrs, m.zones) if !matches && !zoneFilter { - m.logger.Debug("zone ID from remote IP did not match", zap.String("zone", zoneID)) + if c := m.logger.Check(zapcore.DebugLevel, "zone ID from remote IP did not match"); c != nil { + c.Write(zap.String("zone", zoneID)) + } } return matches } diff --git a/modules/caddyhttp/logging.go b/modules/caddyhttp/logging.go index 823763e91..0a389fe16 100644 --- a/modules/caddyhttp/logging.go +++ b/modules/caddyhttp/logging.go @@ -193,7 +193,7 @@ func (sa *StringArray) UnmarshalJSON(b []byte) error { // to use, the error log message, and any extra fields. // If err is a HandlerError, the returned values will // have richer information. -func errLogValues(err error) (status int, msg string, fields []zapcore.Field) { +func errLogValues(err error) (status int, msg string, fields func() []zapcore.Field) { var handlerErr HandlerError if errors.As(err, &handlerErr) { status = handlerErr.StatusCode @@ -202,10 +202,12 @@ func errLogValues(err error) (status int, msg string, fields []zapcore.Field) { } else { msg = handlerErr.Err.Error() } - fields = []zapcore.Field{ - zap.Int("status", handlerErr.StatusCode), - zap.String("err_id", handlerErr.ID), - zap.String("err_trace", handlerErr.Trace), + fields = func() []zapcore.Field { + return []zapcore.Field{ + zap.Int("status", handlerErr.StatusCode), + zap.String("err_id", handlerErr.ID), + zap.String("err_trace", handlerErr.Trace), + } } return } diff --git a/modules/caddyhttp/push/handler.go b/modules/caddyhttp/push/handler.go index 031a8991f..1fbe53d83 100644 --- a/modules/caddyhttp/push/handler.go +++ b/modules/caddyhttp/push/handler.go @@ -20,6 +20,7 @@ import ( "strings" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/modules/caddyhttp" @@ -92,14 +93,17 @@ func (h Handler) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddyhtt // push first! for _, resource := range h.Resources { - h.logger.Debug("pushing resource", - zap.String("uri", r.RequestURI), - zap.String("push_method", resource.Method), - zap.String("push_target", resource.Target), - zap.Object("push_headers", caddyhttp.LoggableHTTPHeader{ - Header: hdr, - ShouldLogCredentials: shouldLogCredentials, - })) + if c := h.logger.Check(zapcore.DebugLevel, "pushing resource"); c != nil { + c.Write( + zap.String("uri", r.RequestURI), + zap.String("push_method", resource.Method), + zap.String("push_target", resource.Target), + zap.Object("push_headers", caddyhttp.LoggableHTTPHeader{ + Header: hdr, + ShouldLogCredentials: shouldLogCredentials, + }), + ) + } err := pusher.Push(repl.ReplaceAll(resource.Target, "."), &http.PushOptions{ Method: resource.Method, Header: hdr, @@ -209,7 +213,9 @@ func (lp linkPusher) WriteHeader(statusCode int) { if links, ok := lp.ResponseWriter.Header()["Link"]; ok { // only initiate these pushes if it hasn't been done yet if val := caddyhttp.GetVar(lp.request.Context(), pushedLink); val == nil { - lp.handler.logger.Debug("pushing Link resources", zap.Strings("linked", links)) + if c := lp.handler.logger.Check(zapcore.DebugLevel, "pushing Link resources"); c != nil { + c.Write(zap.Strings("linked", links)) + } caddyhttp.SetVar(lp.request.Context(), pushedLink, true) lp.handler.servePreloadLinks(lp.pusher, lp.header, links) } diff --git a/modules/caddyhttp/requestbody/requestbody.go b/modules/caddyhttp/requestbody/requestbody.go index d00455a8c..1c804aa13 100644 --- a/modules/caddyhttp/requestbody/requestbody.go +++ b/modules/caddyhttp/requestbody/requestbody.go @@ -20,6 +20,7 @@ import ( "time" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/modules/caddyhttp" @@ -69,12 +70,16 @@ func (rb RequestBody) ServeHTTP(w http.ResponseWriter, r *http.Request, next cad rc := http.NewResponseController(w) if rb.ReadTimeout > 0 { if err := rc.SetReadDeadline(time.Now().Add(rb.ReadTimeout)); err != nil { - rb.logger.Error("could not set read deadline", zap.Error(err)) + if c := rb.logger.Check(zapcore.ErrorLevel, "could not set read deadline"); c != nil { + c.Write(zap.Error(err)) + } } } if rb.WriteTimeout > 0 { if err := rc.SetWriteDeadline(time.Now().Add(rb.WriteTimeout)); err != nil { - rb.logger.Error("could not set write deadline", zap.Error(err)) + if c := rb.logger.Check(zapcore.ErrorLevel, "could not set write deadline"); c != nil { + c.Write(zap.Error(err)) + } } } } diff --git a/modules/caddyhttp/reverseproxy/fastcgi/client.go b/modules/caddyhttp/reverseproxy/fastcgi/client.go index d944c5778..7284fe672 100644 --- a/modules/caddyhttp/reverseproxy/fastcgi/client.go +++ b/modules/caddyhttp/reverseproxy/fastcgi/client.go @@ -40,6 +40,7 @@ import ( "time" "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) // FCGIListenSockFileno describes listen socket file number. @@ -184,10 +185,13 @@ func (f clientCloser) Close() error { return f.rwc.Close() } + logLevel := zapcore.WarnLevel if f.status >= 400 { - f.logger.Error("stderr", zap.ByteString("body", stderr)) - } else { - f.logger.Warn("stderr", zap.ByteString("body", stderr)) + logLevel = zapcore.ErrorLevel + } + + if c := f.logger.Check(logLevel, "stderr"); c != nil { + c.Write(zap.ByteString("body", stderr)) } return f.rwc.Close() diff --git a/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go b/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go index 31febdd4e..3985465ba 100644 --- a/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go +++ b/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go @@ -148,10 +148,13 @@ func (t Transport) RoundTrip(r *http.Request) (*http.Response, error) { zap.Object("request", loggableReq), zap.Object("env", loggableEnv), ) - logger.Debug("roundtrip", - zap.String("dial", address), - zap.Object("env", loggableEnv), - zap.Object("request", loggableReq)) + if c := t.logger.Check(zapcore.DebugLevel, "roundtrip"); c != nil { + c.Write( + zap.String("dial", address), + zap.Object("env", loggableEnv), + zap.Object("request", loggableReq), + ) + } // connect to the backend dialer := net.Dialer{Timeout: time.Duration(t.DialTimeout)} diff --git a/modules/caddyhttp/reverseproxy/healthchecks.go b/modules/caddyhttp/reverseproxy/healthchecks.go index efa1dbf09..179805f20 100644 --- a/modules/caddyhttp/reverseproxy/healthchecks.go +++ b/modules/caddyhttp/reverseproxy/healthchecks.go @@ -28,6 +28,7 @@ import ( "time" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/modules/caddyhttp" @@ -270,9 +271,12 @@ type CircuitBreaker interface { func (h *Handler) activeHealthChecker() { defer func() { if err := recover(); err != nil { - h.HealthChecks.Active.logger.Error("active health checker panicked", - zap.Any("error", err), - zap.ByteString("stack", debug.Stack())) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "active health checker panicked"); c != nil { + c.Write( + zap.Any("error", err), + zap.ByteString("stack", debug.Stack()), + ) + } } }() ticker := time.NewTicker(time.Duration(h.HealthChecks.Active.Interval)) @@ -295,26 +299,33 @@ func (h *Handler) doActiveHealthCheckForAllHosts() { go func(upstream *Upstream) { defer func() { if err := recover(); err != nil { - h.HealthChecks.Active.logger.Error("active health check panicked", - zap.Any("error", err), - zap.ByteString("stack", debug.Stack())) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "active health checker panicked"); c != nil { + c.Write( + zap.Any("error", err), + zap.ByteString("stack", debug.Stack()), + ) + } } }() networkAddr, err := caddy.NewReplacer().ReplaceOrErr(upstream.Dial, true, true) if err != nil { - h.HealthChecks.Active.logger.Error("invalid use of placeholders in dial address for active health checks", - zap.String("address", networkAddr), - zap.Error(err), - ) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "invalid use of placeholders in dial address for active health checks"); c != nil { + c.Write( + zap.String("address", networkAddr), + zap.Error(err), + ) + } return } addr, err := caddy.ParseNetworkAddress(networkAddr) if err != nil { - h.HealthChecks.Active.logger.Error("bad network address", - zap.String("address", networkAddr), - zap.Error(err), - ) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "bad network address"); c != nil { + c.Write( + zap.String("address", networkAddr), + zap.Error(err), + ) + } return } if hcp := uint(upstream.activeHealthCheckPort); hcp != 0 { @@ -324,9 +335,11 @@ func (h *Handler) doActiveHealthCheckForAllHosts() { addr.StartPort, addr.EndPort = hcp, hcp } if addr.PortRangeSize() != 1 { - h.HealthChecks.Active.logger.Error("multiple addresses (upstream must map to only one address)", - zap.String("address", networkAddr), - ) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "multiple addresses (upstream must map to only one address)"); c != nil { + c.Write( + zap.String("address", networkAddr), + ) + } return } hostAddr := addr.JoinHostPort(0) @@ -339,10 +352,12 @@ func (h *Handler) doActiveHealthCheckForAllHosts() { } err = h.doActiveHealthCheck(DialInfo{Network: addr.Network, Address: dialAddr}, hostAddr, networkAddr, upstream) if err != nil { - h.HealthChecks.Active.logger.Error("active health check failed", - zap.String("address", hostAddr), - zap.Error(err), - ) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "active health check failed"); c != nil { + c.Write( + zap.String("address", hostAddr), + zap.Error(err), + ) + } } }(upstream) } @@ -441,9 +456,12 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, networ // increment failures and then check if it has reached the threshold to mark unhealthy err := upstream.Host.countHealthFail(1) if err != nil { - h.HealthChecks.Active.logger.Error("could not count active health failure", - zap.String("host", upstream.Dial), - zap.Error(err)) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "could not count active health failure"); c != nil { + c.Write( + zap.String("host", upstream.Dial), + zap.Error(err), + ) + } return } if upstream.Host.activeHealthFails() >= h.HealthChecks.Active.Fails { @@ -459,14 +477,19 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, networ // increment passes and then check if it has reached the threshold to be healthy err := upstream.Host.countHealthPass(1) if err != nil { - h.HealthChecks.Active.logger.Error("could not count active health pass", - zap.String("host", upstream.Dial), - zap.Error(err)) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "could not count active health pass"); c != nil { + c.Write( + zap.String("host", upstream.Dial), + zap.Error(err), + ) + } return } if upstream.Host.activeHealthPasses() >= h.HealthChecks.Active.Passes { if upstream.setHealthy(true) { - h.HealthChecks.Active.logger.Info("host is up", zap.String("host", hostAddr)) + if c := h.HealthChecks.Active.logger.Check(zapcore.InfoLevel, "host is up"); c != nil { + c.Write(zap.String("host", hostAddr)) + } h.events.Emit(h.ctx, "healthy", map[string]any{"host": hostAddr}) upstream.Host.resetHealth() } @@ -476,10 +499,12 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, networ // do the request, being careful to tame the response body resp, err := h.HealthChecks.Active.httpClient.Do(req) if err != nil { - h.HealthChecks.Active.logger.Info("HTTP request failed", - zap.String("host", hostAddr), - zap.Error(err), - ) + if c := h.HealthChecks.Active.logger.Check(zapcore.InfoLevel, "HTTP request failed"); c != nil { + c.Write( + zap.String("host", hostAddr), + zap.Error(err), + ) + } markUnhealthy() return nil } @@ -496,18 +521,22 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, networ // if status code is outside criteria, mark down if h.HealthChecks.Active.ExpectStatus > 0 { if !caddyhttp.StatusCodeMatches(resp.StatusCode, h.HealthChecks.Active.ExpectStatus) { - h.HealthChecks.Active.logger.Info("unexpected status code", - zap.Int("status_code", resp.StatusCode), - zap.String("host", hostAddr), - ) + if c := h.HealthChecks.Active.logger.Check(zapcore.InfoLevel, "unexpected status code"); c != nil { + c.Write( + zap.Int("status_code", resp.StatusCode), + zap.String("host", hostAddr), + ) + } markUnhealthy() return nil } } else if resp.StatusCode < 200 || resp.StatusCode >= 300 { - h.HealthChecks.Active.logger.Info("status code out of tolerances", - zap.Int("status_code", resp.StatusCode), - zap.String("host", hostAddr), - ) + if c := h.HealthChecks.Active.logger.Check(zapcore.InfoLevel, "status code out of tolerances"); c != nil { + c.Write( + zap.Int("status_code", resp.StatusCode), + zap.String("host", hostAddr), + ) + } markUnhealthy() return nil } @@ -516,17 +545,21 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, networ if h.HealthChecks.Active.bodyRegexp != nil { bodyBytes, err := io.ReadAll(body) if err != nil { - h.HealthChecks.Active.logger.Info("failed to read response body", - zap.String("host", hostAddr), - zap.Error(err), - ) + if c := h.HealthChecks.Active.logger.Check(zapcore.InfoLevel, "failed to read response body"); c != nil { + c.Write( + zap.String("host", hostAddr), + zap.Error(err), + ) + } markUnhealthy() return nil } if !h.HealthChecks.Active.bodyRegexp.Match(bodyBytes) { - h.HealthChecks.Active.logger.Info("response body failed expectations", - zap.String("host", hostAddr), - ) + if c := h.HealthChecks.Active.logger.Check(zapcore.InfoLevel, "response body failed expectations"); c != nil { + c.Write( + zap.String("host", hostAddr), + ) + } markUnhealthy() return nil } @@ -556,9 +589,12 @@ func (h *Handler) countFailure(upstream *Upstream) { // count failure immediately err := upstream.Host.countFail(1) if err != nil { - h.HealthChecks.Passive.logger.Error("could not count failure", - zap.String("host", upstream.Dial), - zap.Error(err)) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "could not count failure"); c != nil { + c.Write( + zap.String("host", upstream.Dial), + zap.Error(err), + ) + } return } @@ -566,9 +602,12 @@ func (h *Handler) countFailure(upstream *Upstream) { go func(host *Host, failDuration time.Duration) { defer func() { if err := recover(); err != nil { - h.HealthChecks.Passive.logger.Error("passive health check failure forgetter panicked", - zap.Any("error", err), - zap.ByteString("stack", debug.Stack())) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "passive health check failure forgetter panicked"); c != nil { + c.Write( + zap.Any("error", err), + zap.ByteString("stack", debug.Stack()), + ) + } } }() timer := time.NewTimer(failDuration) @@ -581,9 +620,12 @@ func (h *Handler) countFailure(upstream *Upstream) { } err := host.countFail(-1) if err != nil { - h.HealthChecks.Passive.logger.Error("could not forget failure", - zap.String("host", upstream.Dial), - zap.Error(err)) + if c := h.HealthChecks.Active.logger.Check(zapcore.ErrorLevel, "could not forget failure"); c != nil { + c.Write( + zap.String("host", upstream.Dial), + zap.Error(err), + ) + } } }(upstream.Host, failDuration) } diff --git a/modules/caddyhttp/reverseproxy/httptransport.go b/modules/caddyhttp/reverseproxy/httptransport.go index 9929ae5d1..144960cf9 100644 --- a/modules/caddyhttp/reverseproxy/httptransport.go +++ b/modules/caddyhttp/reverseproxy/httptransport.go @@ -33,6 +33,7 @@ import ( "github.com/pires/go-proxyproto" "github.com/quic-go/quic-go/http3" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "golang.org/x/net/http2" "github.com/caddyserver/caddy/v2" @@ -750,7 +751,9 @@ func (c *tcpRWTimeoutConn) Read(b []byte) (int, error) { if c.readTimeout > 0 { err := c.TCPConn.SetReadDeadline(time.Now().Add(c.readTimeout)) if err != nil { - c.logger.Error("failed to set read deadline", zap.Error(err)) + if ce := c.logger.Check(zapcore.ErrorLevel, "failed to set read deadline"); ce != nil { + ce.Write(zap.Error(err)) + } } } return c.TCPConn.Read(b) @@ -760,7 +763,9 @@ func (c *tcpRWTimeoutConn) Write(b []byte) (int, error) { if c.writeTimeout > 0 { err := c.TCPConn.SetWriteDeadline(time.Now().Add(c.writeTimeout)) if err != nil { - c.logger.Error("failed to set write deadline", zap.Error(err)) + if ce := c.logger.Check(zapcore.ErrorLevel, "failed to set write deadline"); ce != nil { + ce.Write(zap.Error(err)) + } } } return c.TCPConn.Write(b) diff --git a/modules/caddyhttp/reverseproxy/metrics.go b/modules/caddyhttp/reverseproxy/metrics.go index d3c8ee03e..f744756d3 100644 --- a/modules/caddyhttp/reverseproxy/metrics.go +++ b/modules/caddyhttp/reverseproxy/metrics.go @@ -8,6 +8,7 @@ import ( "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promauto" "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) var reverseProxyMetrics = struct { @@ -48,9 +49,12 @@ func (m *metricsUpstreamsHealthyUpdater) Init() { go func() { defer func() { if err := recover(); err != nil { - reverseProxyMetrics.logger.Error("upstreams healthy metrics updater panicked", - zap.Any("error", err), - zap.ByteString("stack", debug.Stack())) + if c := reverseProxyMetrics.logger.Check(zapcore.ErrorLevel, "upstreams healthy metrics updater panicked"); c != nil { + c.Write( + zap.Any("error", err), + zap.ByteString("stack", debug.Stack()), + ) + } } }() diff --git a/modules/caddyhttp/reverseproxy/reverseproxy.go b/modules/caddyhttp/reverseproxy/reverseproxy.go index 44cc2f9d9..bcbc1ff46 100644 --- a/modules/caddyhttp/reverseproxy/reverseproxy.go +++ b/modules/caddyhttp/reverseproxy/reverseproxy.go @@ -33,6 +33,7 @@ import ( "time" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "golang.org/x/net/http/httpguts" "github.com/caddyserver/caddy/v2" @@ -439,7 +440,9 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddyht if h.LoadBalancing != nil { lbWait = time.Duration(h.LoadBalancing.TryInterval) } - h.logger.Debug("retrying", zap.Error(proxyErr), zap.Duration("after", lbWait)) + if c := h.logger.Check(zapcore.DebugLevel, "retrying"); c != nil { + c.Write(zap.Error(proxyErr), zap.Duration("after", lbWait)) + } } retries++ } @@ -466,13 +469,17 @@ func (h *Handler) proxyLoopIteration(r *http.Request, origReq *http.Request, w h if h.DynamicUpstreams != nil { dUpstreams, err := h.DynamicUpstreams.GetUpstreams(r) if err != nil { - h.logger.Error("failed getting dynamic upstreams; falling back to static upstreams", zap.Error(err)) + if c := h.logger.Check(zapcore.ErrorLevel, "failed getting dynamic upstreams; falling back to static upstreams"); c != nil { + c.Write(zap.Error(err)) + } } else { upstreams = dUpstreams for _, dUp := range dUpstreams { h.provisionUpstream(dUp) } - h.logger.Debug("provisioned dynamic upstreams", zap.Int("count", len(dUpstreams))) + if c := h.logger.Check(zapcore.DebugLevel, "provisioned dynamic upstreams"); c != nil { + c.Write(zap.Int("count", len(dUpstreams))) + } defer func() { // these upstreams are dynamic, so they are only used for this iteration // of the proxy loop; be sure to let them go away when we're done with them @@ -503,9 +510,12 @@ func (h *Handler) proxyLoopIteration(r *http.Request, origReq *http.Request, w h return true, fmt.Errorf("making dial info: %v", err) } - h.logger.Debug("selected upstream", - zap.String("dial", dialInfo.Address), - zap.Int("total_upstreams", len(upstreams))) + if c := h.logger.Check(zapcore.DebugLevel, "selected upstream"); c != nil { + c.Write( + zap.String("dial", dialInfo.Address), + zap.Int("total_upstreams", len(upstreams)), + ) + } // attach to the request information about how to dial the upstream; // this is necessary because the information cannot be sufficiently @@ -811,16 +821,22 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, origRe ShouldLogCredentials: shouldLogCredentials, }), ) + if err != nil { - logger.Debug("upstream roundtrip", zap.Error(err)) + if c := logger.Check(zapcore.DebugLevel, "upstream roundtrip"); c != nil { + c.Write(zap.Error(err)) + } return err } - logger.Debug("upstream roundtrip", - zap.Object("headers", caddyhttp.LoggableHTTPHeader{ - Header: res.Header, - ShouldLogCredentials: shouldLogCredentials, - }), - zap.Int("status", res.StatusCode)) + if c := logger.Check(zapcore.DebugLevel, "upstream roundtrip"); c != nil { + c.Write( + zap.Object("headers", caddyhttp.LoggableHTTPHeader{ + Header: res.Header, + ShouldLogCredentials: shouldLogCredentials, + }), + zap.Int("status", res.StatusCode), + ) + } // duration until upstream wrote response headers (roundtrip duration) repl.Set("http.reverse_proxy.upstream.latency", duration) @@ -879,7 +895,9 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, origRe repl.Set("http.reverse_proxy.status_code", res.StatusCode) repl.Set("http.reverse_proxy.status_text", res.Status) - logger.Debug("handling response", zap.Int("handler", i)) + if c := logger.Check(zapcore.DebugLevel, "handling response"); c != nil { + c.Write(zap.Int("handler", i)) + } // we make some data available via request context to child routes // so that they may inherit some options and functions from the @@ -975,7 +993,9 @@ func (h *Handler) finalizeResponse( err := h.copyResponse(rw, res.Body, h.flushInterval(req, res), logger) errClose := res.Body.Close() // close now, instead of defer, to populate res.Trailer if h.VerboseLogs || errClose != nil { - logger.Debug("closed response body from upstream", zap.Error(errClose)) + if c := logger.Check(zapcore.DebugLevel, "closed response body from upstream"); c != nil { + c.Write(zap.Error(errClose)) + } } if err != nil { // we're streaming the response and we've already written headers, so @@ -983,7 +1003,9 @@ func (h *Handler) finalizeResponse( // we'll just log the error and abort the stream here and panic just as // the standard lib's proxy to propagate the stream error. // see issue https://github.com/caddyserver/caddy/issues/5951 - logger.Warn("aborting with incomplete response", zap.Error(err)) + if c := logger.Check(zapcore.WarnLevel, "aborting with incomplete response"); c != nil { + c.Write(zap.Error(err)) + } // no extra logging from stdlib panic(http.ErrAbortHandler) } diff --git a/modules/caddyhttp/reverseproxy/streaming.go b/modules/caddyhttp/reverseproxy/streaming.go index a696ac7fb..c871a3fa1 100644 --- a/modules/caddyhttp/reverseproxy/streaming.go +++ b/modules/caddyhttp/reverseproxy/streaming.go @@ -31,6 +31,7 @@ import ( "unsafe" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "golang.org/x/net/http/httpguts" ) @@ -41,14 +42,18 @@ func (h *Handler) handleUpgradeResponse(logger *zap.Logger, wg *sync.WaitGroup, // Taken from https://github.com/golang/go/commit/5c489514bc5e61ad9b5b07bd7d8ec65d66a0512a // We know reqUpType is ASCII, it's checked by the caller. if !asciiIsPrint(resUpType) { - logger.Debug("backend tried to switch to invalid protocol", - zap.String("backend_upgrade", resUpType)) + if c := logger.Check(zapcore.DebugLevel, "backend tried to switch to invalid protocol"); c != nil { + c.Write(zap.String("backend_upgrade", resUpType)) + } return } if !asciiEqualFold(reqUpType, resUpType) { - logger.Debug("backend tried to switch to unexpected protocol via Upgrade header", - zap.String("backend_upgrade", resUpType), - zap.String("requested_upgrade", reqUpType)) + if c := logger.Check(zapcore.DebugLevel, "backend tried to switch to unexpected protocol via Upgrade header"); c != nil { + c.Write( + zap.String("backend_upgrade", resUpType), + zap.String("requested_upgrade", reqUpType), + ) + } return } @@ -68,12 +73,16 @@ func (h *Handler) handleUpgradeResponse(logger *zap.Logger, wg *sync.WaitGroup, //nolint:bodyclose conn, brw, hijackErr := http.NewResponseController(rw).Hijack() if errors.Is(hijackErr, http.ErrNotSupported) { - h.logger.Error("can't switch protocols using non-Hijacker ResponseWriter", zap.String("type", fmt.Sprintf("%T", rw))) + if c := logger.Check(zapcore.ErrorLevel, "can't switch protocols using non-Hijacker ResponseWriter"); c != nil { + c.Write(zap.String("type", fmt.Sprintf("%T", rw))) + } return } if hijackErr != nil { - h.logger.Error("hijack failed on protocol switch", zap.Error(hijackErr)) + if c := logger.Check(zapcore.ErrorLevel, "hijack failed on protocol switch"); c != nil { + c.Write(zap.Error(hijackErr)) + } return } @@ -93,11 +102,15 @@ func (h *Handler) handleUpgradeResponse(logger *zap.Logger, wg *sync.WaitGroup, start := time.Now() defer func() { conn.Close() - logger.Debug("connection closed", zap.Duration("duration", time.Since(start))) + if c := logger.Check(zapcore.DebugLevel, "hijack failed on protocol switch"); c != nil { + c.Write(zap.Duration("duration", time.Since(start))) + } }() if err := brw.Flush(); err != nil { - logger.Debug("response flush", zap.Error(err)) + if c := logger.Check(zapcore.DebugLevel, "response flush"); c != nil { + c.Write(zap.Error(err)) + } return } @@ -107,7 +120,9 @@ func (h *Handler) handleUpgradeResponse(logger *zap.Logger, wg *sync.WaitGroup, data, _ := brw.Peek(buffered) _, err := backConn.Write(data) if err != nil { - logger.Debug("backConn write failed", zap.Error(err)) + if c := logger.Check(zapcore.DebugLevel, "backConn write failed"); c != nil { + c.Write(zap.Error(err)) + } return } } @@ -148,9 +163,13 @@ func (h *Handler) handleUpgradeResponse(logger *zap.Logger, wg *sync.WaitGroup, go spc.copyFromBackend(errc) select { case err := <-errc: - logger.Debug("streaming error", zap.Error(err)) + if c := logger.Check(zapcore.DebugLevel, "streaming error"); c != nil { + c.Write(zap.Error(err)) + } case time := <-timeoutc: - logger.Debug("stream timed out", zap.Time("timeout", time)) + if c := logger.Check(zapcore.DebugLevel, "stream timed out"); c != nil { + c.Write(zap.Time("timeout", time)) + } } } @@ -247,7 +266,9 @@ func (h Handler) copyBuffer(dst io.Writer, src io.Reader, buf []byte, logger *za logger.Debug("waiting to read from upstream") nr, rerr := src.Read(buf) logger := logger.With(zap.Int("read", nr)) - logger.Debug("read from upstream", zap.Error(rerr)) + if c := logger.Check(zapcore.DebugLevel, "read from upstream"); c != nil { + c.Write(zap.Error(rerr)) + } if rerr != nil && rerr != io.EOF && rerr != context.Canceled { // TODO: this could be useful to know (indeed, it revealed an error in our // fastcgi PoC earlier; but it's this single error report here that necessitates @@ -256,7 +277,9 @@ func (h Handler) copyBuffer(dst io.Writer, src io.Reader, buf []byte, logger *za // something we need to report to the client, but read errors are a problem on our // end for sure. so we need to decide what we want.) // p.logf("copyBuffer: ReverseProxy read error during body copy: %v", rerr) - h.logger.Error("reading from backend", zap.Error(rerr)) + if c := logger.Check(zapcore.ErrorLevel, "reading from backend"); c != nil { + c.Write(zap.Error(rerr)) + } } if nr > 0 { logger.Debug("writing to downstream") @@ -264,10 +287,13 @@ func (h Handler) copyBuffer(dst io.Writer, src io.Reader, buf []byte, logger *za if nw > 0 { written += int64(nw) } - logger.Debug("wrote to downstream", - zap.Int("written", nw), - zap.Int64("written_total", written), - zap.Error(werr)) + if c := logger.Check(zapcore.DebugLevel, "wrote to downstream"); c != nil { + c.Write( + zap.Int("written", nw), + zap.Int64("written_total", written), + zap.Error(werr), + ) + } if werr != nil { return written, fmt.Errorf("writing: %w", werr) } @@ -347,13 +373,17 @@ func (h *Handler) cleanupConnections() error { if len(h.connections) > 0 { delay := time.Duration(h.StreamCloseDelay) h.connectionsCloseTimer = time.AfterFunc(delay, func() { - h.logger.Debug("closing streaming connections after delay", - zap.Duration("delay", delay)) + if c := h.logger.Check(zapcore.DebugLevel, "closing streaming connections after delay"); c != nil { + c.Write(zap.Duration("delay", delay)) + } err := h.closeConnections() if err != nil { - h.logger.Error("failed to closed connections after delay", - zap.Error(err), - zap.Duration("delay", delay)) + if c := h.logger.Check(zapcore.ErrorLevel, "failed to closed connections after delay"); c != nil { + c.Write( + zap.Error(err), + zap.Duration("delay", delay), + ) + } } }) } @@ -494,7 +524,9 @@ func (m *maxLatencyWriter) Write(p []byte) (n int, err error) { m.mu.Lock() defer m.mu.Unlock() n, err = m.dst.Write(p) - m.logger.Debug("wrote bytes", zap.Int("n", n), zap.Error(err)) + if c := m.logger.Check(zapcore.DebugLevel, "wrote bytes"); c != nil { + c.Write(zap.Int("n", n), zap.Error(err)) + } if m.latency < 0 { m.logger.Debug("flushing immediately") //nolint:errcheck @@ -510,7 +542,9 @@ func (m *maxLatencyWriter) Write(p []byte) (n int, err error) { } else { m.t.Reset(m.latency) } - m.logger.Debug("timer set for delayed flush", zap.Duration("duration", m.latency)) + if c := m.logger.Check(zapcore.DebugLevel, "timer set for delayed flush"); c != nil { + c.Write(zap.Duration("duration", m.latency)) + } m.flushPending = true return } diff --git a/modules/caddyhttp/reverseproxy/upstreams.go b/modules/caddyhttp/reverseproxy/upstreams.go index c8ba930d2..aa59dc41b 100644 --- a/modules/caddyhttp/reverseproxy/upstreams.go +++ b/modules/caddyhttp/reverseproxy/upstreams.go @@ -12,6 +12,7 @@ import ( "time" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "github.com/caddyserver/caddy/v2" ) @@ -136,10 +137,13 @@ func (su SRVUpstreams) GetUpstreams(r *http.Request) ([]*Upstream, error) { return allNew(cached.upstreams), nil } - su.logger.Debug("refreshing SRV upstreams", - zap.String("service", service), - zap.String("proto", proto), - zap.String("name", name)) + if c := su.logger.Check(zapcore.DebugLevel, "refreshing SRV upstreams"); c != nil { + c.Write( + zap.String("service", service), + zap.String("proto", proto), + zap.String("name", name), + ) + } _, records, err := su.resolver.LookupSRV(r.Context(), service, proto, name) if err != nil { @@ -148,23 +152,30 @@ func (su SRVUpstreams) GetUpstreams(r *http.Request) ([]*Upstream, error) { // only return an error if no records were also returned. if len(records) == 0 { if su.GracePeriod > 0 { - su.logger.Error("SRV lookup failed; using previously cached", zap.Error(err)) + if c := su.logger.Check(zapcore.ErrorLevel, "SRV lookup failed; using previously cached"); c != nil { + c.Write(zap.Error(err)) + } cached.freshness = time.Now().Add(time.Duration(su.GracePeriod) - time.Duration(su.Refresh)) srvs[suAddr] = cached return allNew(cached.upstreams), nil } return nil, err } - su.logger.Warn("SRV records filtered", zap.Error(err)) + if c := su.logger.Check(zapcore.WarnLevel, "SRV records filtered"); c != nil { + c.Write(zap.Error(err)) + } } upstreams := make([]Upstream, len(records)) for i, rec := range records { - su.logger.Debug("discovered SRV record", - zap.String("target", rec.Target), - zap.Uint16("port", rec.Port), - zap.Uint16("priority", rec.Priority), - zap.Uint16("weight", rec.Weight)) + if c := su.logger.Check(zapcore.DebugLevel, "discovered SRV record"); c != nil { + c.Write( + zap.String("target", rec.Target), + zap.Uint16("port", rec.Port), + zap.Uint16("priority", rec.Priority), + zap.Uint16("weight", rec.Weight), + ) + } addr := net.JoinHostPort(rec.Target, strconv.Itoa(int(rec.Port))) upstreams[i] = Upstream{Dial: addr} } @@ -361,10 +372,13 @@ func (au AUpstreams) GetUpstreams(r *http.Request) ([]*Upstream, error) { name := repl.ReplaceAll(au.Name, "") port := repl.ReplaceAll(au.Port, "") - au.logger.Debug("refreshing A upstreams", - zap.String("version", ipVersion), - zap.String("name", name), - zap.String("port", port)) + if c := au.logger.Check(zapcore.DebugLevel, "refreshing A upstreams"); c != nil { + c.Write( + zap.String("version", ipVersion), + zap.String("name", name), + zap.String("port", port), + ) + } ips, err := au.resolver.LookupIP(r.Context(), ipVersion, name) if err != nil { @@ -373,8 +387,9 @@ func (au AUpstreams) GetUpstreams(r *http.Request) ([]*Upstream, error) { upstreams := make([]Upstream, len(ips)) for i, ip := range ips { - au.logger.Debug("discovered A record", - zap.String("ip", ip.String())) + if c := au.logger.Check(zapcore.DebugLevel, "discovered A record"); c != nil { + c.Write(zap.String("ip", ip.String())) + } upstreams[i] = Upstream{ Dial: net.JoinHostPort(ip.String(), port), } @@ -467,11 +482,16 @@ func (mu MultiUpstreams) GetUpstreams(r *http.Request) ([]*Upstream, error) { up, err := src.GetUpstreams(r) if err != nil { - mu.logger.Error("upstream source returned error", - zap.Int("source_idx", i), - zap.Error(err)) + if c := mu.logger.Check(zapcore.ErrorLevel, "upstream source returned error"); c != nil { + c.Write( + zap.Int("source_idx", i), + zap.Error(err), + ) + } } else if len(up) == 0 { - mu.logger.Warn("upstream source returned 0 upstreams", zap.Int("source_idx", i)) + if c := mu.logger.Check(zapcore.WarnLevel, "upstream source returned 0 upstreams"); c != nil { + c.Write(zap.Int("source_idx", i)) + } } else { upstreams = append(upstreams, up...) } diff --git a/modules/caddyhttp/rewrite/rewrite.go b/modules/caddyhttp/rewrite/rewrite.go index c45ad98a2..e76682729 100644 --- a/modules/caddyhttp/rewrite/rewrite.go +++ b/modules/caddyhttp/rewrite/rewrite.go @@ -133,19 +133,17 @@ func (rewr Rewrite) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddy repl := r.Context().Value(caddy.ReplacerCtxKey).(*caddy.Replacer) const message = "rewrote request" - if rewr.logger.Check(zap.DebugLevel, message) == nil { + c := rewr.logger.Check(zap.DebugLevel, message) + if c == nil { rewr.Rewrite(r, repl) return next.ServeHTTP(w, r) } - logger := rewr.logger.With( - zap.Object("request", caddyhttp.LoggableHTTPRequest{Request: r}), - ) - changed := rewr.Rewrite(r, repl) if changed { - logger.Debug(message, + c.Write( + zap.Object("request", caddyhttp.LoggableHTTPRequest{Request: r}), zap.String("method", r.Method), zap.String("uri", r.RequestURI), ) diff --git a/modules/caddyhttp/server.go b/modules/caddyhttp/server.go index 6caaabcda..9dfa1bb6d 100644 --- a/modules/caddyhttp/server.go +++ b/modules/caddyhttp/server.go @@ -275,7 +275,9 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { if r.ProtoMajor < 3 { err := s.h3server.SetQUICHeaders(w.Header()) if err != nil { - s.logger.Error("setting HTTP/3 Alt-Svc header", zap.Error(err)) + if c := s.logger.Check(zapcore.ErrorLevel, "setting HTTP/3 Alt-Svc header"); c != nil { + c.Write(zap.Error(err)) + } } } } @@ -283,9 +285,12 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { // reject very long methods; probably a mistake or an attack if len(r.Method) > 32 { if s.shouldLogRequest(r) { - s.accessLogger.Debug("rejecting request with long method", - zap.String("method_trunc", r.Method[:32]), - zap.String("remote_addr", r.RemoteAddr)) + if c := s.accessLogger.Check(zapcore.DebugLevel, "rejecting request with long method"); c != nil { + c.Write( + zap.String("method_trunc", r.Method[:32]), + zap.String("remote_addr", r.RemoteAddr), + ) + } } w.WriteHeader(http.StatusMethodNotAllowed) return @@ -300,7 +305,9 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { //nolint:bodyclose err := http.NewResponseController(w).EnableFullDuplex() if err != nil { - s.logger.Warn("failed to enable full duplex", zap.Error(err)) + if c := s.logger.Check(zapcore.WarnLevel, "failed to enable full duplex"); c != nil { + c.Write(zap.Error(err)) + } } } @@ -379,6 +386,7 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { // add HTTP error information to request context r = s.Errors.WithError(r, err) + var fields []zapcore.Field if s.Errors != nil && len(s.Errors.Routes) > 0 { // execute user-defined error handling route err2 := s.errorHandlerChain.ServeHTTP(w, r) @@ -386,17 +394,28 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { // user's error route handled the error response // successfully, so now just log the error for _, logger := range errLoggers { - logger.Debug(errMsg, errFields...) + if c := logger.Check(zapcore.DebugLevel, errMsg); c != nil { + if fields == nil { + fields = errFields() + } + + c.Write(fields...) + } } } else { // well... this is awkward - errFields = append([]zapcore.Field{ - zap.String("error", err2.Error()), - zap.Namespace("first_error"), - zap.String("msg", errMsg), - }, errFields...) for _, logger := range errLoggers { - logger.Error("error handling handler error", errFields...) + if c := logger.Check(zapcore.ErrorLevel, "error handling handler error"); c != nil { + if fields == nil { + fields = errFields() + fields = append([]zapcore.Field{ + zap.String("error", err2.Error()), + zap.Namespace("first_error"), + zap.String("msg", errMsg), + }, fields...) + } + c.Write(fields...) + } } if handlerErr, ok := err.(HandlerError); ok { w.WriteHeader(handlerErr.StatusCode) @@ -405,11 +424,17 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { } } } else { + logLevel := zapcore.DebugLevel + if errStatus >= 500 { + logLevel = zapcore.ErrorLevel + } + for _, logger := range errLoggers { - if errStatus >= 500 { - logger.Error(errMsg, errFields...) - } else { - logger.Debug(errMsg, errFields...) + if c := logger.Check(logLevel, errMsg); c != nil { + if fields == nil { + fields = errFields() + } + c.Write(fields...) } } w.WriteHeader(errStatus) @@ -746,7 +771,9 @@ func (s *Server) logTrace(mh MiddlewareHandler) { if s.Logs == nil || !s.Logs.Trace { return } - s.traceLogger.Debug(caddy.GetModuleName(mh), zap.Any("module", mh)) + if c := s.traceLogger.Check(zapcore.DebugLevel, caddy.GetModuleName(mh)); c != nil { + c.Write(zap.Any("module", mh)) + } } // logRequest logs the request to access logs, unless skipped. @@ -759,50 +786,64 @@ func (s *Server) logRequest( return } - repl.Set("http.response.status", wrec.Status()) // will be 0 if no response is written by us (Go will write 200 to client) - repl.Set("http.response.size", wrec.Size()) + status := wrec.Status() + size := wrec.Size() + + repl.Set("http.response.status", status) // will be 0 if no response is written by us (Go will write 200 to client) + repl.Set("http.response.size", size) repl.Set("http.response.duration", duration) repl.Set("http.response.duration_ms", duration.Seconds()*1e3) // multiply seconds to preserve decimal (see #4666) - userID, _ := repl.GetString("http.auth.user.id") - - reqBodyLength := 0 - if bodyReader != nil { - reqBodyLength = bodyReader.Length - } - - extra := r.Context().Value(ExtraLogFieldsCtxKey).(*ExtraLogFields) - - fieldCount := 6 - fields := make([]zapcore.Field, 0, fieldCount+len(extra.fields)) - fields = append(fields, - zap.Int("bytes_read", reqBodyLength), - zap.String("user_id", userID), - zap.Duration("duration", *duration), - zap.Int("size", wrec.Size()), - zap.Int("status", wrec.Status()), - zap.Object("resp_headers", LoggableHTTPHeader{ - Header: wrec.Header(), - ShouldLogCredentials: shouldLogCredentials, - })) - fields = append(fields, extra.fields...) - loggers := []*zap.Logger{accLog} if s.Logs != nil { loggers = s.Logs.wrapLogger(accLog, r) } - // wrapping may return multiple loggers, so we log to all of them + message := "handled request" + if nop, ok := GetVar(r.Context(), "unhandled").(bool); ok && nop { + message = "NOP" + } + + logLevel := zapcore.InfoLevel + if status >= 500 { + logLevel = zapcore.ErrorLevel + } + + var fields []zapcore.Field for _, logger := range loggers { - logAtLevel := logger.Info - if wrec.Status() >= 500 { - logAtLevel = logger.Error + c := logger.Check(logLevel, message) + if c == nil { + continue } - message := "handled request" - if nop, ok := GetVar(r.Context(), "unhandled").(bool); ok && nop { - message = "NOP" + + if fields == nil { + + userID, _ := repl.GetString("http.auth.user.id") + + reqBodyLength := 0 + if bodyReader != nil { + reqBodyLength = bodyReader.Length + } + + extra := r.Context().Value(ExtraLogFieldsCtxKey).(*ExtraLogFields) + + fieldCount := 6 + fields = make([]zapcore.Field, 0, fieldCount+len(extra.fields)) + fields = append(fields, + zap.Int("bytes_read", reqBodyLength), + zap.String("user_id", userID), + zap.Duration("duration", *duration), + zap.Int("size", size), + zap.Int("status", status), + zap.Object("resp_headers", LoggableHTTPHeader{ + Header: wrec.Header(), + ShouldLogCredentials: shouldLogCredentials, + }), + ) + fields = append(fields, extra.fields...) } - logAtLevel(message, fields...) + + c.Write(fields...) } } diff --git a/modules/caddyhttp/server_test.go b/modules/caddyhttp/server_test.go index d382a6963..2c8033d45 100644 --- a/modules/caddyhttp/server_test.go +++ b/modules/caddyhttp/server_test.go @@ -121,6 +121,29 @@ func BenchmarkServer_LogRequest(b *testing.B) { } } +func BenchmarkServer_LogRequest_NopLogger(b *testing.B) { + s := &Server{} + + extra := new(ExtraLogFields) + ctx := context.WithValue(context.Background(), ExtraLogFieldsCtxKey, extra) + + req := httptest.NewRequest(http.MethodGet, "/", nil).WithContext(ctx) + rec := httptest.NewRecorder() + wrec := NewResponseRecorder(rec, nil, nil) + + duration := 50 * time.Millisecond + repl := NewTestReplacer(req) + bodyReader := &lengthReader{Source: req.Body} + + accLog := zap.NewNop() + + b.ResetTimer() + + for i := 0; i < b.N; i++ { + s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, false) + } +} + func BenchmarkServer_LogRequest_WithTraceID(b *testing.B) { s := &Server{} diff --git a/modules/caddyhttp/tracing/tracerprovider.go b/modules/caddyhttp/tracing/tracerprovider.go index 035425ed6..0a3766974 100644 --- a/modules/caddyhttp/tracing/tracerprovider.go +++ b/modules/caddyhttp/tracing/tracerprovider.go @@ -7,6 +7,7 @@ import ( sdktrace "go.opentelemetry.io/otel/sdk/trace" "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) // globalTracerProvider stores global tracer provider and is responsible for graceful shutdown when nobody is using it. @@ -47,7 +48,9 @@ func (t *tracerProvider) cleanupTracerProvider(logger *zap.Logger) error { if t.tracerProvider != nil { // tracerProvider.ForceFlush SHOULD be invoked according to https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/trace/sdk.md#forceflush if err := t.tracerProvider.ForceFlush(context.Background()); err != nil { - logger.Error("forcing flush", zap.Error(err)) + if c := logger.Check(zapcore.ErrorLevel, "forcing flush"); c != nil { + c.Write(zap.Error(err)) + } } // tracerProvider.Shutdown MUST be invoked according to https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/trace/sdk.md#shutdown |