[Bug 1561154] [NEW] failed to migrate database during shared-db-relation-changed

Francis Ginther francis.ginther at canonical.com
Wed Mar 23 18:57:57 UTC 2016 

Public bug reported:

Hit this while testing openstack autopilot deployments with landscape in CI. The job for this is:
https://ci.lscape.net/job/landscape-system-tests/1500/

I'm also attaching the 'juju status' form this run. The logs below
indicate that cinder is trying to connect to a sql service on
hendel.scapestack, but the mysql services are running on other nodes.

[from /var/log/juju/unit-cinder-0.log]
2016-03-22 16:22:25 INFO shared-db-relation-changed No handlers could be found for logger "oslo_config.cfg"
2016-03-22 16:22:25 INFO shared-db-relation-changed /usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py:241: NotSupportedWarning: Configuration option(s) ['use_tpool'] not supported
2016-03-22 16:22:25 INFO shared-db-relation-changed   exception.NotSupportedWarning
2016-03-22 16:22:25 INFO shared-db-relation-changed 2016-03-22 16:22:25.501 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 10 attempts left.
2016-03-22 16:22:35 INFO shared-db-relation-changed 2016-03-22 16:22:35.512 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 9 attempts left.
2016-03-22 16:22:45 INFO shared-db-relation-changed 2016-03-22 16:22:45.522 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 8 attempts left.
2016-03-22 16:22:55 INFO shared-db-relation-changed 2016-03-22 16:22:55.530 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 7 attempts left.
2016-03-22 16:23:05 INFO shared-db-relation-changed 2016-03-22 16:23:05.541 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 6 attempts left.
2016-03-22 16:23:15 INFO shared-db-relation-changed 2016-03-22 16:23:15.547 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 5 attempts left.
2016-03-22 16:23:25 INFO shared-db-relation-changed 2016-03-22 16:23:25.557 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 4 attempts left.
2016-03-22 16:23:35 INFO shared-db-relation-changed 2016-03-22 16:23:35.566 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 3 attempts left.
2016-03-22 16:23:45 INFO shared-db-relation-changed 2016-03-22 16:23:45.572 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 2 attempts left.
2016-03-22 16:23:55 INFO shared-db-relation-changed 2016-03-22 16:23:55.576 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 1 attempts left.
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 CRITICAL cinder [-] DBConnectionError: (pymysql.err.OperationalError) (2003, 'Can\'t connect to MySQL server on \'10.96.15.208\' ((1129, u"Host \'hendel.scapestack\' is blocked because of many connection errors; unblock with \'mysqladmin flush-hosts\'"))')
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder Traceback (most recent call last):
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/bin/cinder-manage", line 10, in <module>
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     sys.exit(main())
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/cmd/manage.py", line 593, in main
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     fn(*fn_args)
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/cmd/manage.py", line 232, in sync
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     return db_migration.db_sync(version)
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/db/migration.py", line 57, in db_sync
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     engine = db_api.get_engine()
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 87, in get_engine
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     facade = _create_facade_lazily()
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 74, in _create_facade_lazily
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     **dict(CONF.database)
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 943, in __init__
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     slave_connection=slave_connection)
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 338, in _start
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     engine_args, maker_args)
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 362, in _setup_for_connection
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     sql_connection=sql_connection, **engine_kwargs)
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py", line 152, in create_engine
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     test_conn = _test_connection(engine, max_retries, retry_interval)
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py", line 334, in _test_connection
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     six.reraise(type(de_ref), de_ref)
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "<string>", line 2, in reraise
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder DBConnectionError: (pymysql.err.OperationalError) (2003, 'Can\'t connect to MySQL server on \'10.96.15.208\' ((1129, u"Host \'hendel.scapestack\' is blocked because of many connection errors; unblock with \'mysqladmin flush-hosts\'"))')
2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder 
2016-03-22 16:24:05 INFO shared-db-relation-changed Traceback (most recent call last):
2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/shared-db-relation-changed", line 557, in <module>
2016-03-22 16:24:05 INFO shared-db-relation-changed     hooks.execute(sys.argv)
2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/charmhelpers/core/hookenv.py", line 717, in execute
2016-03-22 16:24:05 INFO shared-db-relation-changed     self._hooks[hook_name]()
2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/charmhelpers/core/host.py", line 438, in wrapped_f
2016-03-22 16:24:05 INFO shared-db-relation-changed     f(*args, **kwargs)
2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/shared-db-relation-changed", line 228, in db_changed
2016-03-22 16:24:05 INFO shared-db-relation-changed     migrate_database()
2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/charmhelpers/core/decorators.py", line 42, in _retry_on_exception_inner_2
2016-03-22 16:24:05 INFO shared-db-relation-changed     return f(*args, **kwargs)
2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/cinder_utils.py", line 577, in migrate_database
2016-03-22 16:24:05 INFO shared-db-relation-changed     subprocess.check_call(cmd)
2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/usr/lib/python2.7/subprocess.py", line 540, in check_call
2016-03-22 16:24:05 INFO shared-db-relation-changed     raise CalledProcessError(retcode, cmd)
2016-03-22 16:24:05 INFO shared-db-relation-changed subprocess.CalledProcessError: Command '['cinder-manage', 'db', 'sync']' returned non-zero exit status 1
2016-03-22 16:24:05 ERROR juju.worker.uniter.operation runhook.go:107 hook "shared-db-relation-changed" failed: exit status 1

** Affects: cinder (Juju Charms Collection)
     Importance: Undecided
         Status: New


** Tags: landscape

** Attachment added: "juju-status.txt"
   https://bugs.launchpad.net/bugs/1561154/+attachment/4608911/+files/juju-status.txt

-- 
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to cinder in Juju Charms Collection.
Matching subscriptions: charm-bugs
https://bugs.launchpad.net/bugs/1561154

Title:
  failed to migrate database during shared-db-relation-changed

Status in cinder package in Juju Charms Collection:
  New

Bug description:
  Hit this while testing openstack autopilot deployments with landscape in CI. The job for this is:
  https://ci.lscape.net/job/landscape-system-tests/1500/

  I'm also attaching the 'juju status' form this run. The logs below
  indicate that cinder is trying to connect to a sql service on
  hendel.scapestack, but the mysql services are running on other nodes.

  [from /var/log/juju/unit-cinder-0.log]
  2016-03-22 16:22:25 INFO shared-db-relation-changed No handlers could be found for logger "oslo_config.cfg"
  2016-03-22 16:22:25 INFO shared-db-relation-changed /usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py:241: NotSupportedWarning: Configuration option(s) ['use_tpool'] not supported
  2016-03-22 16:22:25 INFO shared-db-relation-changed   exception.NotSupportedWarning
  2016-03-22 16:22:25 INFO shared-db-relation-changed 2016-03-22 16:22:25.501 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 10 attempts left.
  2016-03-22 16:22:35 INFO shared-db-relation-changed 2016-03-22 16:22:35.512 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 9 attempts left.
  2016-03-22 16:22:45 INFO shared-db-relation-changed 2016-03-22 16:22:45.522 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 8 attempts left.
  2016-03-22 16:22:55 INFO shared-db-relation-changed 2016-03-22 16:22:55.530 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 7 attempts left.
  2016-03-22 16:23:05 INFO shared-db-relation-changed 2016-03-22 16:23:05.541 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 6 attempts left.
  2016-03-22 16:23:15 INFO shared-db-relation-changed 2016-03-22 16:23:15.547 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 5 attempts left.
  2016-03-22 16:23:25 INFO shared-db-relation-changed 2016-03-22 16:23:25.557 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 4 attempts left.
  2016-03-22 16:23:35 INFO shared-db-relation-changed 2016-03-22 16:23:35.566 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 3 attempts left.
  2016-03-22 16:23:45 INFO shared-db-relation-changed 2016-03-22 16:23:45.572 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 2 attempts left.
  2016-03-22 16:23:55 INFO shared-db-relation-changed 2016-03-22 16:23:55.576 456 WARNING oslo_db.sqlalchemy.engines [-] SQL connection failed. 1 attempts left.
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 CRITICAL cinder [-] DBConnectionError: (pymysql.err.OperationalError) (2003, 'Can\'t connect to MySQL server on \'10.96.15.208\' ((1129, u"Host \'hendel.scapestack\' is blocked because of many connection errors; unblock with \'mysqladmin flush-hosts\'"))')
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder Traceback (most recent call last):
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/bin/cinder-manage", line 10, in <module>
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     sys.exit(main())
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/cmd/manage.py", line 593, in main
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     fn(*fn_args)
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/cmd/manage.py", line 232, in sync
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     return db_migration.db_sync(version)
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/db/migration.py", line 57, in db_sync
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     engine = db_api.get_engine()
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 87, in get_engine
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     facade = _create_facade_lazily()
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 74, in _create_facade_lazily
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     **dict(CONF.database)
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 943, in __init__
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     slave_connection=slave_connection)
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 338, in _start
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     engine_args, maker_args)
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 362, in _setup_for_connection
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     sql_connection=sql_connection, **engine_kwargs)
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py", line 152, in create_engine
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     test_conn = _test_connection(engine, max_retries, retry_interval)
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py", line 334, in _test_connection
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder     six.reraise(type(de_ref), de_ref)
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder   File "<string>", line 2, in reraise
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder DBConnectionError: (pymysql.err.OperationalError) (2003, 'Can\'t connect to MySQL server on \'10.96.15.208\' ((1129, u"Host \'hendel.scapestack\' is blocked because of many connection errors; unblock with \'mysqladmin flush-hosts\'"))')
  2016-03-22 16:24:05 INFO shared-db-relation-changed 2016-03-22 16:24:05.587 456 ERROR cinder 
  2016-03-22 16:24:05 INFO shared-db-relation-changed Traceback (most recent call last):
  2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/shared-db-relation-changed", line 557, in <module>
  2016-03-22 16:24:05 INFO shared-db-relation-changed     hooks.execute(sys.argv)
  2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/charmhelpers/core/hookenv.py", line 717, in execute
  2016-03-22 16:24:05 INFO shared-db-relation-changed     self._hooks[hook_name]()
  2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/charmhelpers/core/host.py", line 438, in wrapped_f
  2016-03-22 16:24:05 INFO shared-db-relation-changed     f(*args, **kwargs)
  2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/shared-db-relation-changed", line 228, in db_changed
  2016-03-22 16:24:05 INFO shared-db-relation-changed     migrate_database()
  2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/charmhelpers/core/decorators.py", line 42, in _retry_on_exception_inner_2
  2016-03-22 16:24:05 INFO shared-db-relation-changed     return f(*args, **kwargs)
  2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/var/lib/juju/agents/unit-cinder-0/charm/hooks/cinder_utils.py", line 577, in migrate_database
  2016-03-22 16:24:05 INFO shared-db-relation-changed     subprocess.check_call(cmd)
  2016-03-22 16:24:05 INFO shared-db-relation-changed   File "/usr/lib/python2.7/subprocess.py", line 540, in check_call
  2016-03-22 16:24:05 INFO shared-db-relation-changed     raise CalledProcessError(retcode, cmd)
  2016-03-22 16:24:05 INFO shared-db-relation-changed subprocess.CalledProcessError: Command '['cinder-manage', 'db', 'sync']' returned non-zero exit status 1
  2016-03-22 16:24:05 ERROR juju.worker.uniter.operation runhook.go:107 hook "shared-db-relation-changed" failed: exit status 1

To manage notifications about this bug go to:
https://bugs.launchpad.net/charms/+source/cinder/+bug/1561154/+subscriptions

More information about the Ubuntu-openstack-bugs mailing list