Juju Charms Collection
galera-cluster package

hook failed install _mysql_exceptions.OperationalError: (1047, 'Unknown command')

Bug #1494981 reported by Larry Michel
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
galera-cluster (Juju Charms Collection)
Fix Released
Critical
Larry Michel

Bug Description

While deploying OpenStack with galera-cluster, I am running into hook installation failure. It's not happening for every deployment but seems to be an issue with some builds:

+ . ./pipeline_parameters
++ export OPENSTACK_RELEASE=kilo
++ OPENSTACK_RELEASE=kilo
++ export COMPUTE=nova-lxc
++ COMPUTE=nova-lxc
++ export BLOCK_STORAGE=cinder-vnx
++ BLOCK_STORAGE=cinder-vnx
++ export IMAGE_STORAGE=glance-ceph
++ IMAGE_STORAGE=glance-ceph
++ export PIPELINE_ID=ac0e1835-1709-4db6-8c72-a57133e61453
++ PIPELINE_ID=ac0e1835-1709-4db6-8c72-a57133e61453
++ export MYSQL=galera-cluster
++ MYSQL=galera-cluster
++ export NETWORKING=nova-network-flatdhcp
++ NETWORKING=nova-network-flatdhcp
++ export UBUNTU_RELEASE=trusty
++ UBUNTU_RELEASE=trusty

From juju_status.yaml:

galera-cluster:
    charm: local:trusty/galera-cluster-45
    exposed: false
    relations:
      cluster:
      - galera-cluster
    service-status:
      current: error
      message: 'hook failed: "install"'
      since: 11 Sep 2015 21:32:51Z
    units:
      galera-cluster/0:
        agent-state: error
        agent-state-info: 'hook failed: "install"'
        agent-status:
          current: idle
          since: 11 Sep 2015 21:32:51Z
          version: 1.24.5
        agent-version: 1.24.5
        machine: '1'
        public-address: hayward-40.oil
        workload-status:
          current: error
          message: 'hook failed: "install"'
          since: 11 Sep 2015 21:32:51Z

From unit log:

2015-09-11 21:32:33 INFO install Setting up galera-3 (25.3.12-1trusty) ...
2015-09-11 21:32:45 INFO install Setting up libhtml-template-perl (2.95-1) ...
2015-09-11 21:32:45 INFO install Processing triggers for libc-bin (2.19-0ubuntu6.6) ...
2015-09-11 21:32:45 INFO install Processing triggers for ureadahead (0.100.0-16) ...
2015-09-11 21:32:46 INFO install * MySQL server PID file could not be found!
2015-09-11 21:32:46 INFO install Starting MySQL
2015-09-11 21:32:50 INFO install .... *
2015-09-11 21:32:50 INFO worker.uniter.jujuc server.go:158 running hook tool "juju-log" ["-l" "DEBUG" "Using existing password file '/var/lib/charm/galera-cluster/mysql.passwd'"]
2015-09-11 21:32:50 DEBUG worker.uniter.jujuc server.go:159 hook context id "galera-cluster/0-install-646729208580310464"; dir "/var/lib/juju/agents/unit-galera-cluster-0/charm"
2015-09-11 21:32:50 DEBUG juju-log Using existing password file '/var/lib/charm/galera-cluster/mysql.passwd'
2015-09-11 21:32:50 INFO worker.uniter.jujuc server.go:158 running hook tool "juju-log" ["-l" "DEBUG" "Opening db connection for root@localhost"]
2015-09-11 21:32:50 DEBUG worker.uniter.jujuc server.go:159 hook context id "galera-cluster/0-install-646729208580310464"; dir "/var/lib/juju/agents/unit-galera-cluster-0/charm"
2015-09-11 21:32:50 DEBUG juju-log Opening db connection for root@localhost
2015-09-11 21:32:51 INFO install Traceback (most recent call last):
2015-09-11 21:32:51 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/install", line 444, in <module>
2015-09-11 21:32:51 INFO install main()
2015-09-11 21:32:51 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/install", line 438, in main
2015-09-11 21:32:51 INFO install hooks.execute(sys.argv)
2015-09-11 21:32:51 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/charmhelpers/core/hookenv.py", line 544, in execute
2015-09-11 21:32:51 INFO install self._hooks[hook_name]()
2015-09-11 21:32:51 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/install", line 99, in install
2015-09-11 21:32:51 INFO install configure_sstuser(mysql_password)
2015-09-11 21:32:51 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/galera_utils.py", line 158, in configure_sstuser
2015-09-11 21:32:51 INFO install m_helper.execute(SQL_SST_USER_SETUP.format(sst_password))
2015-09-11 21:32:51 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/charmhelpers/contrib/database/mysql.py", line 134, in execute
2015-09-11 21:32:51 INFO install cursor.execute(sql)
2015-09-11 21:32:51 INFO install File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
2015-09-11 21:32:51 INFO install self.errorhandler(self, exc, value)
2015-09-11 21:32:51 INFO install File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2015-09-11 21:32:51 INFO install raise errorclass, errorvalue
2015-09-11 21:32:51 INFO install _mysql_exceptions.OperationalError: (1047, 'Unknown command')
2015-09-11 21:32:51 INFO juju.worker.uniter.context context.go:543 handling reboot
2015-09-11 21:32:51 ERROR juju.worker.uniter.operation runhook.go:103 hook "install" failed: exit status 1
2015-09-11 21:32:51 DEBUG juju.worker.uniter modes.go:31 [AGENT-STATUS] failed: run install hook
2015-09-11 21:32:51 INFO juju.worker.uniter modes.go:543 ModeContinue exiting
2015-09-11 21:32:51 INFO juju.worker.uniter modes.go:541 ModeHookError starting

I am attaching the unit log.

See original description
Tags: oil

Related branches

lp:~lmic/charms/trusty/galera-cluster/galera-cluster+source-galera-config-option
Adam Israel (community): Approve
Tim Van Steenburgh (community): Needs Information
Diff: 67 lines (+27/-5)
2 files modified
config.yaml (+9/-1)
hooks/galera_hooks.py (+18/-4)
Revision history for this message
Larry Michel (lmic) wrote :
description: updated
Revision history for this message
Larry Michel (lmic) wrote :
Download full text (4.5 KiB)

We also hit it this morning with icehouse and trusty:

2015-09-17 12:57:30 INFO install Setting up galera-3 (25.3.12-1trusty) ...
2015-09-17 12:57:30 INFO install Setting up libhtml-template-perl (2.95-1) ...
2015-09-17 12:57:30 INFO install Processing triggers for libc-bin (2.19-0ubuntu6.6) ...
2015-09-17 12:57:30 INFO install Processing triggers for ureadahead (0.100.0-16) ...
2015-09-17 12:57:32 INFO install * MySQL server PID file could not be found!
2015-09-17 12:57:32 INFO install Starting MySQL
2015-09-17 12:57:39 DEBUG juju.worker.leadership tracker.go:138 galera-cluster/0 renewing lease for galera-cluster leadership
2015-09-17 12:57:39 DEBUG juju.worker.leadership tracker.go:165 checking galera-cluster/0 for galera-cluster leadership
2015-09-17 12:57:39 DEBUG juju.worker.leadership tracker.go:180 galera-cluster/0 confirmed for galera-cluster leadership until 2015-09-17 12:58:39.535692631 +0000 UTC
2015-09-17 12:57:39 INFO juju.worker.leadership tracker.go:182 galera-cluster/0 will renew galera-cluster leadership at 2015-09-17 12:58:09.535692631 +0000 UTC
2015-09-17 12:57:42 INFO install .......... *
2015-09-17 12:57:42 INFO worker.uniter.jujuc server.go:158 running hook tool "juju-log" ["-l" "DEBUG" "Using existing password file '/var/lib/charm/galera-cluster/mysql.passwd'"]
2015-09-17 12:57:43 DEBUG worker.uniter.jujuc server.go:159 hook context id "galera-cluster/0-install-7730906871290845817"; dir "/var/lib/juju/agents/unit-galera-cluster-0/charm"
2015-09-17 12:57:43 DEBUG juju-log Using existing password file '/var/lib/charm/galera-cluster/mysql.passwd'
2015-09-17 12:57:44 INFO worker.uniter.jujuc server.go:158 running hook tool "juju-log" ["-l" "DEBUG" "Opening db connection for root@localhost"]
2015-09-17 12:57:44 DEBUG worker.uniter.jujuc server.go:159 hook context id "galera-cluster/0-install-7730906871290845817"; dir "/var/lib/juju/agents/unit-galera-cluster-0/charm"
2015-09-17 12:57:44 DEBUG juju-log Opening db connection for root@localhost
2015-09-17 12:57:44 INFO install Traceback (most recent call last):
2015-09-17 12:57:44 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/install", line 444, in <module>
2015-09-17 12:57:44 INFO install main()
2015-09-17 12:57:44 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/install", line 438, in main
2015-09-17 12:57:44 INFO install hooks.execute(sys.argv)
2015-09-17 12:57:44 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/charmhelpers/core/hookenv.py", line 544, in execute
2015-09-17 12:57:44 INFO install self._hooks[hook_name]()
2015-09-17 12:57:44 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/install", line 99, in install
2015-09-17 12:57:44 INFO install configure_sstuser(mysql_password)
2015-09-17 12:57:44 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/galera_utils.py", line 158, in configure_sstuser
2015-09-17 12:57:44 INFO install m_helper.execute(SQL_SST_USER_SETUP.format(sst_password))
2015-09-17 12:57:44 INFO install File "/var/lib/juju/agents/unit-galera-cluster-0/charm/hooks/charmhelpers/contrib/database/mysql....

Read more...

Revision history for this message
Larry Michel (lmic) wrote :

This has also been recreated on some Juno deployments as well.

Revision history for this message
Greg Lutostanski (lutostag) wrote :

Looks like it's having trouble connecting to the sql database to setup users. Can you verify that the service is running and you can interrogate it?

Revision history for this message
Larry Michel (lmic) wrote :

For this one, the issue seemed that there is a window immediately following service restart where mysql isn't quite ready to process commands. Implementing a 1 second time in between the service_restart() and command seemed to work, and I was not able to hit this failure through testing...Removed the timeout and the problem returned.

The proposed fix is to retry after 5 seconds if we hit this Exception.

Larry Michel (lmic)
Changed in galera-cluster (Juju Charms Collection):
status: New → In Progress
Revision history for this message
Philip Stoev (philip-stoev-f) wrote :

Yes, a sleep would be an appropriate fix in this case.

Larry Michel (lmic)
Changed in galera-cluster (Juju Charms Collection):
importance: Undecided → Critical
assignee: nobody → Larry Michel (lmic)
Larry Michel (lmic)
Changed in galera-cluster (Juju Charms Collection):
status: In Progress → Fix Committed
Larry Michel (lmic)
Changed in galera-cluster (Juju Charms Collection):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.