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

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

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

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

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

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

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

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

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

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

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

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

Ну, окей…

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

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

PID 1, supervisor который запускает NGINX и PHP-FPM:

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

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

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

NGINX:

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

А что с РНР?

Тут:

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

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

STDOUT/ERR для Supervisor:

Логи:

supervisor-stdout, supervisor-stderr — есть аутпут.

Теперь NGINX, PID 8:

Логи:

И PHP — PID 9:

Логи:

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

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

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

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

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

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

А почему?

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

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

Решение

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

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

[www]

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

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

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

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

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

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

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

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

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

Находим 21336668:

А PID 1 — наш Supervisor, первый процесс контейнера:

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

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

Логи пода:

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

Готово.