From f2a7e7c966c42b3a09bc8414136af0439fd7b630 Mon Sep 17 00:00:00 2001 From: fleandro <3987005+flga@users.noreply.github.com> Date: Fri, 2 Sep 2022 05:02:48 +0100 Subject: [PATCH] fastcgi: allow users to log stderr output (#4967) (#5004) Co-authored-by: flga --- .../reverseproxy/fastcgi/caddyfile.go | 76 +++++++++++-------- .../caddyhttp/reverseproxy/fastcgi/client.go | 35 ++++++++- .../caddyhttp/reverseproxy/fastcgi/fastcgi.go | 46 +++++++++-- 3 files changed, 116 insertions(+), 41 deletions(-) diff --git a/modules/caddyhttp/reverseproxy/fastcgi/caddyfile.go b/modules/caddyhttp/reverseproxy/fastcgi/caddyfile.go index 96b84f214..a9e6b220f 100644 --- a/modules/caddyhttp/reverseproxy/fastcgi/caddyfile.go +++ b/modules/caddyhttp/reverseproxy/fastcgi/caddyfile.go @@ -35,16 +35,16 @@ func init() { // UnmarshalCaddyfile deserializes Caddyfile tokens into h. // -// transport fastcgi { -// root -// split -// env -// resolve_root_symlink -// dial_timeout -// read_timeout -// write_timeout -// } -// +// transport fastcgi { +// root +// split +// env +// resolve_root_symlink +// dial_timeout +// read_timeout +// write_timeout +// capture_stderr +// } func (t *Transport) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { for d.Next() { for d.NextBlock(0) { @@ -107,6 +107,12 @@ func (t *Transport) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { } t.WriteTimeout = caddy.Duration(dur) + case "capture_stderr": + if d.NextArg() { + return d.ArgErr() + } + t.CaptureStderr = true + default: return d.Errf("unrecognized subdirective %s", d.Val()) } @@ -120,31 +126,31 @@ func (t *Transport) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { // Unmarshaler is invoked by this function) but the resulting proxy is specially // configured for most™️ PHP apps over FastCGI. A line such as this: // -// php_fastcgi localhost:7777 +// php_fastcgi localhost:7777 // // is equivalent to a route consisting of: // -// # Add trailing slash for directory requests -// @canonicalPath { -// file {path}/index.php -// not path */ -// } -// redir @canonicalPath {path}/ 308 +// # Add trailing slash for directory requests +// @canonicalPath { +// file {path}/index.php +// not path */ +// } +// redir @canonicalPath {path}/ 308 // -// # If the requested file does not exist, try index files -// @indexFiles file { -// try_files {path} {path}/index.php index.php -// split_path .php -// } -// rewrite @indexFiles {http.matchers.file.relative} +// # If the requested file does not exist, try index files +// @indexFiles file { +// try_files {path} {path}/index.php index.php +// split_path .php +// } +// rewrite @indexFiles {http.matchers.file.relative} // -// # Proxy PHP files to the FastCGI responder -// @phpFiles path *.php -// reverse_proxy @phpFiles localhost:7777 { -// transport fastcgi { -// split .php -// } -// } +// # Proxy PHP files to the FastCGI responder +// @phpFiles path *.php +// reverse_proxy @phpFiles localhost:7777 { +// transport fastcgi { +// split .php +// } +// } // // Thus, this directive produces multiple handlers, each with a different // matcher because multiple consecutive handlers are necessary to support @@ -154,7 +160,7 @@ func (t *Transport) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { // // If a matcher is specified by the user, for example: // -// php_fastcgi /subpath localhost:7777 +// php_fastcgi /subpath localhost:7777 // // then the resulting handlers are wrapped in a subroute that uses the // user's matcher as a prerequisite to enter the subroute. In other @@ -303,6 +309,14 @@ func parsePHPFastCGI(h httpcaddyfile.Helper) ([]httpcaddyfile.ConfigValue, error fcgiTransport.WriteTimeout = caddy.Duration(dur) dispenser.Delete() dispenser.Delete() + + case "capture_stderr": + args := dispenser.RemainingArgs() + dispenser.Delete() + for range args { + dispenser.Delete() + } + fcgiTransport.CaptureStderr = true } } } diff --git a/modules/caddyhttp/reverseproxy/fastcgi/client.go b/modules/caddyhttp/reverseproxy/fastcgi/client.go index 0fdcbfeef..bccb49cee 100644 --- a/modules/caddyhttp/reverseproxy/fastcgi/client.go +++ b/modules/caddyhttp/reverseproxy/fastcgi/client.go @@ -42,6 +42,8 @@ import ( "strings" "sync" "time" + + "go.uber.org/zap" ) // FCGIListenSockFileno describes listen socket file number. @@ -180,6 +182,7 @@ type FCGIClient struct { stderr bytes.Buffer keepAlive bool reqID uint16 + logger *zap.Logger } // DialWithDialerContext connects to the fcgi responder at the specified network address, using custom net.Dialer @@ -339,7 +342,6 @@ type streamReader struct { } func (w *streamReader) Read(p []byte) (n int, err error) { - if len(p) > 0 { if len(w.buf) == 0 { @@ -400,9 +402,24 @@ func (c *FCGIClient) Do(p map[string]string, req io.Reader) (r io.Reader, err er type clientCloser struct { *FCGIClient io.Reader + + status int + logger *zap.Logger } -func (f clientCloser) Close() error { return f.rwc.Close() } +func (f clientCloser) Close() error { + stderr := f.FCGIClient.stderr.Bytes() + if len(stderr) == 0 { + return f.FCGIClient.rwc.Close() + } + + if f.status >= 400 { + f.logger.Error("stderr", zap.ByteString("body", stderr)) + } else { + f.logger.Warn("stderr", zap.ByteString("body", stderr)) + } + return f.FCGIClient.rwc.Close() +} // Request returns a HTTP Response with Header and Body // from fcgi responder @@ -442,9 +459,19 @@ func (c *FCGIClient) Request(p map[string]string, req io.Reader) (resp *http.Res resp.ContentLength, _ = strconv.ParseInt(resp.Header.Get("Content-Length"), 10, 64) if chunked(resp.TransferEncoding) { - resp.Body = clientCloser{c, httputil.NewChunkedReader(rb)} + resp.Body = clientCloser{ + FCGIClient: c, + Reader: httputil.NewChunkedReader(rb), + status: resp.StatusCode, + logger: c.logger, + } } else { - resp.Body = clientCloser{c, io.NopCloser(rb)} + resp.Body = clientCloser{ + FCGIClient: c, + Reader: rb, + status: resp.StatusCode, + logger: c.logger, + } } return } diff --git a/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go b/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go index 313f4ebd1..a9f8be13a 100644 --- a/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go +++ b/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go @@ -34,6 +34,8 @@ import ( "github.com/caddyserver/caddy/v2" ) +var noopLogger = zap.NewNop() + func init() { caddy.RegisterModule(Transport{}) } @@ -74,6 +76,11 @@ type Transport struct { // The duration used to set a deadline when sending to the FastCGI server. WriteTimeout caddy.Duration `json:"write_timeout,omitempty"` + // Capture and log any messages sent by the upstream on stderr. Logs at WARN + // level by default. If the response has a 4xx or 5xx status ERROR level will + // be used instead. + CaptureStderr bool `json:"capture_stderr,omitempty"` + serverSoftware string logger *zap.Logger } @@ -108,6 +115,8 @@ func (t *Transport) Provision(ctx caddy.Context) error { // RoundTrip implements http.RoundTripper. func (t Transport) RoundTrip(r *http.Request) (*http.Response, error) { + server := r.Context().Value(caddyhttp.ServerCtxKey).(*caddyhttp.Server) + // Disallow null bytes in the request path, because // PHP upstreams may do bad things, like execute a // non-PHP file as PHP code. See #4574 @@ -135,10 +144,16 @@ func (t Transport) RoundTrip(r *http.Request) (*http.Response, error) { address = dialInfo.Address } + logCreds := server.Logs != nil && server.Logs.ShouldLogCredentials + loggableReq := caddyhttp.LoggableHTTPRequest{ + Request: r, + ShouldLogCredentials: logCreds, + } + loggableEnv := loggableEnv{vars: env, logCredentials: logCreds} t.logger.Debug("roundtrip", - zap.Object("request", caddyhttp.LoggableHTTPRequest{Request: r}), + zap.Object("request", loggableReq), zap.String("dial", address), - zap.Object("env", env), + zap.Object("env", loggableEnv), ) fcgiBackend, err := DialContext(ctx, network, address) @@ -146,6 +161,14 @@ func (t Transport) RoundTrip(r *http.Request) (*http.Response, error) { // TODO: wrap in a special error type if the dial failed, so retries can happen if enabled return nil, fmt.Errorf("dialing backend: %v", err) } + if t.CaptureStderr { + fcgiBackend.logger = t.logger.With( + zap.Object("request", loggableReq), + zap.Object("env", loggableEnv), + ) + } else { + fcgiBackend.logger = noopLogger + } // fcgiBackend gets closed when response body is closed (see clientCloser) // read/write timeouts @@ -364,11 +387,22 @@ func (t Transport) splitPos(path string) int { return -1 } -// envVars is a simple type to allow for speeding up zap log encoding. type envVars map[string]string -func (env envVars) MarshalLogObject(enc zapcore.ObjectEncoder) error { - for k, v := range env { +// loggableEnv is a simple type to allow for speeding up zap log encoding. +type loggableEnv struct { + vars envVars + logCredentials bool +} + +func (env loggableEnv) MarshalLogObject(enc zapcore.ObjectEncoder) error { + for k, v := range env.vars { + if !env.logCredentials { + switch strings.ToLower(k) { + case "http_cookie", "http_set_cookie", "http_authorization", "http_proxy_authorization": + v = "" + } + } enc.AddString(k, v) } return nil @@ -387,7 +421,7 @@ var headerNameReplacer = strings.NewReplacer(" ", "_", "-", "_") // Interface guards var ( - _ zapcore.ObjectMarshaler = (*envVars)(nil) + _ zapcore.ObjectMarshaler = (*loggableEnv)(nil) _ caddy.Provisioner = (*Transport)(nil) _ http.RoundTripper = (*Transport)(nil)