Linux: PHP-FPM, Docker, STDOUT and STDERR – no an application’s error logs
Tags: docker, php, linux, todayilearned
Published: 2020-02-24 18:18:47

---
title: Linux: PHP-FPM, Docker, STDOUT and STDERR – no an application’s error logs
published: true
date: 2020-02-24 11:49:57 UTC
tags: Docker,PHP,Linux,todayilearned
canonical_url: https://rtfm.co.ua/en/linux-php-fpm-docker-stdout-and-stderr-no-an-applications-error-logs/
---

![](https://rtfm.co.ua/wp-content/uploads/2011/08/linux-logo.png)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_](https://en.wikipedia.org/wiki/File_descriptor)
3. 1 – `STDOUT`, 2 – `STDERR` (see the [File descriptor](https://en.wikipedia.org/wiki/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`](https://en.wikipedia.org/wiki/Tty_(unix)) (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>>>](https://docs.docker.com/config/containers/logging/):

> 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](https://github.com/nginxinc/docker-nginx/blob/8921999083def7ba43a06fabd5f80e4406651353/mainline/jessie/Dockerfile#L21-L23).
> 
> 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](https://github.com/docker-library/httpd/blob/b13054c7de5c74bbaa6d595dbe38969e6d4f860c/2.2/Dockerfile#L72-L75).

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`](https://www.php.net/manual/en/install.fpm.configuration.php#catch-workers-output) FPM’s option.

Add it to the`www.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`](https://docs.docker.com/engine/reference/run/#logging-drivers---log-driver) 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
  
- <small>02/19/2020</small> [PHP: PHP-FPM ignores environment variables – solutions](https://rtfm.co.ua/en/php-php-fpm-ignores-environment-variables-solutions/) 
- <small>04/02/2018</small> [Docker: PHP Composer и multi-stage билды Docker образов](https://rtfm.co.ua/docker-php-composer-i-multi-stage-bildy-docker-obrazov/) 
- <small>01/23/2020</small> [Debian: php7.3-curl : Depends: libcurl3 (>= 7.44.0) but it is not installable](https://rtfm.co.ua/en/debian-php7-3-curl-depends-libcurl3-7-44-0-but-it-is-not-installable-2/)