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

We have a Docker image with NGINX, PHP-FPM, and Supervisor.

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:

In a second terminal open its logs:

We can see messages from the PHP-FPM daemon but have nothing from the application.

try to send something to the /dev/stderr:

Logs still are empty.

Now, let’s check where are /dev/stderr and /dev/stdout files pointed to:

/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 pointed to?

Check your tty (as we connected to the pod with the -t – Allocate a pseudo-tty):

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:

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:

The pipe:[21223650] will send our data to the host-instances, the Kubernetes WorkerNode, where we can observe them using kubectl logs (or docker logs if using common Docker).

Now, find our NGINX and PHP-FPM processes:

And where are they writing to?

NGINX:

Also to a pipe, all good here. And NGINX’s logs are available in the kubectl logs output.

Okay, and what’s with РНР?

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:

Logs:

supervisor-stdout, supervisor-stderr – otuput is present, all good.

Now NGINX, PID 8:

Logs:

And PHP – PID 9:

Logs:

php-stdout went to the /dev/null, 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:

Send something to the 1 and 2 descriptions of the PID 100 – one of the FPM’s workers:

Check logs – but nothing is here.

Why?

Check the “direction” of those descriptors:

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:

Find a worker:

Its descriptors:

Btw, what is the pipe:[21337244] – where is it pointed to?

Check it using lsof – find the ID used with the pipe:

PID 11 – is the worker, and PID 8 is:

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:

Find the 21336668:

PID 1 – is our Supervisor, the very first container’s process:

And from here Docker json-file log-driver intercepts messages and sends makes them available for us via  kubectl logs.

Let’s test – write something to the FPM’s workers process:

The pod’s logs:

And the application’s error now can be seen using kubectl logs:

Done.