intermittent failure with notification test

[Christian Boos]

The usual make test after a recent pull on trunk gave me the following:

ERROR: test_from_author (trac.ticket.tests.notification.NotificationTestCase)
Using the reporter or change author as the notification sender
----------------------------------------------------------------------
Traceback (most recent call last):
  File "c:\Trac\repos\trunk\trac\ticket\tests\notification.py", line 369, in test_from_author
    ticket.save_changes('noemail', 'More changes')
  File "c:\Trac\repos\trunk\trac\ticket\model.py", line 387, in save_changes
    old_db_values[name], db_values.get(name, '')))
  File "c:\Trac\repos\trunk\trac\db\util.py", line 121, in execute
    cursor.execute(query, params)
  File "c:\Trac\repos\trunk\trac\db\util.py", line 54, in execute
    r = self.cursor.execute(sql_escape_percent(sql), args)
  File "c:\Trac\repos\trunk\trac\db\sqlite_backend.py", line 78, in execute
    result = PyFormatCursor.execute(self, *args)
  File "c:\Trac\repos\trunk\trac\db\sqlite_backend.py", line 56, in execute
    args or [])
  File "c:\Trac\repos\trunk\trac\db\sqlite_backend.py", line 48, in _rollback_on_error
    return function(self, *args, **kwargs)
IntegrityError: columns ticket, time, field are not unique

----------------------------------------------------------------------
Ran 1212 tests in 13.759s

FAILED (errors=1)

Twice in a row… also on 1.0-stable, then not anymore: I could do 10 runs without any errors. Wonder if it's a timing issue or something like that. The errors all happened with Python 2.7 but I don't think this has anything to do with it.

Looking at the code, I find a succession of 4 save_changes calls, without much done in between. It might simply be that the 3rd save_changes (line 369) happens within the same microsecond(?) than the 2nd save_changes (line 361).

This raises the interesting question if we should try to fix this for the tests only or if it would be useful to introduce a small delay in general for the save_changes so that this API becomes "timing" safe.

For example, here's a very simple way to reproduce this error:

trac/ticket/tests/model.py

@@ -110 +110 @@
         ticket2 = self._create_a_ticket()
         ticket2.insert()
         ticket2['summary'] = 'Bar'
+        ticket2['foo'] = 'New value 0'
+        ticket2.save_changes('santa', 'this is my comment 0')
         ticket2['foo'] = 'New value'
         ticket2.save_changes('santa', 'this is my comment')
         return ticket2

But "fixing" this is not straightforward, as experimenting shows that it's not obvious how to pick the appropriate value for the delay. On Windows, adding a call to time.sleep(0.001) did the trick, but 0.0001 didn't. I wonder if 0.001 would be good enough for all platforms and versions of Python.

Then of course, using "time" as part of the key was also not the best idea we ever had…

[Remy Blank]

How about catching the IntegrityError and retrying (a limited number of times) with an incremented timestamp?

[Christian Boos]

Yes, that could work. Actually the problem can be narrowed to the following part:

        if when is None:
            when = datetime.now(utc)
        when_ts = to_utimestamp(when)

In my environment at least (Python 2.7 on Windows 7 (x64)), the resolution is only milliseconds:

>>> [datetime.now().microsecond for x in range(100)]
[172000, 172000, 172000, ..., 172000, 172000]

So we could indeed do something like that:

trac/ticket/model.py

@@ -20 +20 @@
 from __future__ import with_statement
 
 import re
-from datetime import datetime
+from datetime import datetime, timedelta
 
 from trac.attachment import Attachment
 from trac import core
@@ -301 +301 @@
         :since 1.0: the `cnum` parameter is deprecated, and threading should
         be controlled with the `replyto` argument
         """
+        retry = 1
+        if when is None:
+            when = datetime.now(utc) # this might only have msec resolution
+            retry = 10 # assume we're not going faster
+        while retry:
+            retry -= 1
+            try:
+                self.save_changes_at(when, author, comment, db, cnum, replyto)
+                break
+            except self.env.db_exc.IntegrityError, e:
+                now = datetime.now(utc)
+                if now == when:
+                    when += timedelta(0, 0, 10 - retry)
+                else:
+                    when = now
+
+    def save_changes_at(self, when, author=None, comment=None, db=None,
+                        cnum='', replyto=None):
         assert self.exists, "Cannot update a new ticket"
 
         if 'cc' in self.values:
@@ -311 +329 @@
         if (not comment or not comment.strip()) and props_unchanged:
             return False # Not modified
 
-        if when is None:
-            when = datetime.now(utc)
         when_ts = to_utimestamp(when)
 
         if 'component' in self.values:

That works, but is not so pretty…

[Christian Boos]

Well, considering that even when "when" is given, it probably comes from another datetime.now() call, we could always attempt to retry.

[Christian Boos]

I came up with the following, repos:cboos.git:t11301-replay-transactions (more a RFC than something final, in particular I see now that the docstrings need fixing and a useless import in ticket.model; I should get back to the habit of reviewing locally first ;-) ).

[Christian Boos]

Probably need to do two more things here:

• don't even attempt to retry if we're in a nested transaction
• test how this behaves with other backends, PostgreSQL in particular