Description:
When upgrade is happening on server startup it can fail while applying upgrade sql scripts due to user configuration of variables such as max_allowed_packet.
When this happens, error logging is not very useful in diagnosing why it failed. As the upgrade scripts are applied by the server thread, messages such as ER_NET_PACKET_TOO_LARGE seem to be suppressed.
For example, with max_allowed_packet set to 1024, upgrade will fail with the following message:
2024-04-30T04:50:15.790353Z 4 [ERROR] [MY-013178] [Server] Execution of server-side SQL statement 'PREPARE stmt FROM @str; ' failed with error code = 1064, error message = 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'NULL' at line 1'.
This gives no information on why the upgrade is failing, even with log_error_verbosity=3.
How to repeat:
Set max_allowed_packet=1024 in cnf file and issue server upgrade, which will fail.
2024-04-30T05:25:42.542972Z 4 [System] [MY-013381] [Server] Server upgrade from '80028' to '80036' started.
2024-04-30T05:25:42.543399Z 4 [Note] [MY-013386] [Server] Running queries to upgrade MySQL server.
2024-04-30T05:25:42.544115Z 4 [ERROR] [MY-013178] [Server] Execution of server-side SQL statement 'PREPARE stmt FROM @str; ' failed with error code = 1064, error message = 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'NULL' at line 1'.
2024-04-30T05:25:42.544866Z 0 [ERROR] [MY-013380] [Server] Failed to upgrade server.
2024-04-30T05:25:42.544882Z 0 [ERROR] [MY-010119] [Server] Aborting
Now changed max allowed packet to 10,000:
$ grep max_allowed_packet sandboxes/msb_8_0_36/my.sandbox.cnf
max_allowed_packet=1024
$ vim sandboxes/msb_8_0_36/my.sandbox.cnf
$ grep max_allowed_packet sandboxes/msb_8_0_36/my.sandbox.cnf
max_allowed_packet=10000
Upgrade succeeded:
2024-04-30T05:27:24.859255Z 4 [System] [MY-013381] [Server] Server upgrade from '80028' to '80036' started.
2024-04-30T05:27:24.859704Z 4 [Note] [MY-013386] [Server] Running queries to upgrade MySQL server.
2024-04-30T05:27:27.594639Z 4 [Note] [MY-013387] [Server] Upgrading system table data.
2024-04-30T05:27:27.935342Z 4 [Note] [MY-013385] [Server] Upgrading the sys schema.
2024-04-30T05:27:28.710620Z 4 [Note] [MY-013400] [Server] Upgrade of help tables started.
2024-04-30T05:27:28.810961Z 4 [Note] [MY-013400] [Server] Upgrade of help tables completed.
2024-04-30T05:27:28.811034Z 4 [Note] [MY-013394] [Server] Checking 'mysql' schema.
2024-04-30T05:27:28.919794Z 4 [Note] [MY-013394] [Server] Checking 'sys' schema.
2024-04-30T05:27:28.935204Z 4 [System] [MY-013381] [Server] Server upgrade from '80028' to '80036' completed.
Suggested fix:
1. During upgrade, Server upgrade scripts should be protected against "bad" configuration options or at least, useful messages be printed in the event of an error. e.g. if its known max_allowed_packet > 8000 is required, it should be set by the server thread at the "session" level for upgrade or ER_NET_PACKET_TOO_LARGE should be printed in the error logs.
2. "Minimum" values for server variables should not lead to upgrade failures. Ideally, minimums should be raised or upgrade queries should be able to execute on server supported values.
Thanks!
Marc
