Прим. перев.: в процессе поиска решения проблемы с логированием медленных запросов MySQL наткнулся на довольно познавательную статью. Её автор не только в деталях описывает своё расследование, которое может оказаться полезным для начинающих администраторов, но и попутно пробуждает чувства ностальгии по эпохе VT100.

Краткое содержание:

  • MySQL работает под пользователем mysql без root-прав.

  • Контейнер Docker использует Alpine, само собой. А как иначе?

  • Попытка сделать так, чтобы пользователи без root-прав могли записывать в /dev/stderr и /dev/stdout, похоже, провалилась.

  • Впервые в 2020 году выпадает снег в Нью-Йорке (веская причина, ага).

  • Пишу еще одну статью на Medium, к которой непременно вернусь в будущем.

  • TL;DR: достичь желаемого результата (писать slow-логи в stdio) так и не удалось. Тем не менее, в конце статьи упомянуты некоторые альтернативы. В поисках решения рекомендую переходить сразу в конец, ибо основная часть этой истории (как обычно это бывает) посвящена именно процессу, которым я и спешу поделиться с вами.

Сначала краткая предыстория. Я пытался сделать так, чтобы логи медленных запросов в MySQL писались в /dev/stderr и их можно было бы читать с помощью простого docker-compose logs -f mysql без необходимости входить в контейнер с docker-compose exec mysql ash.

Журналы медленных запросов важны, поскольку позволяют выяснить, является ли медленный запрос причиной подвисания приложения.

С этим мы сталкиваемся постоянно — например, когда некий умник пытается провести поиск по всем существующим записям базы данных без фильтра. Да, на MacBookPro, пока его владелец потягивает соевый skinny-латте за 10 баксов в модной кофейне в центре Бушуика в Бруклине (хмм… кого-то напоминает), это сработает, но не в production. Ведь там могут быть сотни тысяч записей, если не больше.

Обычно я загружаю production-базу в локальное окружение и запускаю приложение с включенным журналом медленных запросов. Или уговариваю команду эксплуатации включить slow-логи в stage-окружении.

Что ж, пора заканчивать со введением. Вот как MySQL жалуется на невозможность записи в /dev/stderr:

2020-01-19  9:08:10 0 [ERROR] mysqld: Can't seek in file '/dev/stderr' (Errcode: 29 "Invalid seek")
2020-01-19  9:08:10 0 [ERROR] Could not use /dev/stderr for logging (error 29). Turning logging off for the whole duration of the MariaDB server process. To turn it on again: fix the cause, shutdown the MariaDB server and restart it.

Примечание: хотя термины MySQL и MariaDB используются как взаимозаменяемые, в моем контейнере работает бесплатная MariaDB с открытым исходным кодом. Так что адвокаты Ларри Эллисона могут расслабиться.

В Alpine Linux писать в stdio могут только члены группы tty.

В Alpine только root и tty могут писать в нулевое устройство псевдотелетайпов (PTS).
В Alpine только root и tty могут писать в нулевое устройство псевдотелетайпов (PTS).

Поскольку запуск процессов под root — это зло, я попытаюсь наделить соответствующими правами других пользователей (включая того, кто запускает процесс базы данных mysqld в рассматриваемом Docker-контейнере Alpine).

Пишем в stdio без root-прав в Alpine Linux: что нужно сделать?

  1. Добавить пользователя без root-прав в группу tty.

  2. Убедиться, что tty инициализирован либо docker run, либо docker-compose.

  3. Проверить, что процесс Docker действительно пытается писать логи в /dev/stdout или /dev/stderr.

Эта проблема уже ранее обсуждалась на Medium. Приведенные выше шаги базируются на идеях из этого комментария на github.com:

Они вполне успешно работают для Nginx-контейнера на основе Alpine. Однако в случае аналогичного Alpine-контейнера с MariaDB писать slow-логи в /dev/stderr почему-то не получается.

Все дальнейшие шаги, предпринятые мной для анализа данной проблемы, будут подробно документированы. Это пригодится в будущем.

Если вы не являетесь поклонником жанра ужасов и фильмов о зомби, советую пропустить последующие разделы и просто пролистать до конца, ибо они изобилуют ужасными техническими подробностями.

Обеспечиваем доступ пользователя без root-прав к stdio 

1. Проверяем, есть ли доступ к группе tty у пользователя mysql в Alpine

Заходим в созданный Docker-контейнер как пользователь mysql (без прав root). Именно этот пользователь запускает процесс базы данных в контейнере. Теперь надо проверить, был ли он включен в группу tty во время сборки. Для этого воспользуемся командой groups: она подтверждает, что пользователь является участником группы:

docker-compose run --rm --user=mysql --entrypoint=ash mysql
/ $ groups
mysql tty

Смотрим содержимое Dockerfile:

2. Убеждаемся, что tty доступен

В конфигурации Docker Compose для службы mysql необходимо указать tty: true, чтобы гарантировать, что tty будет выделен при запуске контейнеров. По умолчанию пользователи без root-прав не могут использовать tty в Alpine при запуске с docker-compose up.

Отсутствие tty оправдано, поскольку интерактивная работа с контейнером вроде как не предполагается (ведь никто в реальном времени не будет вводить команды в терминале). Скорее контейнеры будут работать в фоновом режиме самостоятельно, без прямого взаимодействия с пользователем. Однако тут есть странность: пользователю без root-прав все равно нужен tty для перенаправления вывода процесса (а, следовательно, и Docker-логов) в stdio.

Проверяем: tty выделен для пользователя без root-прав в docker-compose.yml
Проверяем: tty выделен для пользователя без root-прав в docker-compose.yml

3. Подтверждаем, что пользователь без root-прав может писать в /dev/stdout

Самый простой способ: зайти в контейнер как пользователь mysql и отправить что-нибудь в stdio:

/ $ echo "hi" > /dev/stdout
hi

Получилось!

Все разрешения есть, но MySQL по-прежнему не пишет логи в stdio

Теперь давайте зайдем в Docker-контейнер и попытаемся запустить процесс базы данных вручную, поигравшись с параметрами.

Контейнер запускается под root’ом. Именно root вызывает su-exec для запуска /usr/bin/mysqld от имени пользователя mysql, не имеющего root-прав:

su-exec mysql /usr/bin/mysqld \
--skip-name-resolve \
--skip-host-cache \
--skip-slave-start \
--debug-gdb \
--slow-query-log-file=/dev/stderr \
--slow-query-log

Это невозможно сделать из другого контейнера, потому что MySQL уже работает и использует тот же Docker-том, и находящиеся в нем файлы заблокированы MySQL-процессом.

Невозможно параллельно запустить два процесса базы данных, использующих один и тот же Docker-том
Невозможно параллельно запустить два процесса базы данных, использующих один и тот же Docker-том

Давайте остановим сервис mysql. Затем запустим отдельный контейнер и попытаемся запустить его вручную.

Отлично. Обратите внимание, что:

  • флаг --user=mysql запускает процесс от имени пользователя mysql;

  • --entrypoint=ash предотвращает фактический запуск mysql.

Ну что ж, хорошо. Даже очень хорошо. Та же самая ошибка возникает при запуске процесса базы данных вручную :

Ошибка воспроизведена. Всегда хорошо иметь возможность воспроизвести проблему вручную
Ошибка воспроизведена. Всегда хорошо иметь возможность воспроизвести проблему вручную

Вот ее полный текст:

2020-01-19  9:08:10 0 [ERROR] mysqld: Can't seek in file '/dev/stderr' (Errcode: 29 "Invalid seek")
2020-01-19  9:08:10 0 [ERROR] Could not use /dev/stderr for logging (error 29). Turning logging off for the whole duration of the MariaDB server process. To turn it on again: fix the cause, shutdown the MariaDB server and restart it.

Еще несколько наблюдений

TTY по умолчанию выделяется при запуске контейнера с помощью docker-compose run. Чтобы TTY не выделялся, необходимо явно указать флаг, так что наша проблема не в отсутствии TTY.

Взято из https://docs.docker.com/compose/reference/run/ :

-T  Disable pseudo-tty allocation. By default `docker-compose run` allocates a TTY.

Кроме того, как говорилось выше, даже если процесс базы данных запускает пользователь без root-прав, сам контейнер работает под root при запуске с помощью docker-compose up -d. Так что tty в таком контейнере в любом случае должен присутствовать (на всякий случай я дополнительно внес в compose-файл соответствующую строку).

Код системной ошибки 29

Теперь насчет этой ошибки: Errcode: 29 "Invalid seek".

Поиск по кодам системных ошибок в MariaDB не дает результата:

А как насчет прямого изменения файлов stdio?

Тоже не работает:

/ # chmod o+w /dev/stdout /dev/stderr

Напомню, что у нас Alpine, и /dev/stderr — это не просто /dev/stderr. Это ссылка, которая указывает на ссылку. Да, именно это я и хотел сказать:

«Но /dev/stdout ссылается на /proc/self/fd/1, который, в свою очередь, обычно ссылается на /dev/pts/0 или нечто подобное. Меняются именно разрешения для этой директории. В Linux, как правило, только root:tty может писать в /dev/stdout напрямую».
«Но /dev/stdout ссылается на /proc/self/fd/1, который, в свою очередь, обычно ссылается на /dev/pts/0 или нечто подобное. Меняются именно разрешения для этой директории. В Linux, как правило, только root:tty может писать в /dev/stdout напрямую».

Что ж, проверим:

Видно, что stdio ссылается на файловые дескрипторы, а файловые дескрипторы ссылаются на нулевой pts
Видно, что stdio ссылается на файловые дескрипторы, а файловые дескрипторы ссылаются на нулевой pts

И еще одна попытка:

Может ли tty читать/писать в pts/0?
Может ли tty читать/писать в pts/0?

Увы:

Пробуем старый трюк

Этот паттерн упоминается в официальной документации Docker. В нем даже есть отсылка на официальный Dockerfile для nginx.

Взято из https://docs.docker.com/config/containers/logging/ :

Официальный образ nginx создает символическую ссылку из /var/log/nginx/access.log на /dev/stdout и еще одну из /var/log/nginx/error.log на /dev/stderr, перезаписывая лог-файлы. В результате логи отправляются на соответствующее специальное устройство. См. Dockerfile.

А вот и Dockerfile, упомянутый в официальной документации Docker. Именно этот его фрагмент относится к нашей проблеме:

Создаем ссылку:

ln -sf /dev/stderr /tmp/err.log

Попробуем еще раз, на этот раз указывая на ссылку, а не на stderr напрямую:

su-exec mysql /usr/bin/mysqld \
--skip-name-resolve \
--skip-host-cache \
--skip-slave-start \
--debug-gdb \
--slow-query-log-file=/tmp/err.log \
--slow-query-log

Снова пытаемся писать slow-логи в /tmp/err.log (напомню, err.log указывает на stdio). Но все равно не получается:

Пишем в ссылку, указывающую на stdio
Пишем в ссылку, указывающую на stdio

А вот если указать реальный файл в директории, в которую пользователь без root-прав может писать (tmp), тогда все в порядке:

su-exec mysql /usr/bin/mysqld \
--skip-name-resolve \
--skip-host-cache \
--skip-slave-start \
--debug-gdb \
--slow-query-log-file=/tmp/errordotlog \
--slow-query-log
С обычным Unix-файлом все работает просто отлично!
С обычным Unix-файлом все работает просто отлично!
Вот файл slow-логов и его содержимое
Вот файл slow-логов и его содержимое

Любопытно.

Самое время для разнообразия совершить небольшой экскурс в историю...

Что такое TTY и PTS?

На одном из приведенных выше скриншотов видно, что /dev/stdio* в Alpine Linux ссылается на файловые дескрипторы /proc/self/fd/[0-2]. Затем эти файловые дескрипторы в свою очередь ссылаются на устройство /dev/pts/0. Также упоминается, что для существования pts/0tty должен быть выделен Docker’ом. Но что такое tty? И что такое pts?

TTY — сокращение от TeleType (телетайп). Их история гораздо богаче, чем может показаться, но достаточно разбить телетайпы на три большие исторические категории:

1. Телетайпы. Электромеханические устройства для кодирования, передачи, декодирования и печати сообщений на больших расстояниях с использованием телеграфии.

Источник: Wikipedia
Источник: Wikipedia

2. Телетайпы с аппаратной эмуляцией. Устройства-эмуляторы обычных телетайпов, в которых мониторы заменили обычные бумажные рулоны. Пример — Терминал VT100:

Терминал VT100. Источник: Wikipedia
Терминал VT100. Источник: Wikipedia

3. Псевдотелетайпы или телетайпы программной эмуляции. Именно это означает термин PTS (PseudoTeleTypes). Некоторые современные примеры псевдотелетайпов включают Hyper, iTerm, Cygwin, Cmd.exe и Bash для Windows.

Возвращаясь к нашей истории, проблема заключается в том, что процесс базы данных mysql не может писать в стандартный поток, который в Alpine указывает на нулевое устройство псевдотелетайпа (pts), расположенное по адресу /dev/pts/0, разновидность телетайпа.

Нет очевидного решения

Пока что похоже, что MariaDB не может писать лог ошибок в стандартный поток или конвейер.

А ведь было бы неплохо иметь возможность пересылать журналы медленных запросов (slow_query_logs) MySQL на stdio и дальше работать сними с помощью docker-compose logs -f mysql.

Важно отметить, что в реальном production-окружении эта проблема не столь актуальна, поскольку логи из разных контейнеров, скорее всего, агрегируются с помощью драйверов для журналирования во что-то вроде Logstash, Splunk или Amazon Cloudwatch.

Менее затратной альтернативой logging-драйверам является запись slow-логов в место, подходящее MariaDB (обычный файл). Специальный Bash-скрипт может извлекать эти обычные файлы из запущенного контейнера с помощью команды копирования — docker cp.

Какой смысл, спросите вы, «убить» всю субботу и воскресенье, пытаясь направить MariaDB slow-логи в stdio вместо обычного файла или внешнего процесса? Дело в том, что это соответствует сложившейся практике.

Именно этот подход я успешно применяю в контейнерах PHP-FPM и Nginx. Он же широко используется и в сообществе, о чем свидетельствует в официальная документация Docker. Кроме того, он попросту выглядит естественным, «чистым» и простым (в духе Docker).

Хотя (в зависимости от контекста) чистота и совершенство могут являться благородной целью, это не всегда желательно или даже возможно. Можно было дальше загонять себя в тупик, пытаясь добиться вывода slow-логов в stdio ... Или можно принять альтернативное решение, которое, хотя и не так красиво, но будет работать столь же хорошо, и, наконец, вспомнить о своих выходных (от коих осталось всего несколько часов). Прекрасный компромисс, на который я, пожалуй, пойду!

P.S. от переводчика

Читайте также в нашем блоге:

Комментарии (7)


  1. vesper-bot
    10.09.2021 11:28
    +9

    tl;dr stdout/stderr не умеют seek и возвращают ошибку, которую mariadb не может обработать. На то, чтобы это понять, ушло два дня.


    1. Eugeeny
      21.09.2021 02:29

      Убогая статья о том, как диагностировать плохо забитые гвозди микроскопом. В первом же куске вывода написано, что stderr не поддерживает seek(). Все, на этом можно было закончить.


  1. amarao
    10.09.2021 11:52
    +11

    По-моему в ошибке ясно написано, что случилось. Can't seek in file '/dev/stderr' (Errcode: 29 "Invalid seek")

    Мускуль хочет сделать seek (вероятнее всего, на конец файла), а /dev/stderr справедливо возражает, что конца ошибкам нет.

    Что делать? Писать патч, потому что весь интернет уверенно говорит, что нельзя из-за кривости мускуля. И дело тут не в правах.

    Альтернативно - запускать sidecart, который будет реэкспортировать локальный ротируемый файл в stderr.


    1. zevssneg Автор
      21.09.2021 02:38

      Да, так и есть. Мне показался любопытным небольшой экскурс в историю, который проводит автор, для объяснения почему это невозможно. Хотя это и отход в сторону от решения непосредственно проблемы.


  1. dolfinus
    10.09.2021 14:14
    +2

    Статья оставляет желать лучшего. Местами полно голословных утверждений и неправильных выводов.

    Однако тут есть странность: пользователю без root-прав все равно нужен tty для перенаправления вывода процесса (а, следовательно, и Docker-логов) в stdio.

    TTY нужен только для взаимодействия с пользователем в интерактивном режиме, он не является обязательной составляющей для запуска приложений-демонов, вроде СУБД.

    Без TTY внутри контейнера /proc/self/fd/{0..2} начинают ссылаться не на /dev/pts/0, а на pipe, который докер-демон на хосте сам читает и раскладывает в файлы с логами:

    В Alpine Linux писать в stdio могут только члены группы tty.

    Владельцем файловых дескрипторов процесса становится пользователь, под которым он запущен. Например, на скриншоте выше я указал пользователя для запуска контейнера с помощью опции -u, и он стал владельцем stdout, как в случае с TTY, так и без него. И он без проблем может в него писать.

    Вот только entrypoint различных СУБД, например mysql и postgres, запускаются под пользователем root. Это нужно, чтобы перед запуском непосредственно самого приложения исправить владельца папки с файлами БД и конфигами, а уже затем выполнить запуск СУБД с помощью su или sudo.

    И тут действительно можно столкнуться с issue, на которое ссылается автор - без TTY владельцем pipe будет тот пользователь, под которым был запущен корневой процесс в контейнере, т.е. root. И так как это pipe, а не файл, к нему нельзя применить chown или chmod. Поэтому приходится использовать обходной вариант с TTY и добавлением пользователя в группу tty либо выполнением chmod o+g /dev/pts/0

    Специальный Bash-скрипт может извлекать эти обычные файлы из запущенного контейнера с помощью команды копирования — docker cp

    Ага, по пути еще и изобретать свой logrotate вместо того, чтобы создать issue в репозиторий MariaDB.


  1. polar_yogi
    10.09.2021 18:05
    +4

    Гораздо быстрее скачать исходники mariadb и посмотреть в исходный код в котором происходит ошибка ( файл sql/log.cc ) Более того, легко увидеть, что в случае pipe ситуация обрабатывается и в pipe логи писать можно.

    is_fifo = my_stat(log_file_name, &f_stat, MYF(0)) &&
    MY_S_ISFIFO(f_stat.st_mode);
    ...
    if (is_fifo)
    seek_offset= 0;
    else if ((seek_offset= mysql_file_tell(file, MYF(MY_WME))))
    goto err;

    Далее, можно найти feature request для этого в жире mariadb https://jira.mariadb.org/browse/MDEV-6870 и создать подобный для character device, либо написать патч самому, либо извернуться и писать логи в pipe и настроить rsyslog, чтобы данные из пайпа отправлять куда нравится.


    1. zevssneg Автор
      21.09.2021 02:32

      Спасибо за дополнение!