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

[figassis]

I have php-fpm running on docker with the following php.ini:

memory_limit = 512M
error_reporting =  E_ALL & ~E_DEPRECATED & ~E_STRICT
display_errors = Off
display_startup_errors = Off
log_errors = On
ignore_repeated_errors = On
html_errors = Off
upload_max_filesize = 5M
post_max_size = 50M
max_input_vars = 5000
max_execution_time = 60
error_log = /var/log/php/error.log
log_level = error
catch_workers_output = yes

Everything worked and nginx was proxying perfectly. 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:

2019/08/26 17:29:35 [error] 22#0: *6 FastCGI sent in stderr: "PHP message: PHP Deprecated:  Function create_function() is deprecated in 

So some plugin in my wordpress (and I know which one it is), is using a deprecated function, but this error is non critical, its actually a notice. The problem is that with this setup, I keep getting 502 Bad Gateway errors when a client requests a page. I actually also see that php-fpm is returning them via the fast cgi protocol, when I connect do it directly.

It all starts working when I set log_errors = Off. So I read a bit and realized the fast-cgi protocol can return a FCGI_STDERR packet to its client, which includes error logs, so I decided not to go down that rabbit hole and try to cheat by doing this:

ln -sf /dev/stderr /var/log/php/error.log to make php-fpm think it was logging to a file and still have the logs show up in docker logs. No such luch, 502 only disappear is I log to /var/log/php/error.log without any connection to stdout/stderr or if I disable logging altogether.

I don't know if its my poor understanding or if this is a bug, but there should be a way to log to stdout/stderr without returning errors to nginx.

Can anyone help?

[tianon]

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

[Vandersteen]

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.

[tomsisk]

Switching log_limit to 1024 fixed this issue for me. Make sure it's under [global].

I question why this is overridden by default? It seems this decision should not be forced on the user. nginx is very commonly used with php-fpm, and does not support this limit by default (only up to 2048).

[tianon]

https://github.com/docker-library/php/pull/725#issuecomment-443540114

[tomsisk]

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.

[wollanup]

@tomsisk I ran into this point today after updating 7.0 to 7.4 php_fpm based images :)

Seems not optimal to me to change log_limit value during an image build process...

[stepanselyuk]

I use PHP-FPM 7.4 Alpine 3.12 image in conjunction with nginx:1-alpine image in one k8s pod, and they contact each other using the socket. After the pod started all going okay for a few hours but then I see nginx cannot connect to php-fpm anymore (error 500). In the logs of PHP-fpm container I see:

[preview-preview-756cfb8c75-lblcx preview] [18-Aug-2020 11:42:15] NOTICE: ready to handle connections
[preview-preview-756cfb8c75-lblcx preview] [18-Aug-2020 16:00:49] NOTICE: [pool www] child 13 exited with code 0 after 15514.912805 seconds from start
[preview-preview-756cfb8c75-lblcx preview] [18-Aug-2020 16:00:49] NOTICE: [pool www] child 16 started
[preview-preview-756cfb8c75-lblcx preview] [18-Aug-2020 16:00:59] NOTICE: [pool www] child 14 exited with code 0 after 15509.292689 seconds from start
[preview-preview-756cfb8c75-lblcx preview] [18-Aug-2020 16:00:59] NOTICE: [pool www] child 17 started
[preview-preview-756cfb8c75-lblcx preview] [18-Aug-2020 16:01:00] NOTICE: [pool www] child 15 exited with code 0 after 15508.987974 seconds from start
[preview-preview-756cfb8c75-lblcx preview] [18-Aug-2020 16:01:00] NOTICE: [pool www] child 18 started

I tried to fix /proc/self/fd/2 as /proc/1/fd/2 (in docker.conf) and also set log_limit to 1024, but it did not help.

[yosifkit]

@stepanselyuk, from some quick research, most users suggest that it may be because there is pm.max_request in php.ini. And I would guess that there could be other php ini settings that may cause them to exit as well.

We try to keep github issues focused on bugs in the image and not general deployment debugging. It likely seems not to be a problem with the image so I would suggest trying to post questions like this in the Docker Community Forums, the Docker Community Slack, or Stack Overflow.

[stepanselyuk]

Hi @yosifkit, thank you. Seems I found the underlying issue: I write logs and cache to /dev/shm (in local dev-containers) and forgot to change this logic. So after exactly ~4 hours the size of the /dev/shm reached 64M and that caused the issue.

[aldas]

I'm having same problem here php:7.4.9-fpm-alpine does not output PHP logs to docker. I do not know what has changed, but 2 months ago built image was working (used php:7.4.3-fpm-alpine that time)

After trying different things seems that outputting logs to /proc/1/fd/2 (instead of /proc/self/fd/2) seems to work

so I added currently to my dockerfile

RUN sed -i 's/\/proc\/self\/fd\/2/\/proc\/1\/fd\/2/g' /usr/local/etc/php-fpm.d/docker.conf

My Docker version on Ubuntu 20.04

Client: Docker Engine - Community
 Version:           19.03.11
 API version:       1.40
 Go version:        go1.13.10
 Git commit:        42e35e61f3
 Built:             Mon Jun  1 09:12:23 2020
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          19.03.11
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.13.10
  Git commit:       42e35e61f3
  Built:            Mon Jun  1 09:10:55 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.2.13
  GitCommit:        7ad184331fa3e55e52b890ea95e65ba581ae3429
 runc:
  Version:          1.0.0-rc10
  GitCommit:        dc9208a3303feef5b3839f4323d9beb36df0a9dd
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683