Имеется Docker-образ, в который включены NGINX и PHP-FPM, плюс Supervisor для их запуска.
В этот же образ включён код PHP-приложения, которое пишет ошибки PHP в /dev/stderr, как задано в php.ini:
...
[global]
error_log=/dev/stderr
...
Проблема заключается в том, что при выполнении kubectl logs — в выводе этих данных нет.
Где проблема? В Docker? Kubernetes? Linux в контейнере?
Содержание
Linux — stdout/stderr
Вспомним вообще — как работает stdout/stderr в Linux.
Подключаемся в под:
[simterm]
$ kk -n bttrm-application-dev-ns exec -ti bttrm-application-dev-deploy-d4d8db79-lks87 bash bash-5.0$
[/simterm]
Во второй консоли — открываем его логи:
[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]
Сейчас тут есть сообщения от PHP-FPM демона — но нет сообщения от приложения.
Пробуем написать в /dev/stderr:
[simterm]
bash-5.0$ echo message > /dev/stderr message bash-5.0$ echo message > /dev/stdout message
[/simterm]
В логах по-прежнему пусто.
Проверяем — куда направлены файлы:
[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 и 2 — казалось бы, всё правильно?
Тут:
/proc/self— указатель на PID вызывающего процесса:
$ ls -l /proc/self
lrwxrwxrwx 1 root root 0 Feb 12 11:28 /proc/self -> 3037773
тут 3037773 — это PID процесса с/usr/bin/ls- fd — file descriptor
- 1 —
STDOUT, 2 —STDERR(см. там же — File descriptor)
А куда смотрят /proc/self/fd/1 и 2?
[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]
Проверяем свой tty (т.к. в под подключались через -t — Allocate a pseudo-tty):
[simterm]
bash-5.0$ tty /dev/pts/0
[/simterm]
Значит всё, что шлётся в дескриптор /dev/stdout отправляется на /proc/self/fd/1, а тот, в свою очередь, на /dev/pts/0, который является нашей консолью, а не отправляется в STDOUT контейнера Docker и, соответственно, не попадает к демону Docker, который сложил бы лог на хост-машину.
Значит, при подключении к поду с tty — все каналы направляются в него:
[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]
Ну, окей…
Docker STDOUT and STDERR
А что у нас происходит при запуске процесса в контейнере самим Docker?
Смотрим документацию>>>:
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.
Проверим дексрипторы процессов в нашем контейнере.
PID 1, supervisor который запускает NGINX и 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]
pipe:[21223650] шлёт на хост-ноду, где мы видим логи в kubectl logs (или docker logs).
Находим процессы NGINX и PHP-FPM:
[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]
Куда они пишут?
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]
Тоже в pipe, тоже всё хорошо. И логи NGINX в kubectl logs мы тоже видим.
А что с РНР?
[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]
Тут:
- stdout идёт в
/dev/null— ну, окей — нас больше ошибки сейчас интересуют - stderr — в
pipe, и пойдёт вSTDOUTконтейнера, а затем в Docker log-driver
Проверяем все процессы — попробуем писать в их дескрипторы.
STDOUT/ERR для Supervisor:
[simterm]
/app $ echo supervisor-stdout > /proc/1/fd/1 /app $ echo supervisor-stderr > /proc/1/fd/2
[/simterm]
Логи:
[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 — есть аутпут.
Теперь 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]
Логи:
[simterm]
... supervisor-stdout supervisor-stderr nginx-stdout nginx-stderr
[/simterm]
И PHP — PID 9:
[simterm]
/app $ echo php-stdout > /proc/9/fd/1 /app $ echo php-err > /proc/9/fd/2
[/simterm]
Логи:
[simterm]
...
supervisor-stdout supervisor-stderr nginx-stdout nginx-stdout nginx-stderr php-err
[/simterm]
Ожидаемо — php-stdout ушёл в /dev/null, а stderr мы увидели.
Значит с всё в порядке?
Почему тогда нет ошибок от приложения?
Проверяем запущенные воркеры PHP-FPM:
[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]
Пишем в дескрипторы 1 и 2 процесса 100 — одного из FPM-воркеров:
[simterm]
/app $ echo php-stdout > /proc/100/fd/1 /app $ echo php-stderr > /proc/100/fd/2
[/simterm]
Проверяем логи — а там пусто.
А почему?
Проверяем «направление» этих дескрипторов:
[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]
А почему что все воркеры пишут в /dev/null?
Решение
И тут вспоминаем про опцию catch_workers_output.
Добавляем её в www.conf:
[www] listen = 9000 pm = dynamic pm.start_servers = 5 ... clear_env = no catch_workers_output = yes
Деплоим, проверяем:
[simterm]
/app $ tail -1 /etc/php7/php-fpm.d/www.conf catch_workers_output = yes
[/simterm]
Находим воркер:
[simterm]
/app $ ps aux | grep www
11 nobody 0:03 {php-fpm7} php-fpm: pool www
...
[/simterm]
И его дескрипторы:
[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]
А что такое pipe:[21337244] — куда он ведёт?
С помощью lsof проверяем ID, который передаётся в pipe:
[simterm]
/app $ lsof | grep 21337244 8 /usr/sbin/php-fpm7 pipe:[21337244] 11 /usr/sbin/php-fpm7 pipe:[21337244]
[/simterm]
PID 11 — наш воркер, а PID 8:
[simterm]
/app $ ps aux | grep 8
8 nobody 0:00 {php-fpm7} php-fpm: master process (/etc/php7/php-fpm.conf)
[/simterm]
Наш мастер-процесс.
Значит, catch_workers_output просто открыл pipe между воркером FPM, и его мастер-процессом: данные из воркера теперь отправляются в мастер-процесс, а от него, в свою очередь, в:
[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]
Находим 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 — наш Supervisor, первый процесс контейнера:
[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]
И уже его данные Docker json-file лог-драйвер перехватывает и выводит нам в kubectl logs.
Проверим — запишем что-то в дескриптор FPM-воркера:
[simterm]
/app $ echo fpm-out > /proc/11/fd/1 /app $ echo fpm-err > /proc/11/fd/2
[/simterm]
Логи пода:
[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]
Думал добавить какую-то ошибку, что бы увидеть реальные ошибки — но не пришлось, «поломалось» само:
[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]
Готово.
