Handle stderr written from fastcgi transport

[francislavoie]

In Caddy v1, we used to write the stderr we received from the fastcgi upstream straight to stderr.

In v2, we didn't port over the bit of code that handled the received stderr, so it just gets dropped. This means that errors reported from PHP can get lost if the PHP app doesn't have some other logging mechanism configured.

Some more context written out here https://caddy.community/t/equivalent-of-errors-stderr-in-caddy-2/16856/7

The relevant chunk of code from v1:

caddy/caddyhttp/fastcgi/fastcgi.go

Lines 186 to 189 in 240de5a

	if fcgiBackend.stderr.Len() != 0 {
	// Remove trailing newline, error logger already does this.
	err = LogError(strings.TrimSuffix(fcgiBackend.stderr.String(), "\n"))
	}

I'm unclear on exactly what we should do with this. There's a few different options, but I'm not sure which is best.

• Just log the stderr we get to the http.reverse_proxy.transport.fastcgi logger at ERROR level, always
  • Pro: this is super easy just a couple lines of code, no config
  • Con: it could be noisy for some, and it could be considered a "breaking change" in the sense that bumping up to a version with this might have a surprising amount of stuff written out; also the logs may contain sensitive info users didn't expect to suddenly get pumped to their logs
  • Note: users could always just configure the default logger to exclude these, and/or a second logger to write them elsewhere, but this is a bit tedious
• Add an opt-in option to the fastcgi transport to log stderr to its logger
  • Pro: things stay the same for users, no noise by default
  • Con: most users may not realize they might be getting errors from their fastcgi app that they're missing out on without explicitly turning this on; adds noise to the config
• Always log it, but at DEBUG level instead
  • Pro: also super easy, not visible by default but can be shown with the debug global option etc
  • Con: similar problem, not immediately obvious they might be missing out on it, but potentially more discoverable; less semantically correct because they are errors, really

Another thing to note, these logs tend to have newlines in them, which can be kinda awkward. For the JSON encoder it's fine, it'll just escape those. But for the console logger, it will render the newlines so logs won't be consistently one-per-line in that case, typically because of a stack trace. But to be fair, Go may write out panic logs which have newlines in them too so I don't think there's really a reasonable expectation that the console logger actually does have a one-per-line guarantee.

[flga]

We're in the process of replacing nginx with caddy and I got "bitten" by this yesterday.
Tried to fiddle with fpm config but came to the conclusion that anything but handling it in caddy or the app itself would be insufficient due to the lack of context in fpm logs. Editing the php app is not really an option for us, so I started digging and drafting up what it could like.

Found this issue while preparing to open a PR.

I disagree with the noise argument, afaict (not a php dev) users can configure what php logs (from notices to errors). If the logs are chatty that's up to the user to fix, not us. If they're chatty even when exclusively logging errors then it's just a broken app.

I sympathize with trying not to fill up disk space. In an ideal world this would not be a factor, errors should be exceptional, logs should be rotated, and storage should be monitored. Given we don't live in such a world, I think having it behind a flag is the way to go. It seems reasonable to assume that the people who wouldn't find this option are people who wouldn't be looking at the error logs anyway, and it should be a small price to pay for people who do care about monitoring.

It seems to me newlines wouldn't be a problem, as long as they're going through a zap field they should be escaped, be it the json or console encoder.

It's such a trivial change that I don't think it's worth opening a PR before we come to a conclusion, but for reference this is what I had drafted up before finding this issue:

diff --git a/modules/caddyhttp/reverseproxy/fastcgi/client.go b/modules/caddyhttp/reverseproxy/fastcgi/client.go
index 0fdcbfee..7726b750 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
@@ -400,9 +403,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("msg", stderr))
+	} else {
+		f.logger.Warn("stderr", zap.ByteString("msg", stderr))
+	}
+	return f.FCGIClient.rwc.Close()
+}
 
 // Request returns a HTTP Response with Header and Body
 // from fcgi responder
@@ -442,9 +460,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 313f4ebd..4236b561 100644
--- a/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go
+++ b/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go
@@ -108,6 +108,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,8 +137,12 @@ func (t Transport) RoundTrip(r *http.Request) (*http.Response, error) {
 		address = dialInfo.Address
 	}
 
+	loggableReq := caddyhttp.LoggableHTTPRequest{
+		Request:              r,
+		ShouldLogCredentials: server.Logs != nil && server.Logs.ShouldLogCredentials,
+	}
 	t.logger.Debug("roundtrip",
-		zap.Object("request", caddyhttp.LoggableHTTPRequest{Request: r}),
+		zap.Object("request", loggableReq),
 		zap.String("dial", address),
 		zap.Object("env", env),
 	)
@@ -146,6 +152,10 @@ 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)
 	}
+	fcgiBackend.logger = t.logger.With(
+		zap.Object("request", loggableReq),
+		zap.Object("env", env),
+	)
 	// fcgiBackend gets closed when response body is closed (see clientCloser)
 
 	// read/write timeouts
... (5 lines left)

Since I was looking at it anyway, I addressed some things that looked out of place. Namely, Roundtrip was not honoring ShouldLogCredentials and we were passing a NopCloser to the Reader field of clientCloser which is a noop. I think we can ignore those for now and focus on the logging bit.

Let me know what you think, I'd like to get this done sooner rather than later but if push comes to shove I can live with a short fork.

[mholt]

@flga Oh, that's awesome. Thanks for the patch set. At a glance it LGTM, but a full review could be conducted in a PR.

I know @francislavoie is busy lately getting slides ready for his Caddy talk at API Platform Conference 2022 (woohoo!) but I'll happily wait for his thoughts on this too.

@WeidiDeng That patch will likely conflict with your PR, #4978 -- just FYI.