Infrastructure/caddy
1
Fork 0
mirror of https://github.com/caddyserver/caddy.git synced 2024-12-16 21:56:40 -05:00
Code Issues Activity

perf: use zap's Check() to prevent useless allocs (#6560)

Browse source 
* perf: use zap's Check() to prevent useless allocs

* fix

* fix

* fix

* fix

* restore previous replacer behavior

* fix linter
This commit is contained in:
Kévin Dunglas 2024-09-13 19:16:37 +02:00 committed by GitHub
parent 21f9c20a04
commit f4bf4e0097
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
30 changed files with 599 additions and 282 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

7
modules/caddyhttp/caddyauth/caddyauth.go
View file

@ -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 {

11
modules/caddyhttp/fileserver/browse.go
View file

@ -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+"/")
}
}

7
modules/caddyhttp/fileserver/browsetplcontext.go
View file

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

14
modules/caddyhttp/fileserver/matcher.go
View file

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

91
modules/caddyhttp/fileserver/staticfiles.go
View file

@ -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

5
modules/caddyhttp/intercept/intercept.go
View file

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

10
modules/caddyhttp/ip_matchers.go
View file

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

12
modules/caddyhttp/logging.go
View file

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

24
modules/caddyhttp/push/handler.go
View file

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

9
modules/caddyhttp/requestbody/requestbody.go
View file

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

10
modules/caddyhttp/reverseproxy/fastcgi/client.go
View file

@ -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()

11
modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go
View file

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

154
modules/caddyhttp/reverseproxy/healthchecks.go
View file

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

9
modules/caddyhttp/reverseproxy/httptransport.go
View file

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

10
modules/caddyhttp/reverseproxy/metrics.go
View file

@ -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()),
)
}
}
}()

54
modules/caddyhttp/reverseproxy/reverseproxy.go
View file

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

84
modules/caddyhttp/reverseproxy/streaming.go
View file

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

62
modules/caddyhttp/reverseproxy/upstreams.go
View file

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

10
modules/caddyhttp/rewrite/rewrite.go
View file

@ -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),
)

141
modules/caddyhttp/server.go
View file

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

23
modules/caddyhttp/server_test.go
View file

@ -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{}

5
modules/caddyhttp/tracing/tracerprovider.go
View file

@ -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

13
modules/caddypki/acmeserver/acmeserver.go
View file

@ -35,6 +35,7 @@ import (
"github.com/smallstep/certificates/db"
"github.com/smallstep/nosql"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/caddyserver/caddy/v2"
"github.com/caddyserver/caddy/v2/modules/caddyhttp"
@ -243,10 +244,14 @@ func (ash Handler) Cleanup() error {
key := ash.getDatabaseKey()
deleted, err := databasePool.Delete(key)
if deleted {
ash.logger.Debug("unloading unused CA database", zap.String("db_key", key))
if c := ash.logger.Check(zapcore.DebugLevel, "unloading unused CA database"); c != nil {
c.Write(zap.String("db_key", key))
}
}
if err != nil {
ash.logger.Error("closing CA database", zap.String("db_key", key), zap.Error(err))
if c := ash.logger.Check(zapcore.ErrorLevel, "closing CA database"); c != nil {
c.Write(zap.String("db_key", key), zap.Error(err))
}
}
return err
}
@ -271,7 +276,9 @@ func (ash Handler) openDatabase() (*db.AuthDB, error) {
})
if loaded {
ash.logger.Debug("loaded preexisting CA database", zap.String("db_key", key))
if c := ash.logger.Check(zapcore.DebugLevel, "loaded preexisting CA database"); c != nil {
c.Write(zap.String("db_key", key))
}
}
return database.(databaseCloser).DB, err

5
modules/caddytls/acmeissuer.go
View file

@ -30,6 +30,7 @@ import (
"github.com/caddyserver/zerossl"
"github.com/mholt/acmez/v2/acme"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/caddyserver/caddy/v2"
"github.com/caddyserver/caddy/v2/caddyconfig"
@ -321,7 +322,9 @@ func (iss *ACMEIssuer) generateZeroSSLEABCredentials(ctx context.Context, acct a
return nil, acct, fmt.Errorf("failed getting EAB credentials: HTTP %d", resp.StatusCode)
}
iss.logger.Info("generated EAB credentials", zap.String("key_id", result.EABKID))
if c := iss.logger.Check(zapcore.InfoLevel, "generated EAB credentials"); c != nil {
c.Write(zap.String("key_id", result.EABKID))
}
return &acme.EAB{
KeyID: result.EABKID,

28
modules/caddytls/automation.go
View file

@ -26,6 +26,7 @@ import (
"github.com/caddyserver/certmagic"
"github.com/mholt/acmez/v2"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/caddyserver/caddy/v2"
)
@ -292,21 +293,30 @@ func (ap *AutomationPolicy) Provision(tlsApp *TLS) error {
remoteIP, _, _ = net.SplitHostPort(remote.String())
}
}
tlsApp.logger.Debug("asking for permission for on-demand certificate",
zap.String("remote_ip", remoteIP),
zap.String("domain", name))
if c := tlsApp.logger.Check(zapcore.DebugLevel, "asking for permission for on-demand certificate"); c != nil {
c.Write(
zap.String("remote_ip", remoteIP),
zap.String("domain", name),
)
}
// ask the permission module if this cert is allowed
if err := tlsApp.Automation.OnDemand.permission.CertificateAllowed(ctx, name); err != nil {
// distinguish true errors from denials, because it's important to elevate actual errors
if errors.Is(err, ErrPermissionDenied) {
tlsApp.logger.Debug("on-demand certificate issuance denied",
zap.String("domain", name),
zap.Error(err))
if c := tlsApp.logger.Check(zapcore.DebugLevel, "on-demand certificate issuance denied"); c != nil {
c.Write(
zap.String("domain", name),
zap.Error(err),
)
}
} else {
tlsApp.logger.Error("failed to get permission for on-demand certificate",
zap.String("domain", name),
zap.Error(err))
if c := tlsApp.logger.Check(zapcore.ErrorLevel, "failed to get permission for on-demand certificate"); c != nil {
c.Write(
zap.String("domain", name),
zap.Error(err),
)
}
}
return err
}

5
modules/caddytls/certmanagers.go
View file

@ -12,6 +12,7 @@ import (
"github.com/caddyserver/certmagic"
"github.com/tailscale/tscert"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/caddyserver/caddy/v2"
"github.com/caddyserver/caddy/v2/caddyconfig/caddyfile"
@ -46,7 +47,9 @@ func (ts Tailscale) GetCertificate(ctx context.Context, hello *tls.ClientHelloIn
return nil, nil // pass-thru: Tailscale can't offer a cert for this name
}
if err != nil {
ts.logger.Warn("could not get status; will try to get certificate anyway", zap.Error(err))
if c := ts.logger.Check(zapcore.WarnLevel, "could not get status; will try to get certificate anyway"); c != nil {
c.Write(zap.Error(err))
}
}
return tscert.GetCertificateWithContext(ctx, hello)
}

6
modules/caddytls/connpolicy.go
View file

@ -28,6 +28,7 @@ import (
"github.com/mholt/acmez/v2"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/caddyserver/caddy/v2"
"github.com/caddyserver/caddy/v2/caddyconfig"
@ -338,8 +339,9 @@ func (p *ConnectionPolicy) buildStandardTLSConfig(ctx caddy.Context) error {
cfg.KeyLogWriter = logFile.(io.Writer)
tlsApp.logger.Warn("TLS SECURITY COMPROMISED: secrets logging is enabled!",
zap.String("log_filename", filename))
if c := tlsApp.logger.Check(zapcore.WarnLevel, "TLS SECURITY COMPROMISED: secrets logging is enabled!"); c != nil {
c.Write(zap.String("log_filename", filename))
}
}
setDefaultTLSParams(cfg)

9
modules/caddytls/matchers.go
View file

@ -25,6 +25,7 @@ import (
"github.com/caddyserver/certmagic"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/caddyserver/caddy/v2"
"github.com/caddyserver/caddy/v2/caddyconfig/caddyfile"
@ -291,7 +292,9 @@ func (m MatchRemoteIP) Match(hello *tls.ClientHelloInfo) bool {
}
ipAddr, err := netip.ParseAddr(ipStr)
if err != nil {
m.logger.Error("invalid client IP address", zap.String("ip", ipStr))
if c := m.logger.Check(zapcore.ErrorLevel, "invalid client IP address"); c != nil {
c.Write(zap.String("ip", ipStr))
}
return false
}
return (len(m.cidrs) == 0 || m.matches(ipAddr, m.cidrs)) &&
@ -408,7 +411,9 @@ func (m MatchLocalIP) Match(hello *tls.ClientHelloInfo) bool {
}
ipAddr, err := netip.ParseAddr(ipStr)
if err != nil {
m.logger.Error("invalid local IP address", zap.String("ip", ipStr))
if c := m.logger.Check(zapcore.ErrorLevel, "invalid local IP address"); c != nil {
c.Write(zap.String("ip", ipStr))
}
return false
}
return (len(m.cidrs) == 0 || m.matches(ipAddr, m.cidrs))

25
modules/caddytls/ondemand.go
View file

@ -26,6 +26,7 @@ import (
"github.com/caddyserver/certmagic"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/caddyserver/caddy/v2"
"github.com/caddyserver/caddy/v2/caddyconfig/caddyfile"
@ -156,10 +157,13 @@ func (p PermissionByHTTP) CertificateAllowed(ctx context.Context, name string) e
remote = chi.Conn.RemoteAddr().String()
}
p.logger.Debug("asking permission endpoint",
zap.String("remote", remote),
zap.String("domain", name),
zap.String("url", askURLString))
if c := p.logger.Check(zapcore.DebugLevel, "asking permission endpoint"); c != nil {
c.Write(
zap.String("remote", remote),
zap.String("domain", name),
zap.String("url", askURLString),
)
}
resp, err := onDemandAskClient.Get(askURLString)
if err != nil {
@ -168,11 +172,14 @@ func (p PermissionByHTTP) CertificateAllowed(ctx context.Context, name string) e
}
resp.Body.Close()
p.logger.Debug("response from permission endpoint",
zap.String("remote", remote),
zap.String("domain", name),
zap.String("url", askURLString),
zap.Int("status", resp.StatusCode))
if c := p.logger.Check(zapcore.DebugLevel, "response from permission endpoint"); c != nil {
c.Write(
zap.String("remote", remote),
zap.String("domain", name),
zap.String("url", askURLString),
zap.Int("status", resp.StatusCode),
)
}
if resp.StatusCode < 200 || resp.StatusCode > 299 {
return fmt.Errorf("%s: %w %s - non-2xx status code %d", name, ErrPermissionDenied, askEndpoint, resp.StatusCode)

27
modules/caddytls/tls.go
View file

@ -27,6 +27,7 @@ import (
"github.com/caddyserver/certmagic"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"github.com/caddyserver/caddy/v2"
"github.com/caddyserver/caddy/v2/modules/caddyevents"
@ -323,8 +324,9 @@ func (t *TLS) Start() error {
if t.Automation.OnDemand == nil || (t.Automation.OnDemand.Ask == "" && t.Automation.OnDemand.permission == nil) {
for _, ap := range t.Automation.Policies {
if ap.OnDemand && ap.isWildcardOrDefault() {
t.logger.Warn("YOUR SERVER MAY BE VULNERABLE TO ABUSE: on-demand TLS is enabled, but no protections are in place",
zap.String("docs", "https://caddyserver.com/docs/automatic-https#on-demand-tls"))
if c := t.logger.Check(zapcore.WarnLevel, "YOUR SERVER MAY BE VULNERABLE TO ABUSE: on-demand TLS is enabled, but no protections are in place"); c != nil {
c.Write(zap.String("docs", "https://caddyserver.com/docs/automatic-https#on-demand-tls"))
}
break
}
}
@ -408,9 +410,12 @@ func (t *TLS) Cleanup() error {
// give the new TLS app a "kick" to manage certs that it is configured for
// with its own configuration instead of the one we just evicted
if err := nextTLSApp.Manage(reManage); err != nil {
t.logger.Error("re-managing unloaded certificates with new config",
zap.Strings("subjects", reManage),
zap.Error(err))
if c := t.logger.Check(zapcore.ErrorLevel, "re-managing unloaded certificates with new config"); c != nil {
c.Write(
zap.Strings("subjects", reManage),
zap.Error(err),
)
}
}
} else {
// no more TLS app running, so delete in-memory cert cache
@ -653,7 +658,9 @@ func (t *TLS) cleanStorageUnits() {
id, err := caddy.InstanceID()
if err != nil {
t.logger.Warn("unable to get instance ID; storage clean stamps will be incomplete", zap.Error(err))
if c := t.logger.Check(zapcore.WarnLevel, "unable to get instance ID; storage clean stamps will be incomplete"); c != nil {
c.Write(zap.Error(err))
}
}
options := certmagic.CleanStorageOptions{
Logger: t.logger,
@ -669,7 +676,9 @@ func (t *TLS) cleanStorageUnits() {
if err != nil {
// probably don't want to return early, since we should still
// see if any other storages can get cleaned up
t.logger.Error("could not clean default/global storage", zap.Error(err))
if c := t.logger.Check(zapcore.ErrorLevel, "could not clean default/global storage"); c != nil {
c.Write(zap.Error(err))
}
}
// then clean each storage defined in ACME automation policies
@ -679,7 +688,9 @@ func (t *TLS) cleanStorageUnits() {
continue
}
if err := certmagic.CleanStorage(t.ctx, ap.storage, options); err != nil {
t.logger.Error("could not clean storage configured in automation policy", zap.Error(err))
if c := t.logger.Check(zapcore.ErrorLevel, "could not clean storage configured in automation policy"); c != nil {
c.Write(zap.Error(err))
}
}
}
}