Comment 0 for bug 1425896

Revision history for this message
Kairat Kushaev (kkushaev) wrote :

Hello Guys!
When I tested heat with tox i got the following exception:
Traceback (most recent call last):
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 457, in fire_timers
    timer()
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/eventlet/hubs/timer.py", line 58, in __call__
    cb(*args, **kw)
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/eventlet/greenthread.py", line 214, in main
    result = function(*args, **kwargs)
  File "heat/engine/service.py", line 115, in _start_with_trace
    return func(*args, **kwargs)
  File "heat/engine/service.py", line 603, in _stack_create
    stack.adopt()
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/osprofiler/profiler.py", line 105, in wrapper
    return f(*args, **kwargs)
  File "heat/engine/stack.py", line 708, in adopt
    creator(timeout=self.timeout_secs())
  File "heat/engine/scheduler.py", line 174, in __call__
    self.start(timeout=timeout)
  File "heat/engine/scheduler.py", line 199, in start
    self.step()
  File "heat/engine/scheduler.py", line 222, in step
    next(self._runner)
  File "heat/engine/scheduler.py", line 321, in wrapper
    subtask = parent.throw(*sys.exc_info())
  File "heat/engine/stack.py", line 631, in stack_task
    yield action_task()
  File "heat/engine/scheduler.py", line 295, in wrapper
    step = next(subtask)
  File "heat/engine/scheduler.py", line 376, in __call__
    r.start()
  File "heat/engine/scheduler.py", line 199, in start
    self.step()
  File "heat/engine/scheduler.py", line 222, in step
    next(self._runner)
  File "heat/engine/scheduler.py", line 321, in wrapper
    subtask = parent.throw(*sys.exc_info())
  File "heat/engine/resource.py", line 536, in _do_action
    yield self.action_handler_task(action, args=handler_args)
  File "/usr/lib/python2.7/contextlib.py", line 35, in __exit__
    self.gen.throw(type, value, traceback)
  File "heat/engine/resource.py", line 475, in _action_recorder
    self.state_set(action, self.FAILED, six.text_type(failure))
  File "heat/engine/resource.py", line 1001, in state_set
    self._add_event(action, status, reason)
  File "heat/engine/resource.py", line 943, in _add_event
    ev.store()
  File "heat/engine/event.py", line 87, in store
    new_ev = db_api.event_create(self.context, ev)
  File "heat/db/api.py", line 214, in event_create
    return IMPL.event_create(context, values)
  File "heat/db/sqlalchemy/api.py", line 629, in event_create
    if ((event_count_all_by_stack(context, values['stack_id']) >=
  File "heat/db/sqlalchemy/api.py", line 609, in event_count_all_by_stack
    return _query_all_by_stack(context, stack_id).count()
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2640, in count
    return self.from_self(col).scalar()
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2426, in scalar
    ret = self.one()
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2395, in one
    ret = list(self)
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2438, in __iter__
    return self._execute_and_instances(context)
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2451, in _execute_and_instances
    close_with_result=True)
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2442, in _connection_from_session
    **kw)
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 854, in connection
    close_with_result=close_with_result)
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 858, in _connection_for_bind
    return self.transaction._connection_for_bind(engine)
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 305, in _connection_for_bind
    self._assert_active()
  File "/home/kairat/MyProjects/heat/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 214, in _assert_active
    % self._rollback_exception
InvalidRequestError: This Session's transaction has been rolled back due to a previous exception during flush. To begin a new transaction with this Session, first issue Session.rollback(). Original exception was: UPDATE statement on table 'resource' expected to update 1 row(s); 0 were matched.

Before testing i removed my previous venv in .tox.
Unfortunately, this trace is reproducing from time to time.
I did some code analysis but I am not sure if it is right or not:
1) The exception is raising when smbd is trying to flush a session that was not commited (or rollback).
2) it is very likely that exception is raising because of this code in engine.resource:
self._store_or_update(action, status, reason)

        if new_state != old_state:
            self._add_event(action, status, reason)
3) when _store_or_update was called the following code in models.HeatBase is updating a resource
       if not session:
            session = orm_session.Session.object_session(self)
            if not session:
                session = get_session()
        session.begin()
        for k, v in six.iteritems(values):
            setattr(self, k, v)
        session.commit()
    You can see that there is not rollback and potentially get_session can be used for transaction.
4) when _add_event was called the following code is creating an event in sql_alchemy.api:
    event_ref.update(values)
    event_ref.save(_session(context))
   The _session returns the following:
        return (context and context.session) or get_session()
   save method is executing flush so we have the error above.
I looked into code and it seems that sqlalchemy is creating a new session during get_sessioncall() but it is somehow using the same session for add_event and update_and_save operations.