/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
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
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:
/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)
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:
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:
/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 the application’s error now can be seen 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)"
[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('***...')"