mysql abort when enable super_read_only with read_only

[mqiloveyou]

Slave
Server version: 5.6.25-73.1-log Percona Server (GPL), Release 73.1, Revision 07b797f
Variable: read_only = 1

I enable super_read_only ,then restart mysql server,it looks like no problem.
[root@mysql2 ~]# /etc/init.d/mysqld restart
Shutting down MySQL (Percona Server)... SUCCESS!
Starting MySQL (Percona Server)... SUCCESS!

But mysql abort.
error log:

150812 11:55:02 mysqld_safe Starting mysqld daemon with databases from /data/mysql/3306/data/
2015-08-12 11:55:03 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-08-12 11:55:03 0 [Warning] 'ERROR_FOR_DIVISION_BY_ZERO' is deprecated and will be removed in a future release.
2015-08-12 11:55:03 0 [Warning] 'NO_ZERO_DATE' is deprecated and will be removed in a future release.
2015-08-12 11:55:03 0 [Warning] 'NO_ZERO_IN_DATE' is deprecated and will be removed in a future release.
2015-08-12 11:55:03 0 [Note] /usr/local/mysql/bin/mysqld (mysqld 5.6.25-73.1-log) starting as process 60494 ...
2015-08-12 11:55:03 60494 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
2015-08-12 11:55:03 60494 [Warning] The option innodb (skip-innodb) is deprecated and will be removed in a future release
2015-08-12 11:55:03 60494 [Note] Plugin 'FEDERATED' is disabled.
2015-08-12 11:55:03 60494 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-08-12 11:55:03 60494 [Note] InnoDB: The InnoDB memory heap is disabled
2015-08-12 11:55:03 60494 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-08-12 11:55:03 60494 [Note] InnoDB: Memory barrier is not used
2015-08-12 11:55:03 60494 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-08-12 11:55:03 60494 [Note] InnoDB: Using Linux native AIO
2015-08-12 11:55:03 60494 [Note] InnoDB: Using CPU crc32 instructions
2015-08-12 11:55:03 60494 [Note] InnoDB: Initializing buffer pool, size = 592.0M
2015-08-12 11:55:03 60494 [Note] InnoDB: Completed initialization of buffer pool
2015-08-12 11:55:03 60494 [Note] InnoDB: Highest supported file format is Barracuda.
2015-08-12 11:55:04 60494 [Note] InnoDB: 128 rollback segment(s) are active.
2015-08-12 11:55:04 60494 [Note] InnoDB: Waiting for purge to start
2015-08-12 11:55:04 60494 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.25-rel73.1 started; log sequence number 168714510
2015-08-12 11:55:04 60494 [Note] RSA private key file not found: /data/mysql/3306/data//private_key.pem. Some authentication plugins will not work.
2015-08-12 11:55:04 60494 [Note] RSA public key file not found: /data/mysql/3306/data//public_key.pem. Some authentication plugins will not work.
2015-08-12 11:55:04 60494 [Note] Server hostname (bind-address): '*'; port: 3306
2015-08-12 11:55:04 60494 [Note] IPv6 is available.
2015-08-12 11:55:04 60494 [Note] - '::' resolves to '::';
2015-08-12 11:55:04 60494 [Note] Server socket created on IP: '::'.
2015-08-12 11:55:04 60494 [Warning] 'proxies_priv' entry '@ root@mysql1' ignored in --skip-name-resolve mode.
2015-08-12 11:55:04 60494 [ERROR] Event Scheduler: Failed to open table mysql.event
2015-08-12 11:55:04 60494 [ERROR] Event Scheduler: Error while loading from disk.
2015-08-12 11:55:04 60494 [Note] Event Scheduler: Purging the queue. 0 events
2015-08-12 11:55:04 60494 [ERROR] Aborting

2015-08-12 11:55:04 60494 [Note] Binlog end
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'partition'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'ARCHIVE'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'BLACKHOLE'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_CHANGED_PAGES'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_METRICS'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_CMPMEM'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_CMP'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_LOCKS'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'INNODB_TRX'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'XTRADB_RSEG'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'XTRADB_INTERNAL_HASH_TABLES'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'XTRADB_READ_VIEW'
2015-08-12 11:55:04 60494 [Note] Shutting down plugin 'InnoDB'
2015-08-12 11:55:04 60494 [Note] InnoDB: FTS optimize thread exiting.
2015-08-12 11:55:04 60494 [Note] InnoDB: Starting shutdown...
2015-08-12 11:55:06 60494 [Note] InnoDB: Shutdown completed; log sequence number 168714520
2015-08-12 11:55:06 60494 [Note] Shutting down plugin 'CSV'
2015-08-12 11:55:06 60494 [Note] Shutting down plugin 'MyISAM'
2015-08-12 11:55:06 60494 [Note] Shutting down plugin 'MRG_MYISAM'
2015-08-12 11:55:06 60494 [Note] Shutting down plugin 'MEMORY'
2015-08-12 11:55:06 60494 [Note] Shutting down plugin 'sha256_password'
2015-08-12 11:55:06 60494 [Note] Shutting down plugin 'mysql_old_password'
2015-08-12 11:55:06 60494 [Note] Shutting down plugin 'mysql_native_password'
2015-08-12 11:55:06 60494 [Note] Shutting down plugin 'binlog'
2015-08-12 11:55:06 60494 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete

Error in my_thread_global_end(): 1 threads didn't exit
150812 11:55:11 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended

[Matthew Kent (mkent)]

Seeing this here as well on percona server 5.6.25-73.1-log, when started with super_read_only = ON it bails with "Event Scheduler: Failed to open table mysql.event". Disabling it fixed the issue.

Pretty nasty one, it actually submarined a full restart of 4 nodes I was doing to enable gtid, none of them came back up except the master!

[Nilnandan Joshi (nilnandan-joshi)]

Hi Matthew,

I couldn't able to reproduce the same with PS 5.6.25.

root@desktop:~# cat /etc/mysql/my.cnf | grep super
super_read_only=1
root@desktop:~#
root@desktop:~# /etc/init.d/mysql restart
 * Stopping MySQL (Percona Server) mysqld [ OK ]
 * Starting MySQL (Percona Server) database server mysqld [ OK ]
 * Checking for corrupt, not cleanly closed and upgrade needing tables.
root@desktop:~#
root@desktop:~#
root@desktop:~# vim /var/log/mysql/error.log
root@desktop:~#
root@desktop:~# mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 39
Server version: 5.6.25-73.1-log Percona Server (GPL), Release 73.1, Revision 07b797f

Copyright (c) 2009-2015 Percona LLC and/or its affiliates
Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show global variables like 'super%';
+-----------------+-------+
| Variable_name | Value |
+-----------------+-------+
| super_read_only | ON |
+-----------------+-------+
1 row in set (0.00 sec)

I got this error in error log,
2015-09-07 15:18:04 4823 [ERROR] Native table 'performance_schema'.'events_waits_history' has the wrong structure

But I could able to add event and nothing was crashed.

mysql> select * from mysql.event \G
*************************** 1. row ***************************
                  db: test
                name: e_hourly
                body: DELETE FROM site_activity.sessions
             definer: root@localhost
          execute_at: NULL
      interval_value: 1
      interval_field: HOUR
             created: 2015-09-07 15:24:59
            modified: 2015-09-07 15:24:59
       last_executed: NULL
              starts: 2015-09-07 09:54:59
                ends: NULL
              status: ENABLED
       on_completion: DROP
            sql_mode: NO_ENGINE_SUBSTITUTION
             comment: Clears out sessions table each hour.
          originator: 1
           time_zone: SYSTEM
character_set_client: utf8
collation_connection: utf8_general_ci
        db_collation: latin1_swedish_ci
           body_utf8: DELETE FROM site_activity.sessions
1 row in set (0.00 sec)

mysql> show global variables like 'super%';
+-----------------+-------+
| Variable_name | Value |
+-----------------+-------+
| super_read_only | ON |
+-----------------+-------+
1 row in set (0.00 sec)

mysql>

Can you please provide the repeatable test case for this ?

[mqiloveyou (rodman2007)]

Hi Nilnandan,

     do you enable read_only simultaneously？

    My test case found that:

      if only enable super_read_only , mysqld can be restarted normally .

     if enable super_read_only with read_only simultaneously , mysqld crashed when be restarted.

[Nilnandan Joshi (nilnandan-joshi)]

So yes, with enable super_read_only with read_only simultaneously, mysqld getting crashed.

root@desktop:~# cat /etc/mysql/my.cnf | grep read_only
super_read_only=1
read_only=1
root@desktop:~#

root@desktop:~# /etc/init.d/mysql restart
 * Stopping MySQL (Percona Server) mysqld [ OK ]
 * Starting MySQL (Percona Server) database server mysqld [fail]
root@desktop:~#

root@desktop:~# tail -100 /var/log/mysql/error.log
...
2015-09-08 10:39:52 1598 [Note] /usr/sbin/mysqld: Shutdown complete

150908 10:39:52 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
150908 10:39:52 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
2015-09-08 10:39:52 0 [Warning] Using unique option prefix key_buffer instead of key_buffer_size is deprecated and will be removed in a future release. Please use the full name instead.
...
2015-09-08 10:39:52 5875 [Note] Server hostname (bind-address): '*'; port: 3306
2015-09-08 10:39:52 5875 [Note] IPv6 is available.
2015-09-08 10:39:52 5875 [Note] - '::' resolves to '::';
2015-09-08 10:39:52 5875 [Note] Server socket created on IP: '::'.
2015-09-08 10:39:52 5875 [ERROR] Native table 'performance_schema'.'events_waits_history' has the wrong structure
2015-09-08 10:39:52 5875 [ERROR] Event Scheduler: Failed to open table mysql.event
2015-09-08 10:39:52 5875 [ERROR] Event Scheduler: Error while loading from disk.
2015-09-08 10:39:52 5875 [Note] Event Scheduler: Purging the queue. 0 events
2015-09-08 10:39:52 5875 [ERROR] Aborting

2015-09-08 10:39:52 5875 [Note] Binlog end
2015-09-08 10:39:52 5875 [Note] Shutting down plugin 'auth_pam_compat'
...
2015-09-08 10:39:55 5875 [Note] Shutting down plugin 'binlog'
2015-09-08 10:39:55 5875 [Note] /usr/sbin/mysqld: Shutdown complete

Error in my_thread_global_end(): 1 threads didn't exit
150908 10:40:01 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
root@desktop:~#

[Laurynas Biveinis (laurynas-biveinis)]

This is fixed at Facebook patch by https://github.com/facebook/mysql-5.6/commit/c70dd2f4c7897734109d62f46f22751cddbb5d9a. That commit appears also to fix bug 1389935.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1024

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-919