tox log fills with 'Unexpected error occurred while processing Exception'

[Peter Stachowski]

In the Trove py27 tests, with oslo.utils 2.6.0 the following error fills the log and causes the process to seem to hang (it'll run for hours).

015-10-14 20:04:30.153 21155 ERROR root [-] Unexpected error occurred while processing Exception
015-10-14 20:04:30.153 21155 ERROR root Traceback (most recent call last):
015-10-14 20:04:30.153 21155 ERROR root File "/opt/trove/trove/.tox/py27/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 226, in inner_func
015-10-14 20:04:30.153 21155 ERROR root time.sleep(1)
015-10-14 20:04:30.153 21155 ERROR root File "/opt/trove/trove/trove/tests/util/event_simulator.py", line 138, in fake_sleep
015-10-14 20:04:30.153 21155 ERROR root raise RuntimeError("Sleeping for no reason.")
015-10-14 20:04:30.153 21155 ERROR root RuntimeError: Sleeping for no reason.

from /opt/trove/trove/.tox/py27/local/lib/python2.7/site-packages/oslo_utils/excutils.py

def forever_retry_uncaught_exceptions(infunc):
    def inner_func(*args, **kwargs):
        last_log_time = 0
        last_exc_message = None
        exc_count = 0
        while True:
            try:
                return infunc(*args, **kwargs)
            except Exception as exc:
                this_exc_message = six.u(str(exc))
                if this_exc_message == last_exc_message:
                    exc_count += 1
                else:
                    exc_count = 1
                # Do not log any more frequently than once a minute unless
                # the exception message changes
                cur_time = int(time.time())
                if (cur_time - last_log_time > 60 or
                        this_exc_message != last_exc_message):
                    logging.exception(
                        _LE('Unexpected exception occurred %d time(s)... '
                            'retrying.') % exc_count)
                    last_log_time = cur_time
                    last_exc_message = this_exc_message
                    exc_count = 0
                # This should be a very rare event. In case it isn't, do
                # a sleep.
                time.sleep(1)
    return inner_func

from /opt/trove/trove/trove/tests/util/event_simulator.py

def fake_sleep(time_to_sleep):
    """Simulates sleep.

    Puts the coroutine which calls it to sleep. If a coroutine object is not
    associated with the caller this will fail.
    """
    global sleep_allowance
    sleep_allowance -= 1
    if not other_threads_are_active():
        if sleep_allowance < -1:
            raise RuntimeError("Sleeping for no reason.")
        else:
            return # Forgive the thread for calling this for one time.
    sleep_allowance = allowable_empty_sleeps

    cr = Coroutine.get_current()
    for ft in fake_threads:
        if ft['greenlet'].id == cr.id:
            ft['next_sleep_time'] = time_to_sleep

    cr.sleep()

This seems to have been caused by: https://github.com/openstack/oslo.utils/commit/6010fb3fff11fc961c5c8038543122b909e15666#diff-3cce8243cb5c7f567a816fe701341c50

It may be fixed already by : https://review.openstack.org/#/c/230619/

If that is the case, we (in Trove) may need a something like the following in global-requirements.txt:

oslo.utils>=2.0.0,!=2.6.0 # Apache-2.0

Thx!