"Unable to start server" on Amazon Linux AMI (works with 5.7)

[Kezzo]

When starting a mysql container with version 8.0.19 (lastest) the container is getting killed after a few seconds due to the following error taken from docker logs:

2020-01-18 20:47:27+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian9 started.
2020-01-18 20:47:27+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2020-01-18 20:47:27+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian9 started.
2020-01-18 20:47:27+00:00 [Note] [Entrypoint]: Initializing database files
2020-01-18T20:47:27.611286Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 1024 (requested 8161)
2020-01-18T20:47:27.611290Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 431 (requested 4000)
2020-01-18T20:47:27.611496Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2020-01-18T20:47:27.612138Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.19) initializing of server in progress as process 45
2020-01-18T20:47:30.175390Z 5 [Warning] [MY-010453] [Server] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2020-01-18 20:47:33+00:00 [Note] [Entrypoint]: Database files initialized
2020-01-18 20:47:33+00:00 [Note] [Entrypoint]: Starting temporary server
2020-01-18T20:47:33.787410Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 1024 (requested 8161)
2020-01-18T20:47:33.787416Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 431 (requested 4000)
2020-01-18T20:47:34.153759Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2020-01-18T20:47:34.164041Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.19) starting as process 95
2020-01-18T20:47:34.208281Z 0 [ERROR] [MY-010946] [Server] Failed to start mysqld daemon. Check mysqld error log.
2020-01-18 20:47:34+00:00 [ERROR] [Entrypoint]: Unable to start server.

It works locally on a mac os system.
The exact linux ami is: amzn2-ami-ecs-hvm-2.0.20191212-x86_64-ebs (ami-027078d981e5d4010)

It is easily reproducable by running the follow command on an ec2 instance:
docker run -e MYSQL_ROOT_PASSWORD=my-secret-pw -d mysql

When running the same command but locking the version to 5.7 it does work:
docker run -e MYSQL_ROOT_PASSWORD=my-secret-pw -d mysql:5.7

[wglambert]

Try running it with --security-opt apparmor=unconfined to see if Apparmor is intervening.

[Kezzo]

When starting the container with the following command you suggested:
docker run -e MYSQL_ROOT_PASSWORD=my-secret-pw -d --security-opt apparmor=unconfined mysql

The following log output can be seen:

2020-01-20 19:39:38+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian9 started.
2020-01-20 19:39:38+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2020-01-20 19:39:38+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian9 started.
2020-01-20 19:39:38+00:00 [Note] [Entrypoint]: Initializing database files
2020-01-20T19:39:38.994914Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 1024 (requested 8161)
2020-01-20T19:39:38.994919Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 431 (requested 4000)
2020-01-20T19:39:38.995172Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2020-01-20T19:39:38.996082Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.19) initializing of server in progress as process 45
2020-01-20T19:39:41.913722Z 5 [Warning] [MY-010453] [Server] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2020-01-20 19:39:44+00:00 [Note] [Entrypoint]: Database files initialized
2020-01-20 19:39:44+00:00 [Note] [Entrypoint]: Starting temporary server
2020-01-20T19:39:44.960694Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 1024 (requested 8161)
2020-01-20T19:39:44.960699Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 431 (requested 4000)
2020-01-20T19:39:45.291522Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2020-01-20T19:39:45.292898Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.19) starting as process 95
2020-01-20T19:39:45.337126Z 0 [ERROR] [MY-010946] [Server] Failed to start

It looks like Apparmor is not intervening and the is not problem there.

I tried to double check the apparmor profile of the container process with the following bash script:

cd /
cid="$(docker run -e MYSQL_ROOT_PASSWORD=my-secret-pw -d --security-opt apparmor=unconfined mysql)"
pid=`docker inspect -f '{{.State.Pid}}' "$cid"`
cat `/proc/"$pid"/attr/current`

But go the following output:
get-apparmor.sh: line 4: /proc/23576/attr/current: Permission denied

[wglambert]

It seems kind of similar to other corrupted image issues we've had before, could you try a docker image rm 3a5e53f63281

My other thought is that the warnings are actually issues, and they're constrained by the ulimit, similar to #598
So maybe docker run -d --ulimit nofile=4096:4096 --name mysql -e MYSQL_ROOT_PASSWORD=my-secret-pw mysql will work

But otherwise I can't reproduce the issue, although I haven't tried on an ec2 server. And there's only about three other similar issues
Of which:
https://bugs.mysql.com/bug.php?id=88065 Seems very similar to your issue, (not our image though)
#332 wasn't our image
#434 volume/permission issue

[Kezzo]

It seems kind of similar to other corrupted image issues we've had before, could you try a docker image rm 3a5e53f63281

I reproduced the issue mutliple times after doing a docker system prune -a and re-pulling the image again, so I don't think a corrupted image is the problem.

My other thought is that the warnings are actually issues, and they're constrained by the ulimit, similar to #598
So maybe docker run -d --ulimit nofile=4096:4096 --name mysql -e MYSQL_ROOT_PASSWORD=my-secret-pw mysql will work

I ran the image with the ulimit parameter and got the following log:

2020-01-23 19:06:27+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian9 started.
2020-01-23 19:06:27+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2020-01-23 19:06:27+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian9 started.
2020-01-23 19:06:27+00:00 [Note] [Entrypoint]: Initializing database files
2020-01-23T19:06:27.384034Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 4096 (requested 8161)
2020-01-23T19:06:27.384040Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 1967 (requested 4000)
2020-01-23T19:06:27.384295Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2020-01-23T19:06:27.384928Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.19) initializing of server in progress as process 44
2020-01-23T19:06:30.054212Z 5 [Warning] [MY-010453] [Server] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2020-01-23 19:06:33+00:00 [Note] [Entrypoint]: Database files initialized
2020-01-23 19:06:33+00:00 [Note] [Entrypoint]: Starting temporary server
/usr/local/bin/docker-entrypoint.sh: line 88:    94 Killed                  "$@" --daemonize --skip-networking --socket="${SOCKET}"
2020-01-23 19:06:34+00:00 [ERROR] [Entrypoint]: Unable to start server.

I checked the issues you linked, but, as you said, they're just related and I couldn't find a fix in those.

[wglambert]

Curiously your error is changing. When you did an unconfined apparmor profile you lost the line [Server] Failed to start mysqld daemon. Check mysqld error log.

And when you upped the ulimit you gained

/usr/local/bin/docker-entrypoint.sh: line 88:   94 Killed    "$@" --daemonize --skip-networking --socket="${SOCKET}"

And the entrypoint logged [Entrypoint]: Unable to start server. compared to the previous mysql error [MY-010946] [Server] Failed to start

[Kezzo]

From what I understand the mysqld error log should by default be logged to the console.
Do the logs we see already include the mysqld error log or can I check them somehow?
The container immediately dies, so I can't enter bash and cat the log manually.

[RobertIndie]

It doesn't work for me too.

But when I execute this command twice, it starts successfully.
./entrypoint.sh mysqld

My log:

root@f5f4e2dc6694:/# ./entrypoint.sh mysqld
2020-04-18 15:14:12+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian10 started.
2020-04-18 15:14:13+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2020-04-18 15:14:13+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian10 started.
2020-04-18 15:14:13+00:00 [Note] [Entrypoint]: Initializing database files
2020-04-18T15:14:13.492549Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2020-04-18T15:14:13.494801Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.19) initializing of server in progress as process 42
2020-04-18T15:14:19.432689Z 5 [Warning] [MY-010453] [Server] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2020-04-18 15:14:25+00:00 [Note] [Entrypoint]: Database files initialized
2020-04-18 15:14:25+00:00 [Note] [Entrypoint]: Starting temporary server
2020-04-18T15:14:26.217602Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2020-04-18T15:14:26.222094Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.19) starting as process 92
2020-04-18T15:14:26.231203Z 0 [ERROR] [MY-010946] [Server] Failed to start mysqld daemon. Check mysqld error log.
2020-04-18 15:14:26+00:00 [ERROR] [Entrypoint]: Unable to start server.
root@f5f4e2dc6694:/# ./entrypoint.sh mysqld
2020-04-18 15:14:31+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian10 started.
2020-04-18 15:14:31+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2020-04-18 15:14:31+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.19-1debian10 started.
2020-04-18T15:14:32.833646Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2020-04-18T15:14:32.833783Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.19) starting as process 94
2020-04-18T15:14:35.187889Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2020-04-18T15:14:35.195462Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2020-04-18T15:14:35.269358Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.19'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
2020-04-18T15:14:35.430262Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/var/run/mysqld/mysqlx.sock' bind-address: '::' port: 33060

[tomplex]

Just as a point of information, I had this error and it turned out I had ~15 instances of MySQL running on that machine (something was failing to clean up). Removing them and re-trying fixed the issue.

[yosifkit]

Closing old issue. As far as I can tell, I don't think think there is anything actionable that we can change in the image.

[zhangguanzhang]

same issue, but could see the oom-killer in the dmesg --follow