MySQL container failing to restart and allow connections
Summary
When an environment is restarted, sometimes the mysql container will fail to start in such a way as to allow connections.
Steps to reproduce
No reliable ways to reproduce at this time:
- Appears to happen on deploys that wipe the database as well as those that keep the database.
- May be associated to how long since the last re-deploy. i.e. test experiences it infrequently, whereas other environments will encounter it their first re-deploy after a week.
- Locally restarting the mysql container quickly doesn't appear to cause it.
- Has happened a few times in a row on a brand new instance (just provisioned), near in time to one that was just provisioned that succeeded
What is the current bug behavior?
The environment starts, and the user will be shown an error message about connecting to the mysql db in their browser.
What is the expected correct behavior?
Mysql container continues working, with any data it had before.
Relevant logs and/or screenshots
Typical fpm container error
Fatal error: Uncaught PDOException: SQLSTATE[HY000] [1130] Host '172.19.0.3' is not allowed to connect to this MySQL server in /srv/pim/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOConnection.php:46 Stack trace: #0 /srv/pim/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOConnection.php(46): PDO->__construct('mysql:host=mysq...', 'akeneo_pim', 'akeneo_pim', Array) #1 /srv/pim/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOMySql/Driver.php(44): Doctrine\DBAL\Driver\PDOConnection->__construct('mysql:host=mysq...', 'akeneo_pim', 'akeneo_pim', Array) #2 /srv/pim/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(386): Doctrine\DBAL\Driver\PDOMySql\Driver->connect(Array, 'akeneo_pim', 'akeneo_pim', Array) #3 /srv/pim/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(448): Doctrine\DBAL\Connection->connect() #4 /srv/pim/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(410): Doctrine\DBAL\Connection->getDatabasePlatformVersion() #5 /srv/pim/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(354): Doctrine\DB in /srv/pim/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractMySQLDriver.php on line 125
MySQL log, this was a just-provisioned instance:
2020-02-08 23:52:02+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.29-1debian9 started.
2020-02-08 23:52:02+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2020-02-08 23:52:02+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.29-1debian9 started.
2020-02-08 23:52:02+00:00 [Note] [Entrypoint]: Initializing database files
2020-02-08T23:52:02.749162Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2020-02-08T23:52:03.216698Z 0 [Warning] InnoDB: New log files created, LSN=45790
2020-02-08T23:52:03.284936Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2020-02-08T23:52:03.363002Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 014af65a-4ace-11ea-ac9c-0242ac130003.
2020-02-08T23:52:03.368194Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2020-02-08T23:52:07.653284Z 0 [Warning] CA certificate ca.pem is self signed.
2020-02-08T23:52:08.025454Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2020-02-08 23:52:10+00:00 [Note] [Entrypoint]: Database files initialized
2020-02-08 23:52:10+00:00 [Note] [Entrypoint]: Starting temporary server
2020-02-08 23:52:10+00:00 [Note] [Entrypoint]: Waiting for server startup
2020-02-08T23:52:10.963416Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2020-02-08T23:52:10.972996Z 0 [Note] mysqld (mysqld 5.7.29) starting as process 83 ...
2020-02-08T23:52:10.977976Z 0 [Note] InnoDB: PUNCH HOLE support available
2020-02-08T23:52:10.978018Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-02-08T23:52:10.978025Z 0 [Note] InnoDB: Uses event mutexes
2020-02-08T23:52:10.978030Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2020-02-08T23:52:10.978034Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-02-08T23:52:10.978038Z 0 [Note] InnoDB: Using Linux native AIO
2020-02-08T23:52:10.980908Z 0 [Note] InnoDB: Number of pools: 1
2020-02-08T23:52:10.981166Z 0 [Note] InnoDB: Using CPU crc32 instructions
2020-02-08T23:52:10.982962Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2020-02-08T23:52:11.007190Z 0 [Note] InnoDB: Completed initialization of buffer pool
2020-02-08T23:52:11.013697Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-02-08T23:52:11.026020Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2020-02-08T23:52:11.036713Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-02-08T23:52:11.040764Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-02-08T23:52:11.104898Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-02-08T23:52:11.106008Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2020-02-08T23:52:11.106089Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2020-02-08T23:52:11.106500Z 0 [Note] InnoDB: Waiting for purge to start
2020-02-08T23:52:11.156749Z 0 [Note] InnoDB: 5.7.29 started; log sequence number 2629932
2020-02-08T23:52:11.157303Z 0 [Note] Plugin 'FEDERATED' is disabled.
2020-02-08T23:52:11.163387Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2020-02-08T23:52:11.167085Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2020-02-08T23:52:11.168082Z 0 [Warning] CA certificate ca.pem is self signed.
2020-02-08T23:52:11.168365Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2020-02-08T23:52:11.168313Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-02-08T23:52:11.170484Z 0 [Note] InnoDB: Buffer pool(s) load completed at 200208 23:52:11
2020-02-08T23:52:11.173885Z 0 [Warning] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2020-02-08T23:52:11.192843Z 0 [Note] Event Scheduler: Loaded 0 events
2020-02-08T23:52:11.200846Z 0 [Note] mysqld: ready for connections.
Version: '5.7.29' socket: '/var/run/mysqld/mysqld.sock' port: 0 MySQL Community Server (GPL)
2020-02-08 23:52:11+00:00 [Note] [Entrypoint]: Temporary server started.
Warning: Unable to load '/usr/share/zoneinfo/iso3166.tab' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2020-02-08 23:52:23+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.29-1debian9 started.
2020-02-08 23:52:24+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2020-02-08 23:52:24+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.29-1debian9 started.
2020-02-08T23:52:24.633548Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2020-02-08T23:52:24.635723Z 0 [Note] mysqld (mysqld 5.7.29) starting as process 1 ...
2020-02-08T23:52:24.646194Z 0 [Note] InnoDB: PUNCH HOLE support available
2020-02-08T23:52:24.646248Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-02-08T23:52:24.646254Z 0 [Note] InnoDB: Uses event mutexes
2020-02-08T23:52:24.646259Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2020-02-08T23:52:24.646263Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-02-08T23:52:24.646267Z 0 [Note] InnoDB: Using Linux native AIO
2020-02-08T23:52:24.646779Z 0 [Note] InnoDB: Number of pools: 1
2020-02-08T23:52:24.647074Z 0 [Note] InnoDB: Using CPU crc32 instructions
2020-02-08T23:52:24.649461Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2020-02-08T23:52:24.660060Z 0 [Note] InnoDB: Completed initialization of buffer pool
2020-02-08T23:52:24.663135Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-02-08T23:52:24.679174Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2020-02-08T23:52:24.681958Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 2629932
2020-02-08T23:52:25.059894Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 7872512
2020-02-08T23:52:25.297352Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 12021719
2020-02-08T23:52:25.298493Z 0 [Note] InnoDB: Database was not shutdown normally!
2020-02-08T23:52:25.298528Z 0 [Note] InnoDB: Starting crash recovery.
2020-02-08T23:52:25.391086Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 131671 row operations to undo
2020-02-08T23:52:25.391142Z 0 [Note] InnoDB: Trx id counter is 1792
2020-02-08T23:52:25.391831Z 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
2020-02-08T23:52:26.041414Z 0 [Note] InnoDB: Apply batch completed
2020-02-08T23:52:26.149538Z 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions
2020-02-08T23:52:26.149568Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2020-02-08T23:52:26.149779Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-02-08T23:52:26.149838Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-02-08T23:52:26.149763Z 0 [Note] InnoDB: Rolling back trx with id 1291, 131671 rows to undo
InnoDB: Progress in percents: 1 22020-02-08T23:52:26.193392Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
32020-02-08T23:52:26.194403Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2020-02-08T23:52:26.200070Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2020-02-08T23:52:26.200411Z 0 [Note] InnoDB: Waiting for purge to start
4 5 62020-02-08T23:52:26.252681Z 0 [Note] InnoDB: 5.7.29 started; log sequence number 12021719
2020-02-08T23:52:26.253111Z 0 [Note] Plugin 'FEDERATED' is disabled.
2020-02-08T23:52:26.256761Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-02-08T23:52:26.261570Z 0 [Note] InnoDB: Buffer pool(s) load completed at 200208 23:52:26
7 8 92020-02-08T23:52:26.290585Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2020-02-08T23:52:26.296657Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2020-02-08T23:52:26.306771Z 0 [Warning] CA certificate ca.pem is self signed.
2020-02-08T23:52:26.306999Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2020-02-08T23:52:26.307996Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2020-02-08T23:52:26.311157Z 0 [Note] IPv6 is available.
2020-02-08T23:52:26.311346Z 0 [Note] - '::' resolves to '::';
2020-02-08T23:52:26.311466Z 0 [Note] Server socket created on IP: '::'.
2020-02-08T23:52:26.313680Z 0 [Warning] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
10 11 12 13 142020-02-08T23:52:26.399534Z 0 [Note] Event Scheduler: Loaded 0 events
152020-02-08T23:52:26.404744Z 0 [Note] mysqld: ready for connections.
Version: '5.7.29' socket: '/var/run/mysqld/mysqld.sock' port: 3306 MySQL Community Server (GPL)
16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002020-02-08T23:52:27.807928Z 0 [Note] InnoDB: Rollback of trx with id 1291 completed
2020-02-08T23:52:27.808175Z 0 [Note] InnoDB: Rollback of non-prepared transactions completed
Possible fixes
None.
Relevant links:
Workarounds:
- Redeploying and wiping the data simply doesn't work. Restarting the mysql container doesn't work. The only fix atm is to destroy the environment, and deploy a new one.