yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1376211] Re: Retry mechanism does not work on startup when used with MySQL

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Doug Hellmann <doug@xxxxxxxxxxxxxxxx>
Date: Fri, 03 Oct 2014 20:11:04 -0000
Reply-to: Bug 1376211 <1376211@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: oslo.db
    Milestone: None => next-kilo

** Also affects: oslo.db/juno
   Importance: Undecided
       Status: New

** Changed in: oslo.db/juno
   Importance: Undecided => High

** Changed in: oslo.db/juno
       Status: New => Confirmed

** Changed in: oslo.db/juno
     Assignee: (unassigned) => Roman Podoliaka (rpodolyaka)

** Changed in: oslo.db/juno
    Milestone: None => next-juno

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1376211

Title:
  Retry mechanism does not work on startup when used with MySQL

Status in OpenStack Neutron (virtual network service):
  Confirmed
Status in Oslo Database library:
  In Progress
Status in oslo.db juno series:
  Confirmed

Bug description:
  This is initially revealed as Red Hat bug:
  https://bugzilla.redhat.com/show_bug.cgi?id=1144181

  The problem shows up when Neutron or any other oslo.db based projects
  start while MySQL server is not up yet. Instead of retrying connection
  as per max_retries and retry_interval, service just crashes with
  return code 1.

  This is because during engine initialization, "engine.execute("SHOW
  VARIABLES LIKE 'sql_mode'")" is called, which opens the connection,
  *before* _test_connection() succeeds. So the server just bail out to
  sys.exit() at the top of the stack.

  This behaviour was checked for both oslo.db 0.4.0 and 1.0.1.

  I suspect this is a regression from the original db code from oslo-
  incubator though I haven't checked it specifically.

  The easiest way to reproduce the traceback is:

  1. stop MariaDB.
  2. execute the following Python script:

  '''
  import oslo.db.sqlalchemy.session

  url = 'mysql://neutron:123456@10.35.161.235/neutron'
  engine = oslo.db.sqlalchemy.session.EngineFacade(url)
  '''

  The following traceback can be seen in service log:

  2014-10-01 13:46:10.588 5812 TRACE neutron Traceback (most recent call last):
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/bin/neutron-server", line 10, in <module>
  2014-10-01 13:46:10.588 5812 TRACE neutron     sys.exit(main())
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/server/__init__.py", line 47, in main
  2014-10-01 13:46:10.588 5812 TRACE neutron     neutron_api = service.serve_wsgi(service.NeutronApiService)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/service.py", line 105, in serve_wsgi
  2014-10-01 13:46:10.588 5812 TRACE neutron     LOG.exception(_('Unrecoverable error: please check log '
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/openstack/common/excutils.py", line 82, in __exit__
  2014-10-01 13:46:10.588 5812 TRACE neutron     six.reraise(self.type_, self.value, self.tb)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/service.py", line 102, in serve_wsgi
  2014-10-01 13:46:10.588 5812 TRACE neutron     service.start()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/service.py", line 73, in start
  2014-10-01 13:46:10.588 5812 TRACE neutron     self.wsgi_app = _run_wsgi(self.app_name)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/service.py", line 168, in _run_wsgi
  2014-10-01 13:46:10.588 5812 TRACE neutron     app = config.load_paste_app(app_name)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/common/config.py", line 182, in load_paste_app
  2014-10-01 13:46:10.588 5812 TRACE neutron     app = deploy.loadapp("config:%s" % config_path, name=app_name)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 247, in loadapp
  2014-10-01 13:46:10.588 5812 TRACE neutron     return loadobj(APP, uri, name=name, **kw)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 272, in loadobj
  2014-10-01 13:46:10.588 5812 TRACE neutron     return context.create()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
  2014-10-01 13:46:10.588 5812 TRACE neutron     return self.object_type.invoke(self)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 144, in invoke
  2014-10-01 13:46:10.588 5812 TRACE neutron     **context.local_conf)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/util.py", line 56, in fix_call
  2014-10-01 13:46:10.588 5812 TRACE neutron     val = callable(*args, **kw)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/urlmap.py", line 25, in urlmap_factory
  2014-10-01 13:46:10.588 5812 TRACE neutron     app = loader.get_app(app_name, global_conf=global_conf)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 350, in get_app
  2014-10-01 13:46:10.588 5812 TRACE neutron     name=name, global_conf=global_conf).create()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
  2014-10-01 13:46:10.588 5812 TRACE neutron     return self.object_type.invoke(self)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 144, in invoke
  2014-10-01 13:46:10.588 5812 TRACE neutron     **context.local_conf)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/util.py", line 56, in fix_call
  2014-10-01 13:46:10.588 5812 TRACE neutron     val = callable(*args, **kw)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/auth.py", line 67, in pipeline_factory
  2014-10-01 13:46:10.588 5812 TRACE neutron     app = loader.get_app(pipeline[-1])
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 350, in get_app
  2014-10-01 13:46:10.588 5812 TRACE neutron     name=name, global_conf=global_conf).create()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
  2014-10-01 13:46:10.588 5812 TRACE neutron     return self.object_type.invoke(self)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 146, in invoke
  2014-10-01 13:46:10.588 5812 TRACE neutron     return fix_call(context.object, context.global_conf, **context.local_conf)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/util.py", line 56, in fix_call
  2014-10-01 13:46:10.588 5812 TRACE neutron     val = callable(*args, **kw)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/api/v2/router.py", line 71, in factory
  2014-10-01 13:46:10.588 5812 TRACE neutron     return cls(**local_config)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/api/v2/router.py", line 75, in __init__
  2014-10-01 13:46:10.588 5812 TRACE neutron     plugin = manager.NeutronManager.get_plugin()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 219, in get_plugin
  2014-10-01 13:46:10.588 5812 TRACE neutron     return weakref.proxy(cls.get_instance().plugin)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 213, in get_instance
  2014-10-01 13:46:10.588 5812 TRACE neutron     cls._create_instance()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/openstack/common/lockutils.py", line 249, in inner
  2014-10-01 13:46:10.588 5812 TRACE neutron     return f(*args, **kwargs)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 199, in _create_instance
  2014-10-01 13:46:10.588 5812 TRACE neutron     cls._instance = cls()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 114, in __init__
  2014-10-01 13:46:10.588 5812 TRACE neutron     plugin_provider)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 140, in _get_plugin_instance
  2014-10-01 13:46:10.588 5812 TRACE neutron     return plugin_class()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 113, in __init__
  2014-10-01 13:46:10.588 5812 TRACE neutron     self.type_manager.initialize()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py", line 74, in initialize
  2014-10-01 13:46:10.588 5812 TRACE neutron     driver.obj.initialize()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/type_vlan.py", line 162, in initialize
  2014-10-01 13:46:10.588 5812 TRACE neutron     self._sync_vlan_allocations()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/type_vlan.py", line 99, in _sync_vlan_allocations
  2014-10-01 13:46:10.588 5812 TRACE neutron     session = db_api.get_session()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 60, in get_session
  2014-10-01 13:46:10.588 5812 TRACE neutron     facade = _create_facade_lazily()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 34, in _create_facade_lazily
  2014-10-01 13:46:10.588 5812 TRACE neutron     _FACADE = session.EngineFacade.from_config(cfg.CONF, sqlite_fk=True)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/oslo/db/sqlalchemy/session.py", line 795, in from_config
  2014-10-01 13:46:10.588 5812 TRACE neutron     retry_interval=conf.database.retry_interval)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/oslo/db/sqlalchemy/session.py", line 711, in __init__
  2014-10-01 13:46:10.588 5812 TRACE neutron     **engine_kwargs)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/oslo/db/sqlalchemy/session.py", line 386, in create_engine
  2014-10-01 13:46:10.588 5812 TRACE neutron     connection_trace=connection_trace
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/oslo/db/sqlalchemy/utils.py", line 890, in __call__
  2014-10-01 13:46:10.588 5812 TRACE neutron     self._url_from_target(target), target, arg, kw)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/oslo/db/sqlalchemy/utils.py", line 927, in _dispatch_on
  2014-10-01 13:46:10.588 5812 TRACE neutron     return self._dispatch_on_db_driver(dbname, driver, arg, kw)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/oslo/db/sqlalchemy/utils.py", line 981, in _dispatch_on_db_driver
  2014-10-01 13:46:10.588 5812 TRACE neutron     if self._invoke_fn(fn, arg, kw) is not None:
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/oslo/db/sqlalchemy/utils.py", line 930, in _invoke_fn
  2014-10-01 13:46:10.588 5812 TRACE neutron     return fn(*arg, **kw)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib/python2.7/site-packages/oslo/db/sqlalchemy/session.py", line 456, in _init_events
  2014-10-01 13:46:10.588 5812 TRACE neutron     realmode = engine.execute("SHOW VARIABLES LIKE 'sql_mode'").fetchone()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1751, in execute
  2014-10-01 13:46:10.588 5812 TRACE neutron     connection = self.contextual_connect(close_with_result=True)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1799, in contextual_connect
  2014-10-01 13:46:10.588 5812 TRACE neutron     self.pool.connect(),
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 338, in connect
  2014-10-01 13:46:10.588 5812 TRACE neutron     return _ConnectionFairy._checkout(self)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 641, in _checkout
  2014-10-01 13:46:10.588 5812 TRACE neutron     fairy = _ConnectionRecord.checkout(pool)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 440, in checkout
  2014-10-01 13:46:10.588 5812 TRACE neutron     rec = pool._do_get()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 961, in _do_get
  2014-10-01 13:46:10.588 5812 TRACE neutron     return self._create_connection()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 285, in _create_connection
  2014-10-01 13:46:10.588 5812 TRACE neutron     return _ConnectionRecord(self)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 411, in __init__
  2014-10-01 13:46:10.588 5812 TRACE neutron     self.connection = self.__connect()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 537, in __connect
  2014-10-01 13:46:10.588 5812 TRACE neutron     connection = self.__pool._creator()
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/strategies.py", line 96, in connect
  2014-10-01 13:46:10.588 5812 TRACE neutron     connection_invalidated=invalidated
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
  2014-10-01 13:46:10.588 5812 TRACE neutron     reraise(type(exception), exception, tb=exc_tb)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/strategies.py", line 90, in connect
  2014-10-01 13:46:10.588 5812 TRACE neutron     return dialect.connect(*cargs, **cparams)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 377, in connect
  2014-10-01 13:46:10.588 5812 TRACE neutron     return self.dbapi.connect(*cargs, **cparams)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/MySQLdb/__init__.py", line 81, in Connect
  2014-10-01 13:46:10.588 5812 TRACE neutron     return Connection(*args, **kwargs)
  2014-10-01 13:46:10.588 5812 TRACE neutron   File "/usr/lib64/python2.7/site-packages/MySQLdb/connections.py", line 187, in __init__
  2014-10-01 13:46:10.588 5812 TRACE neutron     super(Connection, self).__init__(*args, **kwargs2)
  2014-10-01 13:46:10.588 5812 TRACE neutron OperationalError: (OperationalError) (2003, "Can't connect to MySQL server on '10.35.161.235' (111)") None None

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1376211/+subscriptions