Edgewall Software
Modify

Opened 6 years ago

Last modified 6 years ago

#11301 new defect

intermittent failure with notification test

Reported by: Christian Boos Owned by:
Priority: normal Milestone: next-major-releases
Component: ticket system Version: 1.0-stable
Severity: normal Keywords: test timestamp datamodel
Cc: Branch:
Release Notes:
API Changes:

Description

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

     
    110110        ticket2 = self._create_a_ticket()
    111111        ticket2.insert()
    112112        ticket2['summary'] = 'Bar'
     113        ticket2['foo'] = 'New value 0'
     114        ticket2.save_changes('santa', 'this is my comment 0')
    113115        ticket2['foo'] = 'New value'
    114116        ticket2.save_changes('santa', 'this is my comment')
    115117        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…

Attachments (0)

Change History (5)

comment:1 by Remy Blank, 6 years ago

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

comment:2 by Christian Boos, 6 years ago

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

     
    2020from __future__ import with_statement
    2121
    2222import re
    23 from datetime import datetime
     23from datetime import datetime, timedelta
    2424
    2525from trac.attachment import Attachment
    2626from trac import core
     
    301301        :since 1.0: the `cnum` parameter is deprecated, and threading should
    302302        be controlled with the `replyto` argument
    303303        """
     304        retry = 1
     305        if when is None:
     306            when = datetime.now(utc) # this might only have msec resolution
     307            retry = 10 # assume we're not going faster
     308        while retry:
     309            retry -= 1
     310            try:
     311                self.save_changes_at(when, author, comment, db, cnum, replyto)
     312                break
     313            except self.env.db_exc.IntegrityError, e:
     314                now = datetime.now(utc)
     315                if now == when:
     316                    when += timedelta(0, 0, 10 - retry)
     317                else:
     318                    when = now
     319
     320    def save_changes_at(self, when, author=None, comment=None, db=None,
     321                        cnum='', replyto=None):
    304322        assert self.exists, "Cannot update a new ticket"
    305323
    306324        if 'cc' in self.values:
     
    311329        if (not comment or not comment.strip()) and props_unchanged:
    312330            return False # Not modified
    313331
    314         if when is None:
    315             when = datetime.now(utc)
    316332        when_ts = to_utimestamp(when)
    317333
    318334        if 'component' in self.values:

That works, but is not so pretty…

comment:3 by Christian Boos, 6 years ago

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

comment:4 by Christian Boos, 6 years ago

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 ;-) ).

Last edited 6 years ago by Christian Boos (previous) (diff)

comment:5 by Christian Boos, 6 years ago

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

Modify Ticket

Change Properties
Set your email in Preferences
Action
as new The ticket will remain with no owner.
The ticket will be disowned. Next status will be 'new'.
as The resolution will be set. Next status will be 'closed'.
The owner will be changed from (none) to anonymous. Next status will be 'assigned'.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.