test_create_with_live_time can fail if run at "just the wrong time"

[Tony Breeds]

In https://review.openstack.org/#/c/381890 we got the following failure:
| Captured traceback:
| ~~~~~~~~~~~~~~~~~~~
| Traceback (most recent call last):
| File "/home/jenkins/workspace/gate-cross-glance-python27-db-ubuntu-xenial/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1305, in patched
| return func(*args, **keywargs)
| File "glance/tests/unit/v2/test_tasks_resource.py", line 367, in test_create_with_live_time
| self.assertEqual(CONF.task.task_time_to_live, task_live_time_hour)
| File "/home/jenkins/workspace/gate-cross-glance-python27-db-ubuntu-xenial/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 411, in assertEqual
| self.assertThat(observed, matcher, message)
| File "/home/jenkins/workspace/gate-cross-glance-python27-db-ubuntu-xenial/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 498, in assertThat
| raise mismatch_error
| testtools.matchers._impl.MismatchError: 48 != 47

This can happen if the exires_at and updated_at are not 2 days apart (ignoring seconds and microsecond) (from [2])

        # ignore second and microsecond to avoid flaky runs
        task_live_time = (success_task.expires_at.replace(second=0,
                                                          microsecond=0) -
                          success_task.updated_at.replace(second=0,
                                                          microsecond=0))

The following interactive example shows what I mean:

balder:glance tony8129$ python
Python 2.7.12 (default, Jun 29 2016, 12:46:54)
[GCC 4.2.1 Compatible Apple LLVM 6.0 (clang-600.0.57)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import datetime
>>> class FakeTask(object):
... pass
>>> success_task = FakeTask()
>>> success_task.expires_at = datetime.datetime(2016, 10, 3, 00, 00, 00)
>>> success_task.updated_at = datetime.datetime(2016, 10, 1, 00, 00, 00)
>>> task_live_time = (success_task.expires_at.replace(second=0,
>>> microsecond=0) -
... success_task.updated_at.replace(second=0,
... microsecond=0))
... task_live_time
>>> datetime.timedelta(2)
>>> success_task.updated_at = datetime.datetime(2016, 10, 1, 00, 01, 00)
>>> task_live_time = (success_task.expires_at.replace(second=0,
>>> microsecond=0) -
... success_task.updated_at.replace(second=0,
... microsecond=0))
... task_live_time
>>> datetime.timedelta(1, 86340)
task_live_time_hour = (task_live_time.days * 24 +
>>> task_live_time.seconds / 3600)
>>> task_live_time_hour
>>> 47

I couldn't find the specific code but I assume something like:
db.expires_at = now() + CONF.task.task_time_to_live # mm:59
db_updated_at = now() # 1+mm:00

Happens causing this false positive.

[1] http://logs.openstack.org/90/381890/3/gate/gate-cross-glance-python27-db-ubuntu-xenial/1dff2a8/console.html#_2016-10-06_02_26_57_318997
[2] https://github.com/openstack/glance/blob/master/glance/tests/unit/v2/test_tasks_resource.py#L361-L364

[Ian Cordasco (icordasc)]

So, this was a problem in the past as well. It was "fixed" to make it less flakey but it's still flakey. It is presently still a problem and I'm wondering if there's a better way of making this less flakey than we currently have (besides just deleting the test).

[Tony Breeds (o-tony)]

You might me able to mock whatever the timestamp primitive is (datetime.now()?) to return known timestamps but that's brittle if you can't predict the number of calls to the mock.

now = real_datetime.now()
mock_now.side_effect = [now] * 100
*might* work but who knows what else it'll mess up ;P

I didn't spend too long looking for the base code as I started getting lost. If you wanna help me find the code I'm happy to have a look at it with you

You *could* convert task_live_time_hour into a float and then compare it to a range:
---
from __future__ import print_function
from __future__ import division

import datetime

class FakeTask(object):
    pass

task_time_to_live = 48
now = datetime.datetime(2016, 12, 31, 23, 59, 59, 999999)

success_task = FakeTask()
success_task.expires_at = now + datetime.timedelta(hours=task_time_to_live)

# success_task.updated_at = now + datetime.timedelta(microseconds=1) # Passes
# success_task.updated_at = now + datetime.timedelta(minutes=1) # Passes
success_task.updated_at = now + datetime.timedelta(minutes=1, microseconds=1) # Fails

task_live_time = (success_task.expires_at - success_task.updated_at)
task_live_time_hour = (task_live_time.days * 24 +
                       task_live_time.seconds / 3600)

print('Now : %s' % (now))
print('Updated at : %s' % (success_task.updated_at))
print('Expires at : %s' % (success_task.expires_at))
print('Task live time : %s' % (task_live_time))
print('Min : %s' % (task_time_to_live - 1/60))
print('Hours : %s' % (task_live_time_hour))
print('Max : %s' % (float(task_time_to_live)))

print(task_time_to_live - 1/60 <= task_live_time_hour <= task_time_to_live)
---

that *seems* to work and IMO validates that expires_at is being set correctly to include the task_ttl and allows up to a minutes variation.

Anyway it's up to y'all I think the mock thing is the least gross