MySQL cannot write slow logs to /dev/stderr

On this weekend’s adventure:

• MySQL is running as a non-root user, under the name of mysql .
• The Docker container is running Alpine, obviously, nay, righteously.
• The usual steps taken to make sure non-root users can write to /dev/stderr and /dev/stdout seem to be failing pretty hard.
• It snows in New York City for the first time in 2020, on the third week of January (totally related).
• I write yet another Medium article with my future self as the main audience.
• TL;DR: I do not achieve the outcome I am pursuing (writing slow logs to stdio). However, I mention some alternatives at the end of my story. If you’re looking for the solution and not the journey, skip all the way to the end of the story — most of this story (as typical of my stories) is all about the journey. Since I’m in it, why not share it while I’m at it?

[Top image credit: Wikipedia]

This is the provenance of today’s story. I’ve been trying to set up the slow query logs in MySQL to write to /dev/stderr so that I can print them with docker-compose logs -f mysql , instead of having to log into the container and view them with docker-compose exec mysql ash .

As an engineer, slow query logs matter because when the application is non-responsive, the slow logs tell me if a slow query is the culprit for slowing down the application.

It happens all the time, such as when a fellow engineer writes a query to search for all database records in existence without a filter. It may work great from his local MacBookPro inside a $10 dollar skinny soy latte artisan coffee shop in the middle of Bushwick, Brooklyn (maybe I’m looking at the mirror here) … but not so much in production. There might be hundreds of thousand records there, if not more.

Typically I’d download the production database to my local environment and run the application with the slow query logs enabled. Or work with the ops team to get the slow logs enabled in a stage like environment.

Parting with introductions, here’s the MySQL complaining that it cannot write to /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.

Also note that even though I’m going to be using the terms MySQL and MariaDB interchangeably, my container is running the free open-source MariaDB. Not the Larry Ellison-branded, MySQL barrister edition.

In Alpine Linux, writing to stdio is reserved for members of the group tty .

In Alpine, only root and tty can write to pseudo-teletypes (PTS) device zero.

Since running processes as root is evil, here are my battle-tested steps to ensure non-root users, such as the one I’m using to run the mysqld database process in my Alpine Docker container.

Steps to ensure non-root writes to stdio in Alpine Linux

1. Add non-root user to group tty .
2. Ensure tty is provisioned either via docker run or docker-compose .
3. Ensure Docker process is in fact attempting to write logs to /dev/stdout or /dev/stderr .

…

I’ve covered this issue before here on Medium. The source of those steps can be traced to this comment on github.com:

Credit: github

Right now, following this recipe has been working for me in my Nginx container, also using Alpine.

After following these steps on my Alpine container, I can’t still get MariaDB to write the slow logs to /dev/stderr .

During the rest of this story, I’m going to be re-tracing or documenting all the steps I took to analyze this problem for future reference.

If you’re not a fan of the gore or zombie movie genres, I suggest you skip this section and just scroll all the way to the end. It is gory with technical details.

Confirming non-root user access to stdio

1. Check non-root user mysql has access to Alpine group tty

I log in to the built Docker container as the non-root user mysql . This is the user running the database process in the container. I check that the user was made part of the tty group as part of the build process using the command groups , which successfully confirms that the user is in fact part of the group tty .

Check:

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

And in the Dockerfile:

Check.

2. Ensure tty is provisioned

In my Docker Compose declaration for the mysql service I specify tty: true , in order to ensure that tty is allocated when the containers are spun up. By default, tty is not allocated for non-root users when using docker-compose up and using Alpine.

Not allocating tty kinda makes sense since the containers aren’t expected to be run interactively, meaning with someone typing commands in real-time in a terminal — rather the expectation is that the containers will run headless in the background without direct user interaction. However the quirk comes from the fact that the non-root user still needs tty allocated in order to forward process output into stdio, and therefore the Docker logs.

Confirmed: tty is allocated for non-root user in docker-compose.yml

Check.

3. Ensure current non-root user can write to /dev/stdout

As a quick smoke-test, I log in to the container as the non-root user mysql and successfully attempt to write to stdio, also as the user mysql :

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

Check.

All permissions verified, MySQL still refusing to write log to stdio

As the next troubleshooting step, I am going to log in to the Docker container itself and attempt to run the database process manually using varying options.

When the container is run, it is run as the user root . It is the user root who then invokes su-exec to run the database process /usr/bin/mysqld as non-root user mysql :

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

Can’t do that from a separate container because MySQL is already running and using the same Docker named volume, therefore the process’s files are locked.

Cant run two database processes at once using the same Docker volume

Let me stop the mysql service. Then start my own container, and attempt to run it manually from there.

Success. Notice that I am:

• Running as mysql user using the --user=mysql flag.
• I am preventing the mysql process from starting by specifying --entrypoint=ash .

This is good. This is very good. I am able to reproduce the same error, when I start the database process manually:

Error reproduced. Being able to manually reproduce the issue is always a good thing.

The full error is:

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.

Some more research

When starting a container from docker-compose run , by default a TTY is allocated. Like, you have to explicitly specify a flag for TTY not to be allocated when using run , so a missing TTY can’t be the issue at hand.

From https://docs.docker.com/compose/reference/run/:

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

Additionally, as I stated before — even though the database process is being run by a non-root user, the container itself is running as root when spun up by docker-compose up -d , so tty should be allocated there as well, but I still declare it in the compose file just in case while troubleshooting this issue.

System Error Code 29

About that Errcode: 29 "Invalid seek" :

The Operating System Error Codes guide at MariaDB doesn’t offer much advice https://mariadb.com/kb/en/operating-system-error-codes/:

What about directly modifying stdio files?

That didn’t work either:

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

Since this is Alpine, it’s the Docker container equivalent of saying this is Sparta. /dev/stderr is not simply /dev/stderr . It’s a link, that points to a link. Yes. I meant to say that:

Credit: github

Because the proof’s in the pudding:

stdio links to file descriptors, file descriptors link to pts zero

And another attempt:

Confirmed tty has read-write to pts/0

Nope:

Trying an old hat trick

This pattern is referenced in the official Docker documentation, and in turn references to the official Nginx Dockerfile.

From https://docs.docker.com/config/containers/logging/:

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.

And here’s the Dockerfile mentioned in the official Docker docs for reference: https://github.com/nginxinc/docker-nginx/blob/8921999083def7ba43a06fabd5f80e4406651353/mainline/jessie/Dockerfile#L21-L23

The tidbit pertinent to the issue at hand:

Create link:

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

Then attempt again, this time pointing at the link instead of the stderr directly:

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

If I attempt to write the slow log to /tmp/err.log , where err.log points to stdio, it still fails:

Writing to a link that points to stdio

But if I specify an actual file in a directory the non-root user can write to ( tmp ), then all’s fine:

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

But a regular unix file works just fine!

Here’s the regular slow log file and it’s contents

Interesting.

Since this isn’t going anywhere anytime soon, let‘s take a short detour down memory lane for a change.

What the heck is TTY and PTS?

In one of the screenshots above, I show that in Alpine Linux /dev/stdio* links to file descriptors/proc/self/fd/[0-2] . These file descriptors then in turn link to the /dev/pts/0 device. I also mention that in order for pts/0 to exist tty must be allocated by Docker. But what in the world is tty? What is pts?

TTY is short for TeleType. The history is a bit more exhaustive than this, but you can think of teletypes as three big historical categories:

1. Teleprinters. Electro-mechanical devices for encoding, transmitting, decoding, and printing messages over long distances using telegraphy.

Source: wikipedia

2. Hardware-emulated teletypes. Devices that emulated the previous teleprinters, but used monitors instead of paper rolls. The VT100 terminal is an example.

VT100 terminal. Source: wikipedia

3. Pseudo-teletypes, or software-emulated teletypes. This is what the term PTS stands for. Some modern examples of PseudoTeletypes include Hyper, iTerm, Cygwin, Cmd.exe, and Bash for Windows.

Tying this back to this story, the issue at hand described sans-acronyms is that the database process mysqld is having trouble writing to standard error, which in Alpine points to pseudo-teletype (pts) device zero located at /dev/pts/0, a type of teletype.

No Clean Solution

So far it looks like MariaDB will refuse to write the error log to a stream or pipe such as standard error.

It would be nice to be able forward MySQL slow query logs to stdio so they can be displayed by Docker using commands such as docker-compose logs -f mysql .

It bears importance to notice that in an actual production environment this would be much less of an issue since logs from different containers would be most likely aggregated via logging drivers into something like Logstash, Splunk or Amazon Cloudwatch.

A low-overhead alternative to alternate logging drivers is to write the slow logs to a place MariaDB is comfortable with (a regular file). A bash script outside of Docker container can fetch these regular files from the running container via the Docker copy command docker cp .

The whole purpose of spending an entire Saturday and Sunday attempting to write the MariaDB slow logs to stdio, as opposed to a regular file or some external process — is that it follows an established pattern.

It’s a pattern that I successfully employ in my PHP FPM and Nginx containers, it is widely used in the community as referenced by the official Docker docs, and it feels just pure — as in the simplest Docker way of doing things.

However although depending on context purity and perfection can be a noble end, it is not always desirable or even possible. I could continue down a rabbit hole trying to achieve my goals of putting the slow log into Docker’s stdio… Or, I could simply accept an alternate solution that although not as pure, will work as just as well — and give me the reminder of my weekend (a few hours left) back. A perfectly fine compromise I’m willing to accept!