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?
Contents
Linux – stdout/stderr
Let’s recall how stdout/stderr is working in Linux.
Connect to a pod:
[simterm]
$ kk -n bttrm-application-dev-ns exec -ti bttrm-application-dev-deploy-d4d8db79-lks87 bash bash-5.0$
[/simterm]
In a second terminal open its logs:
[simterm]
$ 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
[/simterm]
We can see messages from the PHP-FPM daemon but have nothing from the application.
try to send something to the /dev/stderr:
[simterm]
bash-5.0$ echo message > /dev/stderr message bash-5.0$ echo message > /dev/stdout message
[/simterm]
Logs still are empty.
Now, let’s check where are /dev/stderr and /dev/stdout files pointed to:
[simterm]
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
[/simterm]
/proc/self/fd/ 1 and 2 – looks correct?
Here:
/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/lsprocess- fd – file descriptor
- 1 –
STDOUT, 2 –STDERR(see the File descriptor)
Okay, and where are /proc/self/fd/1 and 2 are pointed to?
[simterm]
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
[/simterm]
Check your tty (as we connected to the pod with the -t – Allocate a pseudo-tty):
[simterm]
bash-5.0$ tty /dev/pts/0
[/simterm]
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:
[simterm]
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
[/simterm]
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:
[simterm]
/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]
[/simterm]
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:
[simterm]
/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)
[/simterm]
And where are they writing to?
NGINX:
[simterm]
/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]
[/simterm]
Also to a pipe, all good here. And NGINX’s logs are available in the kubectl logs output.
Okay, and what’s with РНР?
[simterm]
/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]
[/simterm]
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:
[simterm]
/app $ echo supervisor-stdout > /proc/1/fd/1 /app $ echo supervisor-stderr > /proc/1/fd/2
[/simterm]
Logs:
[simterm]
$ 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
[/simterm]
supervisor-stdout, supervisor-stderr – otuput is present, all good.
Now NGINX, PID 8:
[simterm]
/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
[/simterm]
Logs:
[simterm]
... supervisor-stdout supervisor-stderr nginx-stdout nginx-stderr
[/simterm]
And PHP – PID 9:
[simterm]
/app $ echo php-stdout > /proc/9/fd/1 /app $ echo php-err > /proc/9/fd/2
[/simterm]
Logs:
[simterm]
...
supervisor-stdout supervisor-stderr nginx-stdout nginx-stdout nginx-stderr php-err
[/simterm]
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:
[simterm]
/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
[/simterm]
Send something to the 1 and 2 descriptions of the PID 100 – one of the FPM’s workers:
[simterm]
/app $ echo php-stdout > /proc/100/fd/1 /app $ echo php-stderr > /proc/100/fd/2
[/simterm]
Check logs – but nothing is here.
Why?
Check the “direction” of those descriptors:
[simterm]
/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
[/simterm]
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:
[simterm]
/app $ tail -1 /etc/php7/php-fpm.d/www.conf catch_workers_output = yes
[/simterm]
Find a worker:
[simterm]
/app $ ps aux | grep www
11 nobody 0:03 {php-fpm7} php-fpm: pool www
...
[/simterm]
Its descriptors:
[simterm]
/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]
[/simterm]
Btw, what is the pipe:[21337244] – where is it pointed to?
Check it using lsof – find the ID used with the pipe:
[simterm]
/app $ lsof | grep 21337244 8 /usr/sbin/php-fpm7 pipe:[21337244] 11 /usr/sbin/php-fpm7 pipe:[21337244]
[/simterm]
PID 11 – is the worker, and PID 8 is:
[simterm]
/app $ ps aux | grep 8
8 nobody 0:00 {php-fpm7} php-fpm: master process (/etc/php7/php-fpm.conf)
[/simterm]
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:
[simterm]
/app $ ls -l /proc/8/fd/2 l-wx------ 1 nobody nobody 64 Feb 17 15:24 /proc/8/fd/2 -> pipe:[21336668]
[/simterm]
Find the 21336668:
[simterm]
/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]
[/simterm]
PID 1 – is our Supervisor, the very first container’s process:
[simterm]
/app $ ps xax | grep 1
1 nobody 0:00 {supervisord} /usr/bin/python2 /usr/bin/supervisord -c /etc/supervisor/conf.d/supervisord.conf
[/simterm]
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:
[simterm]
/app $ echo fpm-out > /proc/11/fd/1 /app $ echo fpm-err > /proc/11/fd/2
[/simterm]
The pod’s logs:
[simterm]
$ 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"
[/simterm]
And the application’s error now can be seen using kubectl logs:
[simterm]
$ 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)"
[17-Feb-2020 14:20:15] WARNING: [pool www] child 11 said into stderr: "#1 [internal function]: Sentry\\ErrorHandler->handleError(8, 'unserialize(): ...', '/app/vendor/lar...', 149, Array)"
[17-Feb-2020 14:20:15] WARNING: [pool www] child 11 said into stderr: "#2 /app/vendor/laravel/framework/src/Illuminate/Encryption/Encrypter.php(149): unserialize('***...')"
[17-Feb-2020 14:20:15] WARNING: [pool www] child 11 said into stderr: "#3 /app/vendor/laravel/framework/src/Illuminate/Cookie/Middleware/EncryptCookies.php(95): Illuminate\\Encryption\\Encrypter->decrypt(Array)"
[17-Feb-2020 14:20:15] WARNING: [pool www] child 11 said into stderr: "#4 /app/vendor/laravel/framework/src/Illuminate/Cookie/Middleware/EncryptCookies.php(76): Illuminate\\Cookie\\Middleware\\EncryptCookies->decryptCookie('***...')"
...
[/simterm]
Done.
