Прим. перев.: в процессе поиска решения проблемы с логированием медленных запросов 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).](https://habrastorage.org/getpro/habr/upload_files/7f5/760/c73/7f5760c730e220fc326309385c4eed20.png)
Поскольку запуск процессов под root — это зло, я попытаюсь наделить соответствующими правами других пользователей (включая того, кто запускает процесс базы данных mysqld
в рассматриваемом Docker-контейнере Alpine).
Пишем в stdio без root-прав в Alpine Linux: что нужно сделать?
Добавить пользователя без root-прав в группу
tty
.Убедиться, что tty инициализирован либо
docker run
, либоdocker-compose
.Проверить, что процесс Docker действительно пытается писать логи в
/dev/stdout
или/dev/stderr
.
…
Эта проблема уже ранее обсуждалась на Medium. Приведенные выше шаги базируются на идеях из этого комментария на github.com:
![](https://habrastorage.org/getpro/habr/upload_files/b40/7a9/c8c/b407a9c8c113a4a1ce255f55a9aada40.png)
Они вполне успешно работают для 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:
![](https://habrastorage.org/getpro/habr/upload_files/4ab/c87/d2c/4abc87d2c1ada6162b59d0a1747c673e.png)
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](https://habrastorage.org/getpro/habr/upload_files/c56/e27/e63/c56e27e63c7fd9de2e6d1331ebf095d7.png)
3. Подтверждаем, что пользователь без root-прав может писать в /dev/stdout
Самый простой способ: зайти в контейнер как пользователь mysql
и отправить что-нибудь в stdio:
/ $ echo "hi" > /dev/stdout
hi
![](https://habrastorage.org/getpro/habr/upload_files/485/366/e9f/485366e9fecca13adeea6b9410efe402.png)
Получилось!
Все разрешения есть, но 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-том](https://habrastorage.org/getpro/habr/upload_files/3fe/92f/074/3fe92f074224a89b19da84924895f40a.png)
Давайте остановим сервис mysql
. Затем запустим отдельный контейнер и попытаемся запустить его вручную.
![](https://habrastorage.org/getpro/habr/upload_files/cef/321/12a/cef32112aa783c053911458bf71b7102.png)
Отлично. Обратите внимание, что:
флаг
--user=mysql
запускает процесс от имени пользователяmysql
;--entrypoint=ash
предотвращает фактический запускmysql
.
Ну что ж, хорошо. Даже очень хорошо. Та же самая ошибка возникает при запуске процесса базы данных вручную :
![Ошибка воспроизведена. Всегда хорошо иметь возможность воспроизвести проблему вручную Ошибка воспроизведена. Всегда хорошо иметь возможность воспроизвести проблему вручную](https://habrastorage.org/getpro/habr/upload_files/1af/fb6/f8d/1affb6f8dad663262be6f1e96209102b.png)
Вот ее полный текст:
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 не дает результата:
![](https://habrastorage.org/getpro/habr/upload_files/651/970/79c/65197079c0e1290eaaf0376ca276f998.png)
А как насчет прямого изменения файлов stdio?
Тоже не работает:
/ # chmod o+w /dev/stdout /dev/stderr
![](https://habrastorage.org/getpro/habr/upload_files/96a/595/708/96a595708d0a17249da8520392c2919a.png)
Напомню, что у нас 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 напрямую».](https://habrastorage.org/getpro/habr/upload_files/708/c0c/d77/708c0cd7716a552a5172b6620c9c5046.png)
Что ж, проверим:
![Видно, что stdio ссылается на файловые дескрипторы, а файловые дескрипторы ссылаются на нулевой pts Видно, что stdio ссылается на файловые дескрипторы, а файловые дескрипторы ссылаются на нулевой pts](https://habrastorage.org/getpro/habr/upload_files/5de/dd3/730/5dedd3730d170d4a25486f6ed4f628ec.png)
И еще одна попытка:
![Может ли tty читать/писать в pts/0? Может ли tty читать/писать в pts/0?](https://habrastorage.org/getpro/habr/upload_files/f92/442/d69/f92442d6945a0f73541f37f8d06d7b49.png)
Увы:
![](https://habrastorage.org/getpro/habr/upload_files/ffa/d50/36b/ffad5036b969e44fa1880504b3acbe90.png)
Пробуем старый трюк
Этот паттерн упоминается в официальной документации 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. Именно этот его фрагмент относится к нашей проблеме:
![](https://habrastorage.org/getpro/habr/upload_files/d1a/8f1/482/d1a8f148236b4514ad3b921eaac68975.png)
Создаем ссылку:
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](https://habrastorage.org/getpro/habr/upload_files/4b5/de5/42e/4b5de542e54ae582d9b92f99df8708e8.png)
А вот если указать реальный файл в директории, в которую пользователь без 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-файлом все работает просто отлично!](https://habrastorage.org/getpro/habr/upload_files/148/27e/88e/14827e88eafedfd515f5a44121e3d1a6.png)
![Вот файл slow-логов и его содержимое Вот файл slow-логов и его содержимое](https://habrastorage.org/getpro/habr/upload_files/c05/860/160/c05860160e494be059c396e603638459.png)
Любопытно.
Самое время для разнообразия совершить небольшой экскурс в историю...
Что такое TTY и PTS?
На одном из приведенных выше скриншотов видно, что /dev/stdio*
в Alpine Linux ссылается на файловые дескрипторы /proc/self/fd/[0-2]
. Затем эти файловые дескрипторы в свою очередь ссылаются на устройство /dev/pts/0
. Также упоминается, что для существования pts/0
— tty должен быть выделен Docker’ом. Но что такое tty? И что такое pts?
TTY — сокращение от TeleType (телетайп). Их история гораздо богаче, чем может показаться, но достаточно разбить телетайпы на три большие исторические категории:
1. Телетайпы. Электромеханические устройства для кодирования, передачи, декодирования и печати сообщений на больших расстояниях с использованием телеграфии.
![Источник: Wikipedia Источник: Wikipedia](https://habrastorage.org/getpro/habr/upload_files/06a/b1d/83b/06ab1d83bd21f520d7051f0c502e2c8f.jpeg)
2. Телетайпы с аппаратной эмуляцией. Устройства-эмуляторы обычных телетайпов, в которых мониторы заменили обычные бумажные рулоны. Пример — Терминал VT100:
![Терминал VT100. Источник: Wikipedia Терминал VT100. Источник: Wikipedia](https://habrastorage.org/getpro/habr/upload_files/185/6a6/5e1/1856a65e18040452a54dc5eb6f4095d5.jpeg)
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. от переводчика
Читайте также в нашем блоге:
«Практические истории из наших SRE-будней. Часть 2» (см. историю №1. «Kafka и переменные от Docker’a в K8s»);