php: PHP-FPM stderr logs cause nginx to return 502 errors to client

Hello everyone 👋

TL;DR: set fastcgi.logging = Off in your php.ini

Long explanation:

I know I’m late to the party, but this also means I’ve the advantage of having more google results available and I’m quite confident I found the real fix for what was reported by OP:

The problem with this is logs are never shown in the container’s stdout, so I changed it to:

error_log = /proc/self/fd/2

which meant that I could see the logs with docker logs -f, but I started seeing these errors on nginx

It was suggested that the log_limit “fixes” the problem, but this is only a accidental workaround which others also thought.

It is true, in case the fastcgi stderr channel contains data and is too big, nginx will act on this, this is the source code thereover where this happens in nginx https://github.com/nginx/nginx/blob/c9c3f2f005c43fd885bd78f86e1044261e639bea/src/http/modules/ngx_http_fastcgi_module.c#L1746-L1762

                ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
                              "FastCGI sent in stderr: \"%*s\"", p - msg, msg);

                flcf = ngx_http_get_module_loc_conf(r, ngx_http_fastcgi_module);

                if (flcf->catch_stderr) {
                    pattern = flcf->catch_stderr->elts;

                    for (i = 0; i < flcf->catch_stderr->nelts; i++) {
                        if (ngx_strnstr(msg, (char *) pattern[i].data,
                                        p - msg)
                            != NULL)
                        {
                            return NGX_HTTP_UPSTREAM_INVALID_HEADER;
                        }
                    }
                }

nginx has a setting to control this behaviour and it’s called fastcgi_next_upstream

Syntax: fastcgi_next_upstream error | timeout | invalid_header | http_500 | http_503 | http_403 | http_404 | http_429 | non_idempotent | off …; Default:

fastcgi_next_upstream error timeout;

Context: http, server, location

Specifies in which cases a request should be passed to the next server:

error an error occurred while establishing a connection with the server, passing a request to it, or reading the response header;

So theoretically this behaviour can also be mitigated by configuring nginx to not act that way on fastcgi errors being too large.

But the real answer is from this stackoverflow question:

I’ve been looking at the same issue, and after some trial and error, what worked for me is adding the below into the php-fpm pool configuration. I assume that the same flag could be set in other ways, such as the main php.ini file.

php_admin_flag[fastcgi.logging] = off

The relevant documentation is here: https://www.php.net/manual/en/ini.core.php#ini.fastcgi.logging

And this is IMHO the correct fix: set fastcgi.logging off in your php.ini

Turns on SAPI logging when using FastCGI. Default is to enable logging

What happens is:

• usually everyone has error_log = On and, in container environments, sends it to /dev/stdout or similar
• The default of fastcgi.logging being On means this is additionally send upstream, to nginx for many it seems
• but since people also run with another php-fpm specific setting often called catch_workers_output = yes, the error_log to stdout in PHP is already good/enough

That’s why people also see the PHP errors (warnings, notices, etc.) twice:

• once in your php-fpm container
• twice in your nginx container

Disabling does the desired thing:

• you still have your PHP error logs in php-fpm
• no logs in nginx in this regard anymore

---

In my case I was processing a GraphQL call which triggered an exception; the exception was caught inside the framework correctly and turned into a proper GraphQL JSON response. But the exception was also logged deliberately and what happen then is:

• backend sent back a HTTP 200 JSON payload with the details of the error (aka “expected behaviour”)
• nginx saw the fastcgi stderr (also being too long, see the buffer workaround) and acted upon it, turning it into a HTTP 502 error and replacing/throwing away my actual application response
• frontend was confused because instead of a JSON body it got back HTML 💥

---

Personally (though I’m not an expert on this topic), since we’re talking about the “official docker PHP” images here, I’d say it would make very much sense to either:

• disable this very setting by default or
• at least mention the setting in https://github.com/docker-library/docs/tree/master/php#configuration so ppl are more aware of it

HTH and have a nice day!

Thanks, I’ve seen this, but this is poor reasoning, in my opinion. In fact, he admits it wasn’t changed in PHP due to backwards compatibility. I think it should keep the PHP default and you can choose to override if you want, not the other way around. At the very least it should be documented that this was bumped and you will need to take that into account when pairing with nginx, because literally everyone using nginx will run into this problem at some point.

I’ve finally implemented https://github.com/docker-library/php/issues/878#issuecomment-938595965 over in #1360, but I don’t plan to let it merge until at least the new year (I’ve had a tab open to this issue for over a year now, intending to implement something 😩).

I am facing a similar issue, once too many notices come out of a request. We get a 502 from nginx.

I tried changing the following things: (in /usr/local/etc/php-fpm.d/docker.conf)

[global]
error_log = /proc/self/fd/2

To

[global]
error_log = /proc/1/fd/2

---

[www]
; if we send this to /proc/self/fd/1, it never appears
access.log = /proc/self/fd/2

To

[www]
; if we send this to /proc/self/fd/1, it never appears
access.log = /proc/1/fd/2

---

log_limit = 8192

To

log_limit = 1024

However, it did not solve the issue.

Instead of /proc/self/fd/2, try /proc/1/fd/2 (if that works, we should probably consider adjusting our default configuration too).