Interference between TestTempestWorkspace and TestCallUntilTrue cause unit test job to randomly fail

[Ilya Shakhat]

Tempest unit test job fails if TestTempestWorkspace is executed before TestCallUntilTrue.

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    Traceback (most recent call last):
      File "tempest/tests/lib/common/utils/test_test_utils.py", line 119, in test_call_until_true_with_params
        kwargs=dict(foo='bar', bar='foo'))
      File "tempest/tests/lib/common/utils/test_test_utils.py", line 158, in _test_call_until_true
        *args, **kwargs)
      File "tempest/lib/common/utils/test_utils.py", line 109, in call_until_true
        func_name, time.time() - begin_time)
      File "/usr/lib/python2.7/logging/__init__.py", line 1440, in debug
        self.logger.debug(msg, *args, **kwargs)
      File "/usr/lib/python2.7/logging/__init__.py", line 1155, in debug
        self._log(DEBUG, msg, args, **kwargs)
      File "/usr/lib/python2.7/logging/__init__.py", line 1285, in _log
        record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
      File "/usr/lib/python2.7/logging/__init__.py", line 1259, in makeRecord
        rv = LogRecord(name, level, fn, lno, msg, args, exc_info, func)
      File "/usr/lib/python2.7/logging/__init__.py", line 242, in __init__
        ct = time.time()
      File "/opt/stack/tempest/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1062, in __call__
        return _mock_self._mock_call(*args, **kwargs)
      File "/opt/stack/tempest/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1128, in _mock_call
        ret_val = effect(*args, **kwargs)
      File "tempest/tests/lib/common/utils/test_test_utils.py", line 183, in mocked_time
        return next(time_iterator)
    StopIteration

The issue affects both py27 and py35 jobs.

Steps to reproduce:
-------------------

tox -epy35 -- --until-failure --serial tempest.tests.cmd.test_workspace.TestTempestWorkspace.test_run_workspace_list TestCallUntilTrue

Note that this is localized repro, in the gate error has probabilistic nature.

Analysis:
---------

Success of tests from TestCallUntilTrue depends on log level. This is result of mocking time.time() certain number of times. Mocking does not take into account LOG.debug() statement, which adds one more call of time.time() (see http://git.openstack.org/cgit/openstack/tempest/tree/tempest/lib/common/utils/test_utils.py#n108) Usually log level is WARNING, however after TestTempestWorkspace the log level stays at DEBUG and is not restored.

[Manik Bindlish (manikbindlish19)]

I have run below on my system but tests were passing without any failure or skipping.

tox -epy35 -- --until-failure --serial tempest.tests.cmd.test_workspace.TestTempestWorkspace.test_run_workspace_list TestCallUntilTrue

======
Totals
======
Ran: 24535 tests in 8655.8703 sec.
 - Passed: 24535
 - Skipped: 0
 - Expected Fail: 0
 - Unexpected Success: 0
 - Failed: 0
Sum of execute time for each test: 3184.5269 sec.

==============
Worker Balance
==============
 - Worker 0 (24535 tests) => 2:24:15.870346

Is this still occurring on your environment, if yes then could you please share more detail to reproduce it?

[Ilya Shakhat (shakhat)]

Looks like the bug has disappeared. I run these tests on infra and no failure occurred (http://logs.openstack.org/71/631771/2/check/test-bug-1797870-a/6729a22/job-output.txt.gz#_2019-01-18_10_46_44_555629).

2019-01-18 10:46:44.272113 | TASK [tox : Emit tox command]
2019-01-18 10:46:44.555629 | Running tox: tox -epy35 -- --until-failure --serial tempest.tests.cmd.test_workspace.TestTempestWorkspace.test_run_workspace_list TestCallUntilTrue
2019-01-18 10:46:44.608202 |
2019-01-18 10:46:44.608622 | TASK [tox : Run tox]
2019-01-18 10:46:46.561555 | ubuntu-xenial | py35 develop-inst-noop: /home/zuul/src/git.openstack.org/openstack/tempest
2019-01-18 10:46:47.011740 | ubuntu-xenial | py35 installed: .....
2019-01-18 10:46:47.011884 | ubuntu-xenial | py35 run-test-pre: PYTHONHASHSEED='1403726507'
2019-01-18 10:46:47.011982 | ubuntu-xenial | py35 runtests: commands[0] | find . -type f -name '*.pyc' -delete
2019-01-18 10:46:47.076757 | ubuntu-xenial | py35 runtests: commands[1] | stestr --test-path ./tempest/tests run --until-failure --serial tempest.tests.cmd.test_workspace.TestTempestWorkspace.test_run_workspace_list TestCallUntilTrue

........

2019-01-18 11:13:25.868468 | ubuntu-xenial | ======
2019-01-18 11:13:25.868495 | ubuntu-xenial | Totals
2019-01-18 11:13:25.868516 | ubuntu-xenial | ======
2019-01-18 11:13:25.868560 | ubuntu-xenial | Ran: 4350 tests in 1593.3778 sec.
2019-01-18 11:13:25.868588 | ubuntu-xenial | - Passed: 4350
2019-01-18 11:13:25.868614 | ubuntu-xenial | - Skipped: 0
2019-01-18 11:13:25.868645 | ubuntu-xenial | - Expected Fail: 0
2019-01-18 11:13:25.868680 | ubuntu-xenial | - Unexpected Success: 0
2019-01-18 11:13:25.868705 | ubuntu-xenial | - Failed: 0
2019-01-18 11:13:25.868762 | ubuntu-xenial | Sum of execute time for each test: 647.0440 sec.

Closing the issue as non-reproducible.