OperationalError when performing db operations just after startup

[Adam Collard]

Using percona cluster from cs:~openstack-charmers/trusty/percona-cluster-10

Deployed 3 units on Trusty LXCs using MAAS 1.7.0 and Juju 1.20.14

2014-12-15 11:50:38 INFO install 141215 11:50:38 InnoDB: Using Linux native AIO
2014-12-15 11:50:38 INFO install 141215 11:50:38 InnoDB: Initializing buffer pool, size = 7.7G
2014-12-15 11:50:39 INFO install 141215 11:50:39 InnoDB: Completed initialization of buffer pool
2014-12-15 11:50:39 INFO install 141215 11:50:39 InnoDB: highest supported file format is Barracuda.
2014-12-15 11:50:39 INFO install 141215 11:50:39 InnoDB: Waiting for the background threads to start
2014-12-15 11:50:40 INFO install 141215 11:50:40 Percona XtraDB (http://www.percona.com) 5.5.37-35.0-35.0 started; log sequence number 1597945
2014-12-15 11:50:40 INFO install 141215 11:50:40 [Note] WSREP: Service disconnected.
2014-12-15 11:50:41 INFO install 141215 11:50:41 [Note] WSREP: Some threads may fail to exit.
2014-12-15 11:50:41 INFO install 141215 11:50:41 InnoDB: Starting shutdown...
2014-12-15 11:50:45 INFO install 141215 11:50:45 InnoDB: Shutdown completed; log sequence number 1597945
2014-12-15 11:50:50 INFO install Error in my_thread_global_end(): 1 threads didn't exit
2014-12-15 11:51:25 INFO install * Starting MySQL (Percona XtraDB Cluster) database server mysqld
2014-12-15 11:51:29 INFO install ...done.
2014-12-15 11:51:29 INFO install Processing triggers for libc-bin (2.19-0ubuntu6.4) ...
2014-12-15 11:51:29 INFO install Processing triggers for ureadahead (0.100.0-16) ...
2014-12-15 11:51:30 INFO juju-log Writing file /etc/mysql/my.cnf root:root 444
2014-12-15 11:51:30 INFO juju-log Unknown hook start - skipping.
2014-12-15 11:51:30 WARNING juju.worker.uniter.charm git_deployer.go:200 no current staging repo
2014-12-15 11:51:31 INFO juju-log cluster:14: Unknown hook cluster-relation-joined - skipping.
2014-12-15 11:51:32 INFO juju-log cluster:14: Writing file /etc/mysql/my.cnf root:root 444
2014-12-15 11:51:32 INFO juju-log cluster:14: Unknown hook cluster-relation-joined - skipping.
2014-12-15 11:51:33 INFO juju-log cluster:14: Writing file /etc/mysql/my.cnf root:root 444
2014-12-15 11:51:51 WARNING juju-log shared-db:51: eligible_leader is deprecated. Please consider using is_elected_leader instead.
2014-12-15 11:51:52 WARNING juju-log shared-db:53: eligible_leader is deprecated. Please consider using is_elected_leader instead.
2014-12-15 11:51:52 WARNING juju-log shared-db:54: eligible_leader is deprecated. Please consider using is_elected_leader instead.
2014-12-15 11:51:52 INFO shared-db-relation-changed Traceback (most recent call last):
2014-12-15 11:51:52 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/shared-db-relation-changed", line 339, in <module>
2014-12-15 11:51:52 INFO shared-db-relation-changed main()
2014-12-15 11:51:52 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/shared-db-relation-changed", line 333, in main
2014-12-15 11:51:52 INFO shared-db-relation-changed hooks.execute(sys.argv)
2014-12-15 11:51:52 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/charmhelpers/core/hookenv.py", line 502, in execute
2014-12-15 11:51:52 INFO shared-db-relation-changed self._hooks[hook_name]()
2014-12-15 11:51:52 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/shared-db-relation-changed", line 221, in shared_db_changed
2014-12-15 11:51:52 INFO shared-db-relation-changed settings['username'])
2014-12-15 11:51:52 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/mysql.py", line 199, in configure_db
2014-12-15 11:51:52 INFO shared-db-relation-changed m_helper.create_database(database)
2014-12-15 11:51:52 INFO shared-db-relation-changed File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/mysql.py", line 55, in create_database
2014-12-15 11:51:52 INFO shared-db-relation-changed .format(db_name))
2014-12-15 11:51:52 INFO shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
2014-12-15 11:51:52 INFO shared-db-relation-changed self.errorhandler(self, exc, value)
2014-12-15 11:51:52 INFO shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2014-12-15 11:51:52 INFO shared-db-relation-changed raise errorclass, errorvalue
2014-12-15 11:51:52 INFO shared-db-relation-changed _mysql_exceptions.OperationalError: (1047, 'Unknown command')

[Edward Hope-Morley (hopem)]

Adam, I suspect you might have hit the cluster bootstrap issue that has been observed when deploying multiple units of percona at once. Can you please provide the output of:

juju ssh percona/0 "mysql -uroot -pagoodpassword -e \"show status like 'wsrep_cluster%';\""

...replacing the username/password and unit number appropriately and running for all units deployed.

In particular check that the cluster size is equal to the number of units of percona you have deployed.

[Launchpad Janitor (janitor)]

[Expired for percona-cluster (Juju Charms Collection) because there has been no activity for 60 days.]

[David Britton (dpb)]

landscape@juju-machine-0-lxc-1:~$ juju run --unit mysql/0 'mysql -uroot -pW6y6jmRwCrS1Etu -e "show status like \"wsrep_cluster%\";"'
Variable_name Value
wsrep_cluster_conf_id 18446744073709551615
wsrep_cluster_size 0
wsrep_cluster_state_uuid 96d11a4e-4cca-11e5-99a7-9ad0cd043bb1
wsrep_cluster_status non-Primary
landscape@juju-machine-0-lxc-1:~$ set -o vi
landscape@juju-machine-0-lxc-1:~$ juju run --unit mysql/1 'mysql -uroot -pW6y6jmRwCrS1Etu -e "show status like \"wsrep_cluster%\";"'
Variable_name Value
wsrep_cluster_conf_id 18446744073709551615
wsrep_cluster_size 0
wsrep_cluster_state_uuid 96d11a4e-4cca-11e5-99a7-9ad0cd043bb1
wsrep_cluster_status non-Primary
landscape@juju-machine-0-lxc-1:~$ juju run --unit mysql/2 'mysql -uroot -pW6y6jmRwCrS1Etu -e "show status like \"wsrep_cluster%\";"'
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)
ERROR subprocess encountered error code 1
landscape@juju-machine-0-lxc-1:~$

[David Britton (dpb)]

  min-cluster-size:
    description: |
      Minimum number of units expected to exist before charm will attempt to
      bootstrap percona cluster. If no value is provided this setting is
      ignored.
    type: int
    value: 3
  nagios_context:

[David Britton (dpb)]

Charm version used: cs:trusty/percona-cluster-26
deploying icehouse

[Larry Michel (lmic)]

I hit similar issue with galera-cluster deploying a single unit. This bug 1494981.

[Andreas Hasenack (ahasenack)]

Happened again, this time with cs:trusty/percona-cluster-31

[Andreas Hasenack (ahasenack)]

Logs are in bug #1537679 if needed.

[James Page (james-page)]

This looks like a problem with doing db ops just after a restart of pxc; the fix into galera-cluster was to pause and retry; I'd suggest that we use the retry_on_error helper todo the same, but against other dbops as well.

[James Page (james-page)]

that said the cluster in comment #3 looks pretty broken as well.

I suspect that was as a result of races building clusters in juju versions pre-leader election.