search

docker-library / mysql

Docker Official Image packaging for MySQL Community Server
https://dev.mysql.com/
GNU General Public License v2.0
2.47k stars 2.2k forks source link

mysql 8.0.33 fails on Fly.io but works with 8.0.32 #967

Open fideloper opened 1 year ago

fideloper commented 1 year ago

Hi!

I work at Fly.io, where we convert Docker images to Firecracker VM's. This has worked great for MySQL users until the current (as I write this) release of MySQL.

The current tag mysql:8 (which is mysql:8.0.33) fails during the Entrypoint execution, with no error message. However this works on my local Docker.

Here's what I see in version 8.0.33 output in Fly:

fly m run mysql:8.0.33 \
    -a some-fly-team --cpus 1 --memory 2048 --region ewr \
    -e "MYSQL_DATABASE=my_db" \
    -e "MYSQL_PASSWORD=secret" \
    -e "MYSQL_ROOT_PASSWORD=secret" \
    -e "MYSQL_USER=my_user"
👉 view log output of failing run (8.0.33) 
2023-04-18T00:30:06Z app[9185ee3c792383] ewr [info]Starting init (commit: ed64554)...
2023-04-18T00:30:06Z app[9185ee3c792383] ewr [info]Preparing to run: `docker-entrypoint.sh mysqld` as root
2023-04-18T00:30:06Z app[9185ee3c792383] ewr [info]2023/04/18 00:30:06 listening on [fdaa:1:40e4:a7b:21a1:b5fe:357b:2]:22 (DNS: [fdaa::3]:53)
2023-04-18T00:30:06Z app[9185ee3c792383] ewr [info]2023-04-18 00:30:06+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.33-1.el8 started.
2023-04-18T00:30:07Z app[9185ee3c792383] ewr [info]Starting clean up.
2023-04-18T00:30:08Z app[9185ee3c792383] ewr [info][    2.133634] reboot: Restarting system
2023-04-18T00:30:10Z app[9185ee3c792383] ewr [info]Starting init (commit: ed64554)...
2023-04-18T00:30:10Z app[9185ee3c792383] ewr [info]Preparing to run: `docker-entrypoint.sh mysqld` as root
2023-04-18T00:30:10Z app[9185ee3c792383] ewr [info]2023/04/18 00:30:10 listening on [fdaa:1:40e4:a7b:21a1:b5fe:357b:2]:22 (DNS: [fdaa::3]:53)
2023-04-18T00:30:10Z app[9185ee3c792383] ewr [info]2023-04-18 00:30:10+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.33-1.el8 started.
2023-04-18T00:30:11Z app[9185ee3c792383] ewr [info]Starting clean up.
2023-04-18T00:30:12Z app[9185ee3c792383] ewr [info][    2.132792] reboot: Restarting system
2023-04-18T00:30:13Z app[9185ee3c792383] ewr [info]Starting init (commit: ed64554)...
2023-04-18T00:30:13Z app[9185ee3c792383] ewr [info]Preparing to run: `docker-entrypoint.sh mysqld` as root
2023-04-18T00:30:13Z app[9185ee3c792383] ewr [info]2023/04/18 00:30:13 listening on [fdaa:1:40e4:a7b:21a1:b5fe:357b:2]:22 (DNS: [fdaa::3]:53)
2023-04-18T00:30:13Z app[9185ee3c792383] ewr [info]2023-04-18 00:30:13+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.33-1.el8 started.
2023-04-18T00:30:14Z app[9185ee3c792383] ewr [info]Starting clean up.
2023-04-18T00:30:15Z app[9185ee3c792383] ewr [info][    2.138144] reboot: Restarting system
2023-04-18T00:30:16Z app[9185ee3c792383] ewr [info]2023/04/18 00:30:16 listening on [fdaa:1:40e4:a7b:21a1:b5fe:357b:2]:22 (DNS: [fdaa::3]:53)
2023-04-18T00:30:16Z app[9185ee3c792383] ewr [info]2023-04-18 00:30:16+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.33-1.el8 started.
2023-04-18T00:30:17Z app[9185ee3c792383] ewr [info]Starting clean up.
2023-04-18T00:30:18Z app[9185ee3c792383] ewr [info][    2.135679] reboot: Restarting system
2023-04-18T00:30:21Z app[9185ee3c792383] ewr [info]Starting clean up

The entrypoint script is exiting with some non-zero status code, and Fly is rebooting it. It goes until it hits the max restart limit (defaulting to 10).

Version 8.0.32 does not do this, and works as you'd expect:

fly m run mysql:8.0.32 \
    -a some-fly-team --cpus 1 --memory 2048 --region ewr \
    -e "MYSQL_DATABASE=my_db" \
    -e "MYSQL_PASSWORD=secret" \
    -e "MYSQL_ROOT_PASSWORD=secret" \
    -e "MYSQL_USER=my_user"
👉 view log output of successful run (8.0.32) 
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]Starting init (commit: ed64554)...
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]Preparing to run: `docker-entrypoint.sh mysqld` as root
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]2023/04/18 00:29:02 listening on [fdaa:1:40e4:a7b:ce:414e:3b11:2]:22 (DNS: [fdaa::3]:53)
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]2023-04-18 00:29:02+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.32-1.el8 started.
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]2023-04-18 00:29:02+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]2023-04-18 00:29:02+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.32-1.el8 started.
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]2023-04-18 00:29:02+00:00 [Note] [Entrypoint]: Initializing database files
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]2023-04-18T00:29:02.659391Z 0 [Warning] [MY-011068] [Server] The syntax '--skip-host-cache' is deprecated and will be removed in a future release. Please use SET GLOBAL host_cache_size=0 instead.
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]2023-04-18T00:29:02.659604Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.32) initializing of server in progress as process 591
2023-04-18T00:29:02Z app[91857775f1d308] ewr [info]2023-04-18T00:29:02.667692Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2023-04-18T00:29:03Z app[91857775f1d308] ewr [info]2023-04-18T00:29:03.049568Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2023-04-18T00:29:03Z app[91857775f1d308] ewr [info]2023-04-18T00:29:03.986375Z 6 [Warning] [MY-010453] [Server] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2023-04-18T00:29:05Z app[91857775f1d308] ewr [info]2023-04-18 00:29:05+00:00 [Note] [Entrypoint]: Database files initialized
2023-04-18T00:29:05Z app[91857775f1d308] ewr [info]2023-04-18 00:29:05+00:00 [Note] [Entrypoint]: Starting temporary server
2023-04-18T00:29:06Z app[91857775f1d308] ewr [info]2023-04-18T00:29:06.095803Z 0 [Warning] [MY-011068] [Server] The syntax '--skip-host-cache' is deprecated and will be removed in a future release. Please use SET GLOBAL host_cache_size=0 instead.
2023-04-18T00:29:06Z app[91857775f1d308] ewr [info]2023-04-18T00:29:06.098734Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.32) starting as process 633
2023-04-18T00:29:06Z app[91857775f1d308] ewr [info]2023-04-18T00:29:06.112757Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2023-04-18T00:29:06Z app[91857775f1d308] ewr [info]2023-04-18T00:29:06.363615Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2023-04-18T00:29:06Z app[91857775f1d308] ewr [info]2023-04-18T00:29:06.598917Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to suppo
2023-04-18T00:29:06Z app[91857775f1d308] ewr [info]2023-04-18T00:29:06.598917Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2023-04-18T00:29:06Z app[91857775f1d308] ewr [info]2023-04-18T00:29:06.599453Z 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.
2023-04-18T00:29:06Z app[91857775f1d308] ewr [info]2023-04-18T00:29:06.612631Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: /var/run/mysqld/mysqlx.sock
2023-04-18T00:29:06Z app[91857775f1d308] ewr [info]2023-04-18T00:29:06.612803Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.32'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server - GPL.

I'd love some help in seeing what changed or may be failing here! In theory whatever works in Docker should work in a Fly VM...

Is the only notable change the update of the Gosu version? https://github.com/docker-library/mysql/commit/99f9c4104edb05ce198c5e9282f4d9d702277a60

fideloper commented 1 year ago

Looks like 8.0.33 isn't GA yet (or isn't released yet) but the official Docker site might just be behind (or, rather, has a tag for this not-yet-released release)

image
tianon commented 1 year ago

That's really odd; I don't think we have any specific insight into what might've changed that could've caused this. It's very unlikely that the gosu bump did.

For what it's worth, your link to the release notes is live now (I think we were just faster at getting the release published than the MySQL docs team was :sweat_smile:).

fideloper commented 1 year ago

Makes sense! I'll keep an eye on it to see if something changes either within this tag or the next. If it continues to be an issue, I'll dig in further to see what I can surface.

Thanks

fideloper commented 1 year ago

Hi again!

I did get a bit more useful output today trying this out again (I didn't really change anything except perhaps adding some startup flags that I suspect are unrelated, but I did get a more useful error message from mysqld):

👉 full output on 8.0.33 
2023-04-25T14:21:40.194 app[fc8e61ad] bos [info] Preparing to run: `docker-entrypoint.sh --default-authentication-plugin mysql_native_password --datadir /data/mysql --performance-schema=OFF --innodb-buffer-pool-size 64M` as root

2023-04-25T14:21:40.207 app[fc8e61ad] bos [info] 2023/04/25 14:21:40 listening on [fdaa:0:6ba9:a7b:eb:7:292e:2]:22 (DNS: [fdaa::3]:53)

2023-04-25T14:21:40.241 app[fc8e61ad] bos [info] 2023-04-25 14:21:40+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.33-1.el8 started.

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] 2023-04-25 14:21:40+00:00 [ERROR] [Entrypoint]: mysqld failed while attempting to check config

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] command was: mysqld --default-authentication-plugin mysql_native_password --datadir /data/mysql --performance-schema=OFF --innodb-buffer-pool-size 64M --verbose --help --log-bin-index=/tmp/tmp.p9nJLOlyru

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] 2023-04-25T14:21:40Z UTC - mysqld got signal 11 ;

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] BuildID[sha1]=8076d8618232dd0b5c9df333b4ee48d26d2170ca

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] Thread pointer: 0x0

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] Attempting backtrace. You can use the following information to find out

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] where mysqld died. If you see no messages after this, something went

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] terribly wrong...

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] stack_bottom = 0 thread_stack 0x100000

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x2123181]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /usr/sbin/mysqld(print_fatal_signal(int)+0x397) [0xfe6b07]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /usr/sbin/mysqld(handle_fatal_signal+0xa5) [0xfe6bc5]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /lib64/libpthread.so.0(+0x12d00) [0x7fc0455c9d00]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /usr/sbin/mysqld(Delegate::Delegate(unsigned int)+0xaf) [0x1db91bf]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /usr/sbin/mysqld(delegates_init()+0x34) [0x1db94c4]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /usr/sbin/mysqld() [0xd6ee6d]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /usr/sbin/mysqld(mysqld_main(int, char**)+0x220f) [0xd7581f]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /lib64/libc.so.6(__libc_start_main+0xe5) [0x7fc043b6ed85]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] /usr/sbin/mysqld(_start+0x2e) [0xd5680e]

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains

2023-04-25T14:21:40.446 app[fc8e61ad] bos [info] information that should help you find out what is causing the crash.

2023-04-25T14:21:41.203 app[fc8e61ad] bos [info] Starting clean up.

Here's the relevant stuff:

[info] Preparing to run: `docker-entrypoint.sh --default-authentication-plugin mysql_native_password --datadir /data/mysql --performance-schema=OFF --innodb-buffer-pool-size 64M` as root
[info] 2023/04/25 14:21:40 listening on [fdaa:0:6ba9:a7b:eb:7:292e:2]:22 (DNS: [fdaa::3]:53)
[info] 2023-04-25 14:21:40+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.33-1.el8 started.
[info] 2023-04-25 14:21:40+00:00 [ERROR] [Entrypoint]: mysqld failed while attempting to check config
[info] command was: mysqld --default-authentication-plugin mysql_native_password --datadir /data/mysql --performance-schema=OFF --innodb-buffer-pool-size 64M --verbose --help --log-bin-index=/tmp/tmp.p9nJLOlyru
[info] 2023-04-25T14:21:40Z UTC - mysqld got signal 11 ;
[info] Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
[info] BuildID[sha1]=8076d8618232dd0b5c9df333b4ee48d26d2170ca
[info] Thread pointer: 0x0
[info] Attempting backtrace. You can use the following information to find out
[info] where mysqld died. If you see no messages after this, something went
[info] terribly wrong...
[info] stack_bottom = 0 thread_stack 0x100000
[info] /usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x2123181]
[info] /usr/sbin/mysqld(print_fatal_signal(int)+0x397) [0xfe6b07]
[info] /usr/sbin/mysqld(handle_fatal_signal+0xa5) [0xfe6bc5]
[info] /lib64/libpthread.so.0(+0x12d00) [0x7fc0455c9d00]
[info] /usr/sbin/mysqld(Delegate::Delegate(unsigned int)+0xaf) [0x1db91bf]
[info] /usr/sbin/mysqld(delegates_init()+0x34) [0x1db94c4]
[info] /usr/sbin/mysqld() [0xd6ee6d]
[info] /usr/sbin/mysqld(mysqld_main(int, char**)+0x220f) [0xd7581f]
[info] /lib64/libc.so.6(__libc_start_main+0xe5) [0x7fc043b6ed85]
[info] /usr/sbin/mysqld(_start+0x2e) [0xd5680e]
[info] The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
[info] information that should help you find out what is causing the crash.
[info] Starting clean up.

MySQL 8.0.32 starts up without issue (via the official Docker container)

fideloper commented 1 year ago

Unfortunately, this continues with version 8.0.34, same error when attempting to boot the official MySQL image on a Fly.io VM

[info]2023-09-18 14:01:31+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.34-1.el8 started.
[info]2023-09-18 14:01:32+00:00 [ERROR] [Entrypoint]: mysqld failed while attempting to check config
[info] command was: mysqld --datadir /data/mysql --default-authentication-plugin mysql_native_password --performance-schema=OFF --innodb-buffer-pool-size 64M --verbose --help --log-bin-index=/tmp/tmp.TOh7WZIsF4
[info] 2023-09-18T14:01:32Z UTC - mysqld got signal 11 ;
[info]Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
[info]BuildID[sha1]=1758de1e111952b1f61480360c447dc27d6caddc
[info]Thread pointer: 0x0
[info]Attempting backtrace. You can use the following information to find out
[info]where mysqld died. If you see no messages after this, something went
[info]terribly wrong...
[info]stack_bottom = 0 thread_stack 0x100000
[info]/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x2130f51]
[info]/usr/sbin/mysqld(print_fatal_signal(int)+0x397) [0xfee797]
[info]/usr/sbin/mysqld(handle_fatal_signal+0xa5) [0xfee855]
[info]/lib64/libpthread.so.0(+0x12d40) [0x7fa6d58dcd40]
[info]/usr/sbin/mysqld(Delegate::Delegate(unsigned int)+0xaf) [0x1dc4e6f]
[info]/usr/sbin/mysqld(delegates_init()+0x34) [0x1dc5174]
[info]/usr/sbin/mysqld() [0xd7473d]
[info]/usr/sbin/mysqld(mysqld_main(int, char**)+0x23fb) [0xd7b45b]
[info]/lib64/libc.so.6(__libc_start_main+0xe5) [0x7fa6d3e82e45]
[info]/usr/sbin/mysqld(_start+0x2e) [0xd5c17e]
[info]The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
[info]information that should help you find out what is causing the crash.
helloqiu commented 1 year ago

MySQL used a new malloc function my_aligned_malloc in 8.0.33: https://github.com/mysql/mysql-server/commit/be8348a7c3e8510b998a063065b626a459631b32 According to the stack: /usr/sbin/mysqld(Delegate::Delegate(unsigned int)+0xaf) mysqld malloc an atomic<int> and wrote '0' into it then crashed here: https://github.com/mysql/mysql-server/blob/ea7087d885006918ad54458e7aad215b1650312c/sql/rpl_handler.cc#L94 This error may be caused by the new malloc function.

fideloper commented 1 year ago

Hi! Thanks for the shout out!

That looks like perhaps a fix is in place? Altho that's for mysql-cluster 8.2 rather than mysql-server, so I'm not sure if that helps us here!