Linux: PHP-FPM, Docker, STDOUT and STDERR – no an application’s error logs
Arseny Zinchenko
Posted on February 24, 2020
We have a Docker image with NGINX, PHP-FPM, and Supervisor, and we are using AWS Kubernetes Service to manage our containers.
In the same image, we have our PHP application included, which outputs its errors to the /dev/stderr as per its php.ini file:
...
[global]
error_log=/dev/stderr
...
The problem is, that if run kubectl logs – there will be no error output from the application.
So, where is the root cause? In the Docker? Kubernetes? In the Linux OS inside of the image?
Linux – stdout/stderr
Let’s recall how stdout/stderr is working in Linux.
Connect to a pod (kk here is an alias for the kubectl):
$ kk -n bttrm-application-dev-ns exec -ti bttrm-application-dev-deploy-d4d8db79-lks87 bash
bash-5.0$
In a second terminal open its logs:
$ kk -n bttrm-application-dev-ns logs -f bttrm-application-dev-deploy-d4d8db79-lks87
...
[17-Feb-2020 12:29:03] NOTICE: [pool www] child 2595 exited with code 0 after 681.391780 seconds from start
[17-Feb-2020 12:29:03] NOTICE: [pool www] child 2605 started
We can see messages from the PHP-FPM daemon but have nothing from the application.
Try to send something to the /dev/stderr and /dev/stdout channels:
bash-5.0$ echo message > /dev/stderr
message
bash-5.0$ echo message > /dev/stdout
message
Logs still are empty.
Now, let’s check where are /dev/stderr and /dev/stdout files pointed to:
bash-5.0$ ls -l /dev/stdout
lrwxrwxrwx 1 root root 15 Feb 13 15:56 /dev/stdout -> /proc/self/fd/1
bash-5.0$ ls -l /dev/stderr
lrwxrwxrwx 1 root root 15 Feb 13 15:56 /dev/stderr -> /proc/self/fd/2
/proc/self/fd/ 1 and 2 – looks correct?
Here:
-
/proc/self– a “pointer” to the calling process PID$ ls -l /proc/selflrwxrwxrwx 1 root root 0 Feb 12 11:28 /proc/self -> 3037773the 3037773 here is the PID of the/usr/bin/lsprocess - fd – file descriptor
- 1 –
STDOUT, 2 –STDERR(see the File descriptor)
Okay, and where are /proc/self/fd/1 and 2 are pointing to?
bash-5.0$ ls -l /proc/self/fd/1
lrwx------ 1 nobody nobody 64 Feb 17 12:31 /proc/self/fd/1 -> /dev/pts/0
bash-5.0$ ls -l /proc/self/fd/2
lrwx------ 1 nobody nobody 64 Feb 17 12:31 /proc/self/fd/2 -> /dev/pts/0
Check your tty (as we connected to the pod with the -t – Allocate a pseudo-tty):
bash-5.0$ tty
/dev/pts/0
Thus, everything sent via /dev/stdout will be sent to the /proc/self/fd/1 and it in its turn sends everything to the /dev/pts/0 which is our terminal, and will not be sent to the STDOUT of the Docker container and will not go through the Docker daemon and will not be passed to the host system.
So, if connect with tty – all channels will be pointed to a terminal:
root@test-env-deploy-5db5ff4d89-wwkdq:/# ls -l /proc/self/fd
total 0
lrwx------ 1 root root 64 Feb 17 12:46 0 -> /dev/pts/0
lrwx------ 1 root root 64 Feb 17 12:46 1 -> /dev/pts/0
lrwx------ 1 root root 64 Feb 17 12:46 2 -> /dev/pts/0
lr-x------ 1 root root 64 Feb 17 12:46 3 -> /proc/866/fd
Okay…
Docker STDOUT and STDERR
But what’s happening when we are running an application inside of a Docker container?
Let’s see the documentation>>>:
By default,
docker logsordocker service logsshows the command’s output just as it would appear if you ran the command interactively in a terminal. UNIX and Linux commands typically open three I/O streams when they run, calledSTDIN,STDOUT, andSTDERR.
…
The officialnginximage creates a symbolic link from/var/log/nginx/access.logto/dev/stdout, and creates another symbolic link from/var/log/nginx/error.logto/dev/stderr, overwriting the log files and causing logs to be sent to the relevant special device instead. See the Dockerfile.The official
httpddriver changes thehttpdapplication’s configuration to write its normal output directly to/proc/self/fd/1(which isSTDOUT) and its errors to/proc/self/fd/2(which isSTDERR). See the Dockerfile.
Let’s check the file descriptors in our container.
PID 1, supervisor which is used to spin up NGINX and PHP-FPM:
/app $ ls -l /proc/1/fd/1
l-wx------ 1 nobody nobody 64 Feb 17 13:24 /proc/1/fd/1 -> pipe:[21223649]
/app $ ls -l /proc/1/fd/2
l-wx------ 1 nobody nobody 64 Feb 17 13:24 /proc/1/fd/2 -> pipe:[21223650]
The pipe:[21223650] will send our data to the host-instances, the Kubernetes WorkerNodes, where we can observe them using kubectl logs (or docker logs if using common Docker).
Now, find our NGINX and PHP-FPM processes:
/app $ ps aux | grep master
8 nobody 0:00 nginx: master process nginx -g daemon off;
9 nobody 0:00 {php-fpm7} php-fpm: master process (/etc/php7/php-fpm.conf)
And where are they writing to?
NGINX:
/app $ ls -l /proc/8/fd/1
l-wx------ 1 nobody nobody 64 Feb 17 13:37 /proc/8/fd/1 -> pipe:[21224126]
/app $ ls -l /proc/8/fd/2
l-wx------ 1 nobody nobody 64 Feb 17 13:37 /proc/8/fd/2 -> pipe:[21224127]
Also to a pipe, all good here. And NGINX’s logs are available in the kubectl logs output.
Okay, and what’s with РНР?
/app $ ls -l /proc/9/fd/1
lrwx------ 1 nobody nobody 64 Feb 17 13:33 /proc/9/fd/1 -> /dev/null
/app $ ls -l /proc/9/fd/2
l-wx------ 1 nobody nobody 64 Feb 17 13:24 /proc/9/fd/2 -> pipe:[21224131]
Here:
-
stdout is sent to the
/dev/null– okay, we are more interested in the errors channel at this moment -
stderr – to the
pipe, and will go to the container’sSTDOUTand then to the Docker log-driver and to the host’ system
Let’s check processes and send something to their descriptors.
STDOUT/ERR for the Supervisor:
/app $ echo supervisor-stdout > /proc/1/fd/1
/app $ echo supervisor-stderr > /proc/1/fd/2
Logs:
kk -n bttrm-application-dev-ns logs -f bttrm-application-dev-deploy-656d9dfb69-zf6zc
2020-02-17 13:24:07,504 INFO supervisord started with pid 1
2020-02-17 13:24:08,506 INFO spawned: 'nginx' with pid 8
2020-02-17 13:24:08,508 INFO spawned: 'php-fpm' with pid 9
[17-Feb-2020 13:24:08] NOTICE: fpm is running, pid 9
[17-Feb-2020 13:24:08] NOTICE: ready to handle connections
2020-02-17 13:24:09,535 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2020-02-17 13:24:09,535 INFO success: php-fpm entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
[17-Feb-2020 13:35:00] NOTICE: [pool www] child 13 exited with code 0 after 651.735356 seconds from start
[17-Feb-2020 13:35:00] NOTICE: [pool www] child 81 started
...
supervisor-stdout
supervisor-stderr
supervisor-stdout, supervisor-stderr – output is present, all good.
Now NGINX, PID 8:
/app $ ps aux | grep master
8 nobody 0:00 nginx: master process nginx -g daemon off;
9 nobody 0:00 {php-fpm7} php-fpm: master process (/etc/php7/php-fpm.conf)
/app $ echo nginx-stdout > /proc/8/fd/1
/app $ echo nginx-stderr > /proc/8/fd/2
Logs:
...
supervisor-stdout
supervisor-stderr
nginx-stdout
nginx-stderr
And PHP – PID 9:
/app $ echo php-stdout > /proc/9/fd/1
/app $ echo php-err > /proc/9/fd/2
Logs:
...
supervisor-stdout
supervisor-stderr
nginx-stdout
nginx-stdout
nginx-stderr
php-err
php-stdout went to the /dev/null as expected, and we were able to see the stderr .
So – all good here?
But where are the application’s errors?
Check the PHP-FPM’s workers running:
/app $ ps aux | grep php
9 nobody 0:00 {php-fpm7} php-fpm: master process (/etc/php7/php-fpm.conf)
99 nobody 0:12 {php-fpm7} php-fpm: pool www
100 nobody 0:12 {php-fpm7} php-fpm: pool www
101 nobody 0:09 {php-fpm7} php-fpm: pool www
105 nobody 0:05 {php-fpm7} php-fpm: pool www
110 nobody 0:00 {php-fpm7} php-fpm: pool www
Send something to the 1 and 2 descriptions of the PID 100 – one of the FPM’s workers:
/app $ echo php-stdout > /proc/100/fd/1
/app $ echo php-stderr > /proc/100/fd/2
Check logs – but nothing is here.
Why?
Check the "direction" of those descriptors:
/app $ ls -l /proc/101/fd/1
lrwx------ 1 nobody nobody 64 Feb 17 13:55 /proc/101/fd/1 -> /dev/null
/app $ ls -l /proc/101/fd/2
lrwx------ 1 nobody nobody 64 Feb 17 13:55 /proc/101/fd/2 -> /dev/null
Errr… /dev/null? Why???
The Solution
And here we can recall the catch_workers_output FPM’s option.
Add it to thewww.conf:
[www]
listen = 9000
pm = dynamic
pm.start_servers = 5
...
clear_env = no
catch_workers_output = yes
Deploy and check:
/app $ tail -1 /etc/php7/php-fpm.d/www.conf
catch_workers_output = yes
Find a worker:
/app $ ps aux | grep www
11 nobody 0:03 {php-fpm7} php-fpm: pool www
...
And check its descriptors:
/app $ ls -l /proc/11/fd/1
l-wx------ 1 nobody nobody 64 Feb 17 14:16 /proc/11/fd/1 -> pipe:[21337244]
/app $ ls -l /proc/11/fd/2
l-wx------ 1 nobody nobody 64 Feb 17 14:16 /proc/11/fd/2 -> pipe:[21337245]
Btw, what is the pipe:[21337244] – where is it pointed to?
Check it using lsof – find the ID used with the pipe:
/app $ lsof | grep 21337244
8 /usr/sbin/php-fpm7 pipe:[21337244]
11 /usr/sbin/php-fpm7 pipe:[21337244]
PID 11 – is the worker, and PID 8 is:
/app $ ps aux | grep 8
8 nobody 0:00 {php-fpm7} php-fpm: master process (/etc/php7/php-fpm.conf)
Our PHP-FPM’s master-process.
So, catch_workers_output just opened a pipe between the FPM’s worker and its master-process, and now workers send data to the master-process, which’s output is pointed to the:
/app $ ls -l /proc/8/fd/2
l-wx------ 1 nobody nobody 64 Feb 17 15:24 /proc/8/fd/2 -> pipe:[21336668]
Find the 21336668:
/app $ lsof | grep 21336668
1 /usr/bin/python2.7 pipe:[21336668]
1 /usr/bin/python2.7 pipe:[21336668]
1 /usr/bin/python2.7 pipe:[21336668]
8 /usr/sbin/php-fpm7 pipe:[21336668]
8 /usr/sbin/php-fpm7 pipe:[21336668]
PID 1 – is our Supervisor, the very first container’s process:
/app $ ps xax | grep 1
1 nobody 0:00 {supervisord} /usr/bin/python2 /usr/bin/supervisord -c /etc/supervisor/conf.d/supervisord.conf
And from here Docker json-file log-driver intercepts messages and sends to the host's operating system makes them available for us via kubectl logs.
Let’s test – write something to the FPM’s workers process:
/app $ echo fpm-out > /proc/11/fd/1
/app $ echo fpm-err > /proc/11/fd/2
The pod’s logs:
$ kk -n bttrm-application-dev-ns logs -f bttrm-application-dev-deploy-d88598f78-r7xsw
...
2020-02-17 14:13:47,991 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2020-02-17 14:13:47,991 INFO success: php-fpm entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
[17-Feb-2020 14:17:45] WARNING: [pool www] child 11 said into stdout: "fpm-out"
[17-Feb-2020 14:17:50] WARNING: [pool www] child 11 said into stderr: "fpm-err"
And in a few moments I got our errors using kubectl logs:
$ kk -n bttrm-application-dev-ns logs -f bttrm-application-dev-deploy-d88598f78-r7xsw
...
2020-02-17 14:13:47,991 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2020-02-17 14:13:47,991 INFO success: php-fpm entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
[17-Feb-2020 14:17:45] WARNING: [pool www] child 11 said into stdout: "fpm-out"
[17-Feb-2020 14:17:50] WARNING: [pool www] child 11 said into stderr: "fpm-err"
[17-Feb-2020 14:20:15] WARNING: [pool www] child 11 said into stderr: "[2020-02-17 16:20:15] dev.ERROR: unserialize(): Error at offset 0 of 40 bytes {"exception":"[object] (ErrorException(code: 0): unserialize(): Error at offset 0 of 40 bytes at /app/vendor/laravel/framework/src/Illuminate/Encryption/Encrypter.php:149)"
[17-Feb-2020 14:20:15] WARNING: [pool www] child 11 said into stderr: "[stacktrace]"
[17-Feb-2020 14:20:15] WARNING: [pool www] child 11 said into stderr: "#0 /app/vendor/sentry/sentry/src/ErrorHandler.php(379): Illuminate\\Foundation\\Bootstrap\\HandleExceptions->handleError(8, 'unserialize(): ...', '/app/vendor/lar...', 149, Array)"
...
Done.
Similar posts
Posted on February 24, 2020
Join Our Newsletter. No Spam, Only the good stuff.
Sign up to receive the latest update from our blog.