fastcgi: allow users to log stderr output (#4967) (#5004)

Co-authored-by: flga <flga@users.noreply.github.com>

modules/caddyhttp/reverseproxy/fastcgi/caddyfile.go

@@ -35,16 +35,16 @@ func init() {
 
 // UnmarshalCaddyfile deserializes Caddyfile tokens into h.
 //
-//     transport fastcgi {
-//         root <path>
-//         split <at>
-//         env <key> <value>
-//         resolve_root_symlink
-//         dial_timeout <duration>
-//         read_timeout <duration>
-//         write_timeout <duration>
-//     }
-//
+//	transport fastcgi {
+//	    root <path>
+//	    split <at>
+//	    env <key> <value>
+//	    resolve_root_symlink
+//	    dial_timeout <duration>
+//	    read_timeout <duration>
+//	    write_timeout <duration>
+//	    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
 			}
 		}
 	}

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
 }

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)