[MDEV-21022] mysql_upgrade failure ERROR 1408 (HY000) at line 391: Event Scheduler: An error occurred when initializing system tables Created: 2019-11-11  Updated: 2022-07-27  Resolved: 2022-07-27

Status: Closed
Project: MariaDB Server
Component/s: Upgrades
Affects Version/s: 10.4.10
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Roland Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None
Environment:

Windows 10


 Description   

After upgrading to 10.4.10 (from 10.4.6) when i run `mysql_upgrade --verbose` than i get the following error and the upgrade stopped with following output. Re-running the command doesn't help.

Phase 4/7: Running 'mysql_fix_privilege_tables'
 
ERROR 1408 (HY000) at line 391: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
 
FATAL ERROR: Upgrade failed

Note: After a complete re-install of the database with `mysql_install_db` it works, but also deletes all existing databases.

 Comments   
Comment by Elena Stepanova [ 2019-11-18 ]

Are there any errors in the server error log? Can you attach mysql.event table with which it fails? (event.frm, event.MAD, event.MAI files).
If you don't want to create public attachments, files can be uploaded to ftp.askmonty.org/private.

Comment by Roland [ 2019-11-19 ]

Sorry. I cannot provide more information here because the `mysql_install_db` command deleted all my existing data directory contents.
After that command (what is basically a fresh install of mariadb) it works.
I guess that something in my setup was corrupt.
I had the database since 10.2.x and just upgraded everytime a release came out.
Starting with 10.4.6 there was another bug https://jira.mariadb.org/browse/MDEV-20228 that prevented a successful run of mysql_upgrade.
Now with 10.4.10 that seems to be fixed.
Maybe somewhere inbetween 10.4.6 upgrade bug and 10.4.10 upgrade i ruined my installation.
Altough my database worked fine all the time, i just had problem with the command mysql_upgrade since 10.4.6.

I just recommend to provide way more debug information when anything in mysql_upgrade fails. On which query, etc....

Comment by Daniel Black [ 2022-07-27 ] 

$ podman volume create v1046 
v1046
 
 
 
$ podman run -v v1046:/var/lib/mysql --env MYSQL_ROOT_PASSWORD=bob -d mariadb:10.4.6
 
7491e794d6329ec4d830dad11787b9e0844c3648d16c8808b612eed1c5c89ab9
 
 
 
$ podman kill 7491e794d6329ec4d830dad11787b9e0844c3648d16c8808b612eed1c5c89ab9
 
7491e794d6329ec4d830dad11787b9e0844c3648d16c8808b612eed1c5c89ab9
 
 
 
$ podman run -v v1046:/var/lib/mysql --name m10410 -d mariadb:10.4.10
 
Resolved "mariadb" as an alias (/home/dan/.cache/containers/short-name-aliases.conf)
 
Trying to pull docker.io/library/mariadb:10.4.10...
 
Getting image source signatures
 
Copying blob c1bbdc448b72 done  
Copying blob 59feacde9e08 done  
Copying blob 45d437916d57 done  
Copying blob 8c3b70e39044 done  
Copying blob 7ddbc47eeb70 done  
Copying blob 215d801d0263 done  
Copying blob 741aa98d779c done  
Copying blob e3f771d07df1 done  
Copying blob 38be307a8063 done  
Copying blob 5ef9df553f6d done  
Copying blob 3917045a4802 done  
Copying blob 2635016646c9 done  
Copying blob 77025b2c59dc done  
Copying blob be95797e69cd done  
Copying config 38c637f60d done  
Writing manifest to image destination
 
Storing signatures
 
2d4171899d9a28b78738f3c0bd36b74365f2fe0d2c9df57be6700af580d74cb0
 
 
 
$ podman exec m10410 mysql_upgrade -pbob
 
Phase 1/7: Checking and upgrading mysql database
 
Processing databases
 
mysql
 
mysql.column_stats                                 OK
 
mysql.columns_priv                                 OK
 
mysql.db                                           OK
 
mysql.event                                        OK
 
mysql.func                                         OK
 
mysql.global_priv                                  OK
 
mysql.gtid_slave_pos                               OK
 
mysql.help_category                                OK
 
mysql.help_keyword                                 OK
 
mysql.help_relation                                OK
 
mysql.help_topic                                   OK
 
mysql.index_stats                                  OK
 
mysql.innodb_index_stats                           OK
 
mysql.innodb_table_stats                           OK
 
mysql.plugin                                       OK
 
mysql.proc                                         OK
 
mysql.procs_priv                                   OK
 
mysql.proxies_priv                                 OK
 
mysql.roles_mapping                                OK
 
mysql.servers                                      OK
 
mysql.table_stats                                  OK
 
mysql.tables_priv                                  OK
 
mysql.time_zone                                    OK
 
mysql.time_zone_leap_second                        OK
 
mysql.time_zone_name                               OK
 
mysql.time_zone_transition                         OK
 
mysql.time_zone_transition_type                    OK
 
mysql.transaction_registry                         OK
 
Phase 2/7: Installing used storage engines... Skipped
 
Phase 3/7: Fixing views
 
mysql.user                                         OK
 
Phase 4/7: Running 'mysql_fix_privilege_tables'
 
Phase 5/7: Fixing table and database names
 
Phase 6/7: Checking and upgrading tables
 
Processing databases
 
information_schema
 
performance_schema
 
Phase 7/7: Running 'FLUSH PRIVILEGES'
 
OK
 
 
 
$ podman kill m10410
 
m10410
 
 
 
$ podman run -v v1046:/var/lib/mysql --name m10410a  mariadb:10.4.10
 
2022-07-27 10:55:24+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.10+maria~bionic started.
 
2022-07-27 10:55:24+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
 
2022-07-27 10:55:24+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.10+maria~bionic started.
 
2022-07-27 10:55:24 0 [Note] mysqld (mysqld 10.4.10-MariaDB-1:10.4.10+maria~bionic) starting as process 1 ...
 
2022-07-27 10:55:24 0 [Note] mysqld: Aria engine: starting recovery
 
recovered pages: 0% 12% 23% 33% 43% 54% 65% 75% 86% 97% 100% (0.0 seconds); 
2022-07-27 10:55:24 0 [Note] mysqld: Aria engine: recovery done
 
2022-07-27 10:55:24 0 [Note] InnoDB: Using Linux native AIO
 
2022-07-27 10:55:24 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2022-07-27 10:55:24 0 [Note] InnoDB: Uses event mutexes
 
2022-07-27 10:55:24 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2022-07-27 10:55:24 0 [Note] InnoDB: Number of pools: 1
 
2022-07-27 10:55:24 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2022-07-27 10:55:24 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
2022-07-27 10:55:24 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
 
2022-07-27 10:55:25 0 [Note] InnoDB: Completed initialization of buffer pool
 
2022-07-27 10:55:25 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2022-07-27 10:55:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139854
 
2022-07-27 10:55:25 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2022-07-27 10:55:25 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2022-07-27 10:55:25 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2022-07-27 10:55:25 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2022-07-27 10:55:25 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2022-07-27 10:55:25 0 [Note] InnoDB: Waiting for purge to start
 
2022-07-27 10:55:25 0 [Note] InnoDB: 10.4.10 started; log sequence number 139863; transaction id 21
 
2022-07-27 10:55:25 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
2022-07-27 10:55:25 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/plugin'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/servers'
 
2022-07-27 10:55:25 0 [Note] InnoDB: Buffer pool(s) load completed at 220727 10:55:25
 
2022-07-27 10:55:25 0 [Note] Server socket created on IP: '::'.
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/db'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/proxies_priv'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/roles_mapping'
 
2022-07-27 10:55:25 0 [Warning] 'proxies_priv' entry '@% root@7491e794d632' ignored in --skip-name-resolve mode.
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/time_zone_leap_second'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/time_zone_name'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/time_zone'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/time_zone_transition_type'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/time_zone_transition'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/tables_priv'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/columns_priv'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/procs_priv'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/func'
 
2022-07-27 10:55:25 0 [Note] Zerofilling moved table:  './mysql/event'
 
2022-07-27 10:55:25 0 [Note] Reading of all Master_info entries succeeded
 
2022-07-27 10:55:25 0 [Note] Added new Master_info '' to hash table
 
2022-07-27 10:55:25 0 [Note] mysqld: ready for connections.
 
Version: '10.4.10-MariaDB-1:10.4.10+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
 
 
 
$ podman run -v v1046:/var/lib/mysql --name m10410b --rm  mariadb:10.4.10 --event-scheduler
 
2022-07-27 11:00:39+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.10+maria~bionic started.
 
2022-07-27 11:00:39+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
 
2022-07-27 11:00:39+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.10+maria~bionic started.
 
2022-07-27 11:00:40 0 [Note] mysqld (mysqld 10.4.10-MariaDB-1:10.4.10+maria~bionic) starting as process 1 ...
 
2022-07-27 11:00:40 0 [Note] InnoDB: Using Linux native AIO
 
2022-07-27 11:00:40 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2022-07-27 11:00:40 0 [Note] InnoDB: Uses event mutexes
 
2022-07-27 11:00:40 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2022-07-27 11:00:40 0 [Note] InnoDB: Number of pools: 1
 
2022-07-27 11:00:40 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2022-07-27 11:00:40 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
2022-07-27 11:00:40 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
 
2022-07-27 11:00:40 0 [Note] InnoDB: Completed initialization of buffer pool
 
2022-07-27 11:00:40 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2022-07-27 11:00:40 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139872
 
2022-07-27 11:00:40 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2022-07-27 11:00:40 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2022-07-27 11:00:40 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2022-07-27 11:00:40 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2022-07-27 11:00:40 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2022-07-27 11:00:40 0 [Note] InnoDB: Waiting for purge to start
 
2022-07-27 11:00:40 0 [Note] InnoDB: 10.4.10 started; log sequence number 139881; transaction id 21
 
2022-07-27 11:00:40 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
2022-07-27 11:00:40 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2022-07-27 11:00:40 0 [Note] Server socket created on IP: '::'.
 
2022-07-27 11:00:40 0 [Warning] 'proxies_priv' entry '@% root@7491e794d632' ignored in --skip-name-resolve mode.
 
2022-07-27 11:00:40 0 [Note] InnoDB: Buffer pool(s) load completed at 220727 11:00:40
 
2022-07-27 11:00:40 6 [Note] Event Scheduler: scheduler thread started with id 6
 
2022-07-27 11:00:40 0 [Note] Reading of all Master_info entries succeeded
 
2022-07-27 11:00:40 0 [Note] Added new Master_info '' to hash table
 
2022-07-27 11:00:40 0 [Note] mysqld: ready for connections.
 
Version: '10.4.10-MariaDB-1:10.4.10+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

Sorry, I can't reproduce this.

Generated at Thu Feb 08 09:04:00 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.