time_monotonically_increases always produces values in the past, and can produce duplicates

[jamadden]

There are two separate but related issues here.

The first is that if two or more functions are wrapped with time_monotonically_increases within the scope of a test (support test_foo() calls setup1 and setup2, both of which are wrapped), duplicate times will be produced (both starting at 0). This is not monotonic (although it is within the possibility of the real time.time function).

Second, the values are always in the past (beginning at 0). If anyone had captured a time before the wrapping took place, the new values will sort earlier, which can be a problem.

Both of these are potential issues when using this function together with ZODB's MappingStorage and DemoStorage. It wants to assign transaction IDs for every commit based on the current timestamp. Lookup of objects is partially based on these timestamps. If timestamps repeat or are in the past of where they should be, baffling errors can result:

 File "//tests/mock_dataserver.py", line 234, in __enter__
    sitemanc = conn.root()['nti.dataserver']
  File "/eggs/ZODB-5.2.0-py2.7.egg/ZODB/Connection.py", line 351, in root
    return RootConvenience(self.get(z64))
  File "//eggs/ZODB-5.2.0-py2.7.egg/ZODB/Connection.py", line 247, in get
    p, _ = self._storage.load(oid)
  File "//eggs/ZODB-5.2.0-py2.7.egg/ZODB/mvccadapter.py", line 146, in load
    raise POSException.ReadConflictError(repr(oid))
ReadConflictError: '\x00\x00\x00\x00\x00\x00\x00\x00'

Here, '\x00\x00\x00\x00\x00\x00\x00\x00' is the root OID, which is guaranteed to exist (and this exception is raised if it isn't found). Examining the storage, we see a mix of timestamp values; the most recent timestamp, recorded by the outside storage is in the past (76.0 seconds):

ipdb> self
<ZODB.mvccadapter.MVCCAdapterInstance object at 0x126734050>
ipdb> self._storage
DemoStorage("DemoStorage('MappingStorage', 'MappingStorage')", 'MappingStorage')

ipdb> self._storage.base.changes._data.get(oid).keys()
['\x03\xbe\x9d\xde\xd4\x9fUU', '\x03\xbe\x9d\xde\xd4\xa4\xc7D', '\x03\xbe\x9d\xde\xddN\r\xee']
ipdb> u64(self._storage.lastTransaction())
161050971118781508
ipdb> [u64(x) for x in self._storage.base.changes._data.get(oid).keys()]
[269826608064320853, 269826608064677700, 269826608209989102]
ipdb> u64(self._storage.base.lastTransaction())
269826652665136076
ipdb> u64(self._storage.changes.lastTransaction())
161050971118781508

In [15]: ts = TS(p64(161050971118781508))

 In [17]: ts.timeTime()
 Out[17]: 76.0

 In [20]: str(ts)
 Out[20]: '1970-01-01 00:01:16.000000'

Contrast with this value, which is clearly a real time stamp:

 ipdb> u64(self._storage.base.lastTransaction())
 269826652665136076

 In [18]: TS(p64(269826608064320853)).timeTime()
 Out[18]: 1491930169.833374

 In [19]: str(TS(p64(269826608064320853)))
 Out[19]: '2017-04-11 17:02:49.833374'

Both of these problems can be avoided if t_m_i produces times starting with the real time, and also keeps a global value to increment. Something like:

i = [max(i, real_time_time())]
def incr():
   i[0] += 1
   return i

This may need to be optional or in a different function, because I'm sure there are tests relying on the sequence being repeatable and starting at a known value.

Thoughts @jzuech3 @papachoco ?

[jzuech3]

I would prefer making time_monotonically_increases start at a base time (the current time). I think any tests relying on incremental increases should be changed to testing relative times (greater-than, less-than). Plus it would avoid getting puzzling errors in the future if someone uses the wrong fudged time.

[jamadden]

I would prefer making time_monotonically_increases start at a base time (the current time)...Plus it would avoid getting puzzling errors in the future if someone uses the wrong fudged time.

I do agree that's safest, but it might result in a lot of test cleanup. What if we keep the existing version but have it use warnings to emit a warning, possibly with an environment variable causing it to raise an exception? Then the old behaviour could be removed at the next major release. That keeps this version drop-in compatible and provides a transition path to help locate the problematic areas.

OTOH, if you feel that the test cleanup is quickly manageable, we can go ahead and change the behaviour and release a major version bump.

[jamadden]

(Oh, also the documentation for this function is atrocious. It's not clear what the signature is or how to use it. That should be improved too.)

[jzuech3]

Maybe we make the change we want and then trial run the tests to see what kind of issues we'll have. Hopefully it's relatively simple to fix a handful of test cases.

We'd also want this default behavior so that relative create times are in-step. E.g. we want stuff created in the layer to be created/modified before any items created in the tests.

[jamadden]

Yeah, good points. OK, so I'll put out a 2.0 with this as default, and you can alternate your version pin to address issues as necessary. Sound good?

[jzuech3]

Yep, let's do it

[jamadden]

See PR #6. I think another set of eyeballs on it would be good.