Linux: PHP-FPM, Docker, STDOUT и STDERR — нет логов приложения

Автор: | 02/17/2020
 

Имеется 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.

Подключаемся в под:

kk -n bttrm-application-dev-ns exec -ti bttrm-application-dev-deploy-d4d8db79-lks87 bash
bash-5.0$

Во второй консоли — открываем его логи:

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

Сейчас тут есть сообщения от PHP-FPM демона — но нет сообщения от приложения.

Пробуем написать в /dev/stderr:

bash-5.0$ echo message > /dev/stderr
message
bash-5.0$ echo message > /dev/stdout
message

В логах по-прежнему пусто.

Проверяем — куда направлены файлы:

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 и 2 — казалось бы, всё правильно?

Тут:

  1. /proc/self — указатель на PID вызывающего процесса:
    $ ls -l /proc/self
    lrwxrwxrwx 1 root root 0 Feb 12 11:28 /proc/self -> 3037773
    тут 3037773 — это PID процесса с /usr/bin/ls
  2. fd — file descriptor
  3. 1 — STDOUT, 2 — STDERR (см. там же — File descriptor)

А куда смотрят /proc/self/fd/1 и 2?

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

Проверяем свой tty (т.к. в под подключались через -tAllocate a pseudo-tty):

bash-5.0$ tty
/dev/pts/0

Значит всё, что шлётся в дескриптор /dev/stdout отправляется на /proc/self/fd/1, а тот, в свою очередь, на /dev/pts/0, который является нашей консолью, а не отправляется в STDOUT контейнера Docker и, соответственно, не попадает к демону Docker, который сложил бы лог на хост-машину.

Значит, при подключении к поду с tty — все каналы направляются в него:

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

Ну, окей…

Docker STDOUT and STDERR

А что у нас происходит при запуске процесса в контейнере самим Docker?

Смотрим документацию>>>:

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 STDINSTDOUT, 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.

Проверим дексрипторы процессов в нашем контейнере.

PID 1, supervisor который запускает NGINX и 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]

pipe:[21223650] шлёт на хост-ноду, где мы видим логи в kubectl logs (или docker logs).

Находим процессы NGINX и PHP-FPM:

/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)

Куда они пишут?

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]

Тоже в pipe, тоже всё хорошо. И логи NGINX в kubectl logs мы тоже видим.

А что с РНР?

/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]

Тут:

  • stdout идёт в /dev/null — ну, окей — нас больше ошибки сейчас интересуют
  • stderr — в pipe, и пойдёт в STDOUT контейнера, а затем в Docker log-driver

Проверяем все процессы — попробуем писать в их дескрипторы.

STDOUT/ERR для Supervisor:

/app $ echo supervisor-stdout > /proc/1/fd/1
/app $ echo supervisor-stderr > /proc/1/fd/2

Логи:

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 — есть аутпут.

Теперь 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

Логи:

...
supervisor-stdout
supervisor-stderr
nginx-stdout
nginx-stderr

И PHP — PID 9:

/app $ echo php-stdout > /proc/9/fd/1
/app $ echo php-err > /proc/9/fd/2

Логи:

...
supervisor-stdout
supervisor-stderr
nginx-stdout
nginx-stdout
nginx-stderr
php-err

Ожидаемо — php-stdout ушёл в /dev/null, а stderr мы увидели.

Значит с всё в порядке?

Почему тогда нет ошибок от приложения?

Проверяем запущенные воркеры PHP-FPM:

/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

Пишем в дескрипторы 1 и 2 процесса 100 — одного из FPM-воркеров:

/app $ echo php-stdout > /proc/100/fd/1
/app $ echo php-stderr > /proc/100/fd/2

Проверяем логи — а там пусто.

А почему?

Проверяем «направление» этих дескрипторов:

/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

А почему что все воркеры пишут в /dev/null?

Решение

И тут вспоминаем про опцию catch_workers_output.

Добавляем её в www.conf:

[www]

listen = 9000
pm = dynamic
pm.start_servers = 5
...
clear_env = no
catch_workers_output = yes

Деплоим, проверяем:

/app $ tail -1 /etc/php7/php-fpm.d/www.conf
catch_workers_output = yes

Находим воркер:

/app $ ps aux | grep www
11 nobody    0:03 {php-fpm7} php-fpm: pool www
...

И его дескрипторы:

/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]

А что такое pipe:[21337244] — куда он ведёт?

С помощью lsof проверяем ID, который передаётся в pipe:

/app $ lsof | grep 21337244
8       /usr/sbin/php-fpm7      pipe:[21337244]
11      /usr/sbin/php-fpm7      pipe:[21337244]

PID 11 — наш воркер, а PID 8:

/app $ ps aux | grep 8
8 nobody    0:00 {php-fpm7} php-fpm: master process (/etc/php7/php-fpm.conf)

Наш мастер-процесс.

Значит, catch_workers_output просто открыл pipe между воркером FPM, и его мастер-процессом: данные из воркера теперь отправляются в мастер-процесс, а от него, в свою очередь, в:

/app $ ls -l /proc/8/fd/2
l-wx------    1 nobody   nobody          64 Feb 17 15:24 /proc/8/fd/2 -> pipe:[21336668]

Находим 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 — наш Supervisor, первый процесс контейнера:

/app $ ps xax | grep 1
1 nobody    0:00 {supervisord} /usr/bin/python2 /usr/bin/supervisord -c /etc/supervisor/conf.d/supervisord.conf

И уже его данные Docker json-file лог-драйвер перехватывает и выводит нам в kubectl logs.

Проверим — запишем что-то в дескриптор FPM-воркера:

/app $ echo fpm-out > /proc/11/fd/1
/app $ echo fpm-err > /proc/11/fd/2

Логи пода:

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"

Думал добавить какую-то ошибку, что бы увидеть реальные ошибки — но не пришлось, «поломалось» само:

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('***...')"
...

Готово.