hook error due to "The MySQL server is running with the --super-read-only option so it cannot execute this statement"

[Alex Kavanagh]

2020-06-04 18:39:48 [INFO] Deploying bundle './tests/bundles/focal-ussuri.yaml' on to 'zaza-06426b0084ad' model
...
zaza.model.UnitError: Units mysql-innodb-cluster/0 in error state

debug log for unit:

2020-06-04 19:04:09 DEBUG db-router-relation-changed Traceback (most recent call last):
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/charm/hooks/db-router-relation-changed", line 22, in <module>
2020-06-04 19:04:09 DEBUG db-router-relation-changed main()
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
2020-06-04 19:04:09 DEBUG db-router-relation-changed bus.dispatch(restricted=restricted_mode)
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
2020-06-04 19:04:09 DEBUG db-router-relation-changed _invoke(other_handlers)
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
2020-06-04 19:04:09 DEBUG db-router-relation-changed handler.invoke()
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 181, in invoke
2020-06-04 19:04:09 DEBUG db-router-relation-changed self._action(*args)
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/charm/reactive/mysql_innodb_cluster_handlers.py", line 274, in db_router_respond
2020-06-04 19:04:09 DEBUG db-router-relation-changed if instance.create_databases_and_users(db_router):
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "lib/charm/openstack/mysql_innodb_cluster.py", line 1059, in create_databases_and_users
2020-06-04 19:04:09 DEBUG db-router-relation-changed password = self.configure_db_for_hosts(
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "lib/charm/openstack/mysql_innodb_cluster.py", line 1135, in configure_db_for_hosts
2020-06-04 19:04:09 DEBUG db-router-relation-changed password = rw_helper.configure_db(host, database, username)
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charmhelpers/contrib/database/mysql.py", line 464, in configure_db
2020-06-04 19:04:09 DEBUG db-router-relation-changed self.create_database(database)
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charmhelpers/contrib/database/mysql.py", line 115, in create_database
2020-06-04 19:04:09 DEBUG db-router-relation-changed cursor.execute("CREATE DATABASE `{}` CHARACTER SET UTF8"
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/MySQLdb/cursors.py", line 209, in execute
2020-06-04 19:04:09 DEBUG db-router-relation-changed res = self._query(query)
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/MySQLdb/cursors.py", line 315, in _query
2020-06-04 19:04:09 DEBUG db-router-relation-changed db.query(q)
2020-06-04 19:04:09 DEBUG db-router-relation-changed File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/MySQLdb/connections.py", line 239, in query
2020-06-04 19:04:09 DEBUG db-router-relation-changed _mysql.connection.query(self, query)
2020-06-04 19:04:09 DEBUG db-router-relation-changed MySQLdb._exceptions.OperationalError: (1290, 'The MySQL server is running with the --super-read-only option so it cannot execute this statement')
2020-06-04 19:04:09 ERROR juju.worker.uniter.operation runhook.go:132 hook "db-router-relation-changed" failed: exit status 1

https://review.opendev.org/#/c/732667/
https://openstack-ci-reports.ubuntu.com/artifacts/test_charm_pipeline_func_full/openstack/charm-octavia-diskimage-retrofit/732667/1/5943/index.html

[Sachin Kulkarni (sachin-trilio)]

Hit this issue while deploying "Ussuri" on focal.

mysql-innodb-cluster - Gets in error with "hook failed: "cluster-relation-changed""
Ussuri Bundle - cs:bundle/openstack-base-69
mysql-innodb-cluster charms used - cs:mysql-innodb-cluster-0 and cs:~openstack-charmers-next/mysql-innodb-cluster-42

Debug logs -
unit-mysql-innodb-cluster-6: 11:17:12 INFO unit.mysql-innodb-cluster/6.juju-log cluster:90: Invoking reactive handler: hooks/relations/mysql-innodb-cluster/peers.py:69:joined:cluster
unit-mysql-innodb-cluster-6: 11:17:12 DEBUG unit.mysql-innodb-cluster/6.juju-log cluster:90: tracer>
tracer: set flag cluster.available
tracer: ++ queue handler reactive/mysql_innodb_cluster_handlers.py:88:create_remote_cluster_user
tracer: -- dequeue handler reactive/mysql_innodb_cluster_handlers.py:66:send_cluster_connection_info
unit-mysql-innodb-cluster-6: 11:17:12 INFO unit.mysql-innodb-cluster/6.juju-log cluster:90: Invoking reactive handler: hooks/relations/mysql-innodb-cluster/peers.py:75:changed:cluster
unit-mysql-innodb-cluster-6: 11:17:12 INFO unit.mysql-innodb-cluster/6.juju-log cluster:90: Invoking reactive handler: hooks/relations/tls-certificates/requires.py:109:broken:certificates
unit-mysql-innodb-cluster-6: 11:17:13 INFO unit.mysql-innodb-cluster/6.juju-log cluster:90: Invoking reactive handler: hooks/relations/mysql-router/provides.py:47:joined:db-router
unit-mysql-innodb-cluster-6: 11:17:13 INFO unit.mysql-innodb-cluster/6.juju-log cluster:90: Invoking reactive handler: hooks/relations/mysql-router/provides.py:53:changed:db-router
unit-mysql-innodb-cluster-6: 11:17:13 INFO unit.mysql-innodb-cluster/6.juju-log cluster:90: Invoking reactive handler: reactive/mysql_innodb_cluster_handlers.py:88:create_remote_cluster_user
unit-mysql-innodb-cluster-6: 11:17:14 DEBUG unit.mysql-innodb-cluster/6.juju-log cluster:90: Creating remote users.
unit-mysql-innodb-cluster-6: 11:17:14 WARNING unit.mysql-innodb-cluster/6.juju-log cluster:90: This instance is not yet clustered: cannot determine the cluster status.
unit-mysql-innodb-cluster-6: 11:17:14 WARNING unit.mysql-innodb-cluster/6.juju-log cluster:90: Cannot determine the cluster primary RW node for writes.
unit-mysql-innodb-cluster-6: 11:17:14 DEBUG unit.mysql-innodb-cluster/6.juju-log cluster:90: Opening db connection for root@None
unit-mysql-innodb-cluster-6: 11:17:14 WARNING unit.mysql-innodb-cluster/6.juju-log cluster:90: User clusteruser already exists.
unit-mysql-innodb-cluster-6: 11:17:14 ERROR unit.mysql-innodb-cluster/6.juju-log cluster:90: Hook error:
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-6/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
    bus.dispatch(restricted=restricted_mode)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-6/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
    _invoke(other_handlers)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-6/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
    handler.invoke()
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-6/.venv/lib/python3.8/site-packages/charms/reactive...

[Dmitrii Shcherbakov (dmitriis)]

unit-mysql-innodb-cluster-0 /var/log/mysql/error.log:

2020-06-04T19:00:16.144352Z 0 [Warning] [MY-011499] [Repl] Plugin group_replication reported: 'Members removed from the group: 172.17.108.12:3306'
2020-06-04T19:02:08.894844Z 0 [Warning] [MY-011499] [Repl] Plugin group_replication reported: 'Members removed from the group: 172.17.108.10:3306'
2020-06-04T19:03:13.320409Z 0 [Warning] [MY-011493] [Repl] Plugin group_replication reported: 'Member with address 172.17.108.12:3306 has become unreachable.'
2020-06-04T19:03:13.320507Z 0 [Warning] [MY-011493] [Repl] Plugin group_replication reported: 'Member with address 172.17.108.10:3306 has become unreachable.'
2020-06-04T19:03:13.320524Z 0 [ERROR] [MY-011495] [Repl] Plugin group_replication reported: 'This server is not able to reach a majority of members in the group. This server will now block all updates. The server will remain blocked until contact with the majority is restored. It is possible to use group_replication_force_members to force a new group membership.'
2020-06-04T19:03:16.519849Z 0 [ERROR] [MY-011505] [Repl] Plugin group_replication reported: 'Member was expelled from the group due to network failures, changing member status to ERROR.'
2020-06-04T19:03:16.520033Z 0 [ERROR] [MY-011712] [Repl] Plugin group_replication reported: 'The server was automatically set into read only mode after an error was detected.'
2020-06-04T19:03:16.528336Z 160 [Warning] [MY-013373] [Repl] Plugin group_replication reported: 'Started auto-rejoin procedure attempt 1 of 1000'

The symptoms here look similar to what I saw in a CI failure for https://review.opendev.org/#/c/742500.

Automatic re-connection retries are set to 1000 for members that lose connectivity to the cluster, however, they are expelled 5 seconds after the loss of connectivity.

https://dev.mysql.com/doc/refman/8.0/en/mysql-innodb-cluster-working-with-cluster.html#configuring-automatic-rejoin-of-instances
https://opendev.org/openstack/charm-mysql-innodb-cluster/src/commit/6d979f9ab3dba1938baa5262c20d5ad423aee273/src/config.yaml#L21-L26
https://opendev.org/openstack/charm-mysql-innodb-cluster/src/commit/6d979f9ab3dba1938baa5262c20d5ad423aee273/src/reactive/mysql_innodb_cluster_handlers.py#L221-L223

Also the period of time between retries seems to be 5 minutes: "After an unsuccessful auto-rejoin attempt, the member waits 5 minutes before the next try."
https://dev.mysql.com/doc/refman/8.0/en/group-replication-options.html#sysvar_group_replication_autorejoin_tries
But in this case there was only one attempt.

I don't think bumping up the group_replication_member_expel_timeout will fully fix this but at least it will make it equal to the one used in newer versions upstream.

https://dev.mysql.com/doc/refman/8.0/en/group-replication-options.html#sysvar_group_replication_member_expel_timeout
"Up to and including MySQL 8.0.20, the value of group_replication_member_expel_timeout defaults to 0, meaning that there is no waiting period and a suspected member is liable for expulsion immediately after the 5-second detection period ends. From MySQL 8.0.21, the value defaults to 5, meaning that a suspected member is liable for expulsion 5 seconds af...

[Dmitrii Shcherbakov (dmitriis)]

A patchset to bump the expel timeout: https://review.opendev.org/742664

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/742664
Committed: https://git.openstack.org/cgit/openstack/charm-mysql-innodb-cluster/commit/?id=5eb43790d4d33671edd8613558043150a84f3135
Submitter: Zuul
Branch: master

commit 5eb43790d4d33671edd8613558043150a84f3135
Author: Dmitrii Shcherbakov <email address hidden>
Date: Thu Jul 23 16:21:22 2020 +0300

    Set expel timeout to 5 seconds

    Focal has MySQL version 8.0.20-0ubuntu0.20.04.1 which sets
    group_replication_member_expel_timeout to 0 by default [0]. As a result,
    cluster members are expelled from the cluster 5 seconds after the loss
    of connectivity.

    This proves to be too short for our CI and some other environments in
    the wild.

    MySQL documentation for this option suggests that 5 or even 10 seconds
    may be too low for congested or overcommitted environments which happens
    to be the case. As of MySQL 8.0.21 the default for
    group_replication_member_expel_timeout is set to 5 seconds.

    [0] https://dev.mysql.com/doc/refman/8.0/en/group-replication-options.html#sysvar_group_replication_member_expel_timeout
    [1] https://dev.mysql.com/doc/refman/8.0/en/group-replication-responses-failure-expel.html

    Change-Id: Ia33c6263e616657d21b41fcf1a8abfb34e6cb58d
    Partial-Bug: #1882205

[Aurelien Lourot (aurelien-lourot)]

happened again: https://openstack-ci-reports.ubuntu.com/artifacts/test_charm_pipeline_func_full/openstack/charm-keystone/744690/1/6611/index.html

2020-08-04 14:14:19 ERROR juju-log cluster:3: Hook error:
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
    bus.dispatch(restricted=restricted_mode)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
    _invoke(other_handlers)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
    handler.invoke()
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 181, in invoke
    self._action(*args)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/charm/reactive/mysql_innodb_cluster_handlers.py", line 103, in create_remote_cluster_user
    instance.create_cluster_user(
  File "lib/charm/openstack/mysql_innodb_cluster.py", line 519, in create_cluster_user
    m_helper.execute(SQL_CLUSTER_USER_GRANT.format(
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/charmhelpers/contrib/database/mysql.py", line 178, in execute
    cursor.execute(sql)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/MySQLdb/cursors.py", line 206, in execute
    res = self._query(query)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/MySQLdb/cursors.py", line 319, in _query
    db.query(q)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-0/.venv/lib/python3.8/site-packages/MySQLdb/connections.py", line 259, in query
    _mysql.connection.query(self, query)
MySQLdb._exceptions.OperationalError: (1290, 'The MySQL server is running with the --super-read-only option so it cannot execute this statement')

[Aurelien Lourot (aurelien-lourot)]

That last occurence is probably due to a very busy/overloaded cloud.

[Aurelien Lourot (aurelien-lourot)]

Also seen in another hook (leader-elected) while deploying the charm-nova-cloud-controller focal-victoria zaza test bundle:

https://review.opendev.org/#/c/748650/
https://openstack-ci-reports.ubuntu.com/artifacts/test_charm_pipeline_func_full/openstack/charm-nova-cloud-controller/748650/1/6786/index.html

2020-09-07 15:02:50 ERROR juju-log Hook error:
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
    bus.dispatch(restricted=restricted_mode)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
    _invoke(other_handlers)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
    handler.invoke()
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 181, in invoke
    self._action(*args)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/charm/reactive/mysql_innodb_cluster_handlers.py", line 279, in db_router_respond
    if instance.create_databases_and_users(db_router):
  File "lib/charm/openstack/mysql_innodb_cluster.py", line 1114, in create_databases_and_users
    password = self.configure_db_router(
  File "lib/charm/openstack/mysql_innodb_cluster.py", line 1228, in configure_db_router
    password = rw_helper.configure_router(host, username)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charmhelpers/contrib/database/mysql.py", line 757, in configure_router
    self.create_router_grant(username, remote_ip, password)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charmhelpers/contrib/database/mysql.py", line 730, in create_router_grant
    cursor.execute("GRANT CREATE USER ON *.* TO '{}'@'{}' WITH GRANT "
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/MySQLdb/cursors.py", line 206, in execute
    res = self._query(query)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/MySQLdb/cursors.py", line 319, in _query
    db.query(q)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/MySQLdb/connections.py", line 259, in query
    _mysql.connection.query(self, query)
MySQLdb._exceptions.OperationalError: (1290, 'The MySQL server is running with the --super-read-only option so it cannot execute this statement')

[Aurelien Lourot (aurelien-lourot)]

Increasing expel-timeout in charm-nova-cloud-controller zaza bundles: https://review.opendev.org/#/c/748650/

[Aurelien Lourot (aurelien-lourot)]

Same in charm-keystone-ldap: https://review.opendev.org/#/c/748636

[Aurelien Lourot (aurelien-lourot)]

Same in charm-placement: https://review.opendev.org/#/c/752250/

[Aurelien Lourot (aurelien-lourot)]

Marking this as fixed as increasing `expel-timeout` in our test bundles seems to help.

[Aurelien Lourot (aurelien-lourot)]

Let's change the default in the charm.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/752464

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/752464
Committed: https://git.openstack.org/cgit/openstack/charm-mysql-innodb-cluster/commit/?id=93bf629ad2022c13d2d91fdca1b560adc2fa7882
Submitter: Zuul
Branch: master

commit 93bf629ad2022c13d2d91fdca1b560adc2fa7882
Author: Aurelien Lourot <email address hidden>
Date: Thu Sep 17 15:06:38 2020 +0200

    Increase default expel-timeout

    In order to reduce chances of spurious "super-read-only" failures.

    Change-Id: I3cfbd6991b743e92d447ba06aa0e466631cec4f6
    Closes-Bug: #1882205

[Aurelien Lourot (aurelien-lourot)]

Re-opening as this is still happening:

https://review.opendev.org/#/c/748652/
https://openstack-ci-reports.ubuntu.com/artifacts/test_charm_pipeline_func_full/openstack/charm-octavia/748652/3/7000/index.html

2020-09-28 16:01:01 ERROR juju-log cluster:3: Hook error:
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
    bus.dispatch(restricted=restricted_mode)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
    _invoke(other_handlers)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
    handler.invoke()
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 181, in invoke
    self._action(*args)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/charm/reactive/mysql_innodb_cluster_handlers.py", line 103, in create_remote_cluster_user
    instance.create_cluster_user(
  File "lib/charm/openstack/mysql_innodb_cluster.py", line 524, in create_cluster_user
    m_helper.execute(SQL_CLUSTER_USER_GRANT.format(
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/charmhelpers/contrib/database/mysql.py", line 178, in execute
    cursor.execute(sql)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/MySQLdb/cursors.py", line 206, in execute
    res = self._query(query)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/MySQLdb/cursors.py", line 319, in _query
    db.query(q)
  File "/var/lib/juju/agents/unit-mysql-innodb-cluster-1/.venv/lib/python3.8/site-packages/MySQLdb/connections.py", line 259, in query
    _mysql.connection.query(self, query)
MySQLdb._exceptions.OperationalError: (1290, 'The MySQL server is running with the --super-read-only option so it cannot execute this statement')

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/756410

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/756410
Committed: https://git.openstack.org/cgit/openstack/charm-mysql-innodb-cluster/commit/?id=6cc500974d958982e6692d87a6a99354d9f2b50a
Submitter: Zuul
Branch: master

commit 6cc500974d958982e6692d87a6a99354d9f2b50a
Author: David Ames <email address hidden>
Date: Tue Oct 6 15:58:35 2020 -0700

    Handle attempts to write to a RO node

    Though the charm took pains to avoid it there are states the charm can
    get into in which it attempts to write to a read only node.

    This change catches the OperationalError error code 1290: "The MySQL server
    is running with the --super-read-only option so it cannot execute this
    statement" gracefully.

    Change-Id: If9188f5e72701f4bd7575b09217f355fa3d505a2
    Closes-Bug: #1882205