Linux: PHP-FPM, Docker, STDOUT and STDERR – no an application’s error logs

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:

1. /proc/self – a “pointer” to the calling process PID $ ls -l /proc/self lrwxrwxrwx 1 root root 0 Feb 12 11:28 /proc/self -> 3037773 the 3037773 here is the PID of the /usr/bin/ls process
2. fd – file descriptor
3. 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 logs or docker service logs shows 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, called STDIN, STDOUT, and STDERR.

…

The official nginx image creates a symbolic link from /var/log/nginx/access.log to /dev/stdout, and creates another symbolic link from /var/log/nginx/error.log to /dev/stderr, overwriting the log files and causing logs to be sent to the relevant special device instead. See the Dockerfile.

The official httpd driver changes the httpd application’s configuration to write its normal output directly to /proc/self/fd/1 (which is STDOUT) and its errors to /proc/self/fd/2 (which is STDERR). 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’s STDOUT and 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

• 02/19/2020 PHP: PHP-FPM ignores environment variables – solutions
• 04/02/2018 Docker: PHP Composer и multi-stage билды Docker образов
• 01/23/2020 Debian: php7.3-curl : Depends: libcurl3 (>= 7.44.0) but it is not installable