Booked times aren't updated correctly with concurrent edits

[Phillip Leder <phillip.leder@…>]

If there are concurrent edits only the first submit will update the total time, while all submits are stored in the trac-db.

[Russ Tyndall]

Well that is interesting. Those edits don't even seem particularly concurrent.

We have never run into this (or noticed it at least). I am guessing that instead of adding hours to totalhours, we should set totalhours to the sum of hours below this change (trac changes are to the microsecond I think, which *usually* avoids actual concurrent edits). Best guess is that the first change is going through, but not having updated total_hours, while the second change starts and queries the old value for total_hours.

More useful information:

• it would be nice to have the actual timestamps / an export of the ticket_change table for that ticket
• What database backend is this using?
• Version of trac, version of plugin etc. (about trac logged in as admin has all this in a tidy copy-pastable block)

Thanks very much for reporting this bug

[Russ Tyndall]

In 14398:

Attempt at fixing concurrency errors in the ticket_daemon

Replaces stateful work with a handful of sql statements that will
behave correctly regardless of ordering in the case of concurrency

re #12173

[Russ Tyndall]

In 14401:

Porting concurrency fixes to Permissions branch re #12173

[Russ Tyndall]

In 14402:

(more)Porting concurrency fixes to Permissions branch re #12173

[Russ Tyndall]

In 14403:

concurrency fixes to ticket_daemon, version bumped to 1.4.1 re #12173

[Russ Tyndall]

I think this is tested and debugged. I know it works on sqlite, postgresql and have faith that it probably works against mysql too.

Please install 1.4.1 and hopefully never run into that edge case again, but rest assured if you do, it should work correctly now.

I fixed this by replacing stateful python calls with a couple of database commands that just set the state to be what it should be based on whats in the database. If it gets triggered twice it shouldnt matter now.

[Russ Tyndall]

In 14407:

Fixing new ticket hours after concurrency bug re #12173

[Russ Tyndall]

In 14408:

Fixing new ticket hours after concurrency bug (again) re #12173

[Phillip Leder <phillip.leder@…>]

Thank you for the fast feedback and (hopefully) fix. I will roll out the new version today and get back to you on friday.

The problem didn't occur sooner as we only recently upgraded our trac-server and with the old version submissions of concurrent edits were blocked completely for any editor but the first, as you surely know.

[Phillip Leder <phillip.leder@…>]

Unfortunately the fix doesn't seem to help. Below you will find the System Information and Plugin Information.

System Information
Package		Version
Trac 		1.0.1
Babel  		0.9.6
Docutils 	0.8.1
Genshi 		0.6 (with speedups)
mod_wsgi 	3.3 (WSGIProcessGroup WSGIApplicationGroup %{GLOBAL})
psycopg2 	2.4.5
Pygments 	1.5
Python 		2.7.3 (default, Mar 13 2014, 11:26:58) [GCC 4.7.2]
pytz 		2012c
setuptools 	0.6
Subversion 	1.6.17 (r1128011)
jQuery		1.7.2

Installed Plugins
Name				Version			Location
AutocompleteUsers 		0.4.2dev-r13962 	/usr/local/lib/python2.7/dist-packages/AutocompleteUsers-0.4.2dev_r13962-py2.7.egg
DefaultCc 			0.3dev-r13747	 	/usr/local/lib/python2.7/dist-packages/DefaultCc-0.3dev_r13747-py2.7.egg
RoadmapHours 			0.5 			/usr/local/lib/python2.7/dist-packages/RoadmapHours-0.5-py2.7.egg
timingandestimationplugin 	1.4.3b 			/usr/local/lib/python2.7/dist-packages/timingandestimationplugin-1.4.3b-py2.7.egg
TracAccountManager 		0.2.1dev	 	/usr/lib/pymodules/python2.7
TracCustomFieldAdmin 		0.2.6		 	/usr/lib/python2.7/dist-packages
TracMasterTickets 		3.0.2 			/usr/lib/python2.7/dist-packages

Unfortunately your fix broke something else causing booking hours to randomly fail. The comment was added, but the total hours weren't updated, as seen in the table below:

trac=# select * from ticket_change where ticket=10639;
 ticket |       time       |     author      |   field    | oldvalue | newvalue 
--------+------------------+-----------------+------------+----------+----------
  10639 | 1423217149689690 | j               | comment    | 2        | 
  10639 | 1423217149689690 | j               | hours      | 0        | 0,5
  10639 | 1418648453114760 | j               | totalhours | 0.0      | 0.25
  10639 | 1418648453114760 | j               | hours      | 0.0      | 0.25
(4 Zeilen)

The 0.25h were booked 8 weeks ago, the 0.5 today.

Then on other occasions the comment wouldn't be correct, but the total hours in the ticket overview were, as seen in the attached image .

I reverted back to 1.37b (the version we were running previously) now and everything but submissions after the ticket has been edited is working again (that is concurrency or am I misunderstanding the meaning?). Should I update to a version <1.4.3b or do you want me to try something else?

Best Regards, Phillip Leder

[Russ Tyndall]

everything but submissions after the ticket has been edited is working again (that is concurrency or am I misunderstanding the meaning?)

Ok, that is not the concurrency problem I was trying to fix, though the newest version should fix all of them. The newest version should also repair any missing total hours (the next time hours are submitted). It should also ensure that the "totalhours" field is always correct.

Both the old and new version of the plugin and the old have worked for us for concurrent edits for years. (We had another plugin that enabled concurrent edits before this was built into trac.) I am not sure what is going on in your setup, but hopefully we can get to the answer. I dont use the Permissions branch, but I did port the change to it and check that it worked.

We are running the same database and the same version of the plugin (1.4.3).

This is the query that the plugin is running to add ticket_change items. Does it correctly return the missing row for the above ticket that is missing total hours? It would also be responsible for the "1 to 0" problem in the screen shot. It looks right and is working for me.

      SELECT ticket, author, time, 'totalhours',  
               (SELECT SUM( CASE WHEN newvalue = '' OR newvalue IS NULL THEN 0
                           ELSE CAST( newvalue AS DECIMAL ) END ) as total
               FROM ticket_change as guts 
               WHERE guts.ticket = ticket_change.ticket AND guts.field='hours'
                 AND guts.time < ticket_change.time
              ) as oldvalue, 
              (SELECT SUM( CASE WHEN newvalue = '' OR newvalue IS NULL THEN 0
                           ELSE CAST( newvalue AS DECIMAL ) END ) as total
               FROM ticket_change as guts 
               WHERE guts.ticket = ticket_change.ticket AND guts.field='hours'
                 AND guts.time <= ticket_change.time
              ) as newvalue
          FROM ticket_change
         WHERE ticket=10639 and field='hours'
           AND NOT EXISTS( SELECT ticket
                             FROM ticket_change as guts 
                            WHERE guts.ticket=ticket_change.ticket
                              AND guts.author=ticket_change.author
                              AND guts.time=ticket_change.time
                              AND field='totalhours')

[Phillip Leder <phillip.leder@…>]

Unfortunately the last update doesn't seem to fix the problem either. While the concurrent edits did in fact work, the other stuff that was broken still is.

Somehow the hours that were added after the updated were added as "0,25" (the decimal seperator we use in Germany) instead of "0.25". This caused the error "DataError: FEHLER: ungültige Eingabesyntax für Typ numeric: »0,25«" ("DataError: ERROR: Invalid input syntax for type numeric: »0,25«") to appear. I attached a screenshot of the error for reference.

[Russ Tyndall]

In 14416:

attempting to better handle "," in numbers re #12173

[Russ Tyndall]

In 14419:

port hours/float/decimal point changes to Permissions branch, bumped version to 1.4.4 re #12173

[Russ Tyndall]

Ok, I tested that in *my* en_US locale, I can enter numbers with both decimal points (period and comma) and everything gets updated and set correctly.

I have no idea how this is going to play with trac / python / postgres when the locale is de_DE. I think it should be equivalent to what it was doing in previous versions, but its possible something is messed up.

Please let me know how it goes, I would like to get this working across locales as it was.

[Phillip Leder <phillip.leder@…>]

Sorry for the late comment, Unfortunately I can't test the update right now, as I have another project that needs my attention. I will test it sometime next week.

[Phillip Leder <phillip.leder@…>]

Today I tested 1.4.5b and this version seems to do the trick. I deployed it to the live server just now to see if my users run into any problems, but so far everything seems fine. Unless something else comes up this ticket can be closed. Thank you for your effort :)

[Russ Tyndall]

Hurrah! So pleased we were able to get the plugin to continue working for everyone (especially internationally).

[Phillip Leder <phillip.leder@…>]

Unfortunately there still seems to be a minor problem...

  10659 | 1424349850673911 | m               | totalhours | 41.50    | 44.00
  10659 | 1424349850673911 | m               | comment    | 28       | <comment>
  10659 | 1424349850673911 | m               | hours      | 0        | 2.5
  10659 | 1424349648145988 | c               | comment    | 27       | <comment>
  10659 | 1424349648145988 | c               | totalhours | 39.50    | 35.5
  10659 | 1424349648145988 | c               | hours      | 0        | 2
  10659 | 1424349635798471 | d               | totalhours | 37.50    | 39.50
  10659 | 1424349635798471 | d               | comment    | 26       | <comment>
  10659 | 1424349635798471 | d               | hours      | 0        | 2

The total hours are displayed correct, but somehow the time added by c substracts 4h instead of addind 2h, but it's only in the comment. The total time after another addition is fine. The comments don't contain any special characters, only default ASCII-characters.
In addition this problem doesn't happen all the time. This was the only time after patching the plugin.

[Russ Tyndall]

I cannot recreate the problem (but I also dont think we use trac as heavily as you). One suggestion I have is to delete all of the totalhours rows for that ticket and let the plugin recalculate them to see if this is recurring problem (which would indicate something funky in the data in the hours column). (Time will need to be added to the ticket to kick off the recalc process).

I was able to repeatedly remove all ticket_change 'totalhours' rows and recalculate them without error.

DELETE FROM ticket_change WHERE field='totalhours' where ticket=10659;

This is the query I used to track down missing / incorrect totalhours fields (perhaps it will help you find the problem?). It is based heavily on the query being run inside the plugin to create the rows.

I have many trac databases in pg database as different schemas and public views which allow querying all of them at once. (Which is the purpose below of all the commented out 'schema' column references).

SELECT * FROM (
   SELECT --ticket_change.schema, 
          ticket_change.ticket, ticket_change.author, ticket_change.time, 'totalhours',  
               (SELECT SUM( CASE WHEN newvalue = '' OR newvalue IS NULL THEN 0
                           ELSE CAST( newvalue AS DECIMAL ) END ) as total
               FROM ticket_change as guts 
               WHERE guts.ticket = ticket_change.ticket AND guts.field='hours'
                 AND guts.time < ticket_change.time
                 --AND ticket_change.schema = guts.schema
              ) as oldvalue, 
              (SELECT SUM( CASE WHEN newvalue = '' OR newvalue IS NULL THEN 0
                           ELSE CAST( newvalue AS DECIMAL ) END ) as total
               FROM ticket_change as guts 
               WHERE guts.ticket = ticket_change.ticket AND guts.field='hours'
                   AND guts.time <= ticket_change.time
                   --AND ticket_change.schema = guts.schema
              ) as newvalue, 
              existing.hours as existingtotalhours, newvalue as hours
          FROM ticket_change     
               LEFT JOIN ( SELECT ticket, time, author, CASE WHEN newvalue = '' OR newvalue IS NULL THEN 0
                           ELSE CAST( newvalue AS DECIMAL ) END as hours, schema
                             FROM ticket_change as guts 
                            WHERE field='totalhours'  ) 
                  AS existing  ON existing.ticket = ticket_change.ticket and existing.time=ticket_change.time
                        AND ticket_change.author = existing.author
                        --AND ticket_change.schema = existing.schema
         WHERE ticket_change.field='hours'
) tbl 
WHERE (existingtotalhours IS NULL or ABS(newvalue - existingtotalhours) > .001 ) 
ORDER BY time desc;

[Russ Tyndall]

Here is the query (from the plugin guts) to reinsert the total hours rows so you can just do that from psql.

INSERT INTO ticket_change (ticket, author, time, field, oldvalue, newvalue)
       SELECT ticket, author, time, 'totalhours',  
               (SELECT SUM( CASE WHEN newvalue = '' OR newvalue IS NULL THEN 0
                           ELSE CAST( newvalue AS DECIMAL ) END ) as total
               FROM ticket_change as guts 
               WHERE guts.ticket = ticket_change.ticket AND guts.field='hours'
                 AND guts.time < ticket_change.time
              ) as oldvalue, 
              (SELECT SUM( CASE WHEN newvalue = '' OR newvalue IS NULL THEN 0
                           ELSE CAST( newvalue AS DECIMAL ) END ) as total
               FROM ticket_change as guts 
               WHERE guts.ticket = ticket_change.ticket AND guts.field='hours'
                 AND guts.time <= ticket_change.time
              ) as newvalue
          FROM ticket_change
         WHERE field='hours'
           AND NOT EXISTS( SELECT ticket
                             FROM ticket_change as guts 
                            WHERE guts.ticket=ticket_change.ticket
                              AND guts.author=ticket_change.author
                              AND guts.time=ticket_change.time
                              AND field='totalhours')

[anonymous]

Back in action from a short vacation. I deleted all the totalhours and added some time, now everything is fine. Apart from that one occurrence it didn't happen anywhere else, so it might have been something I or my users did wrong.

Good work, let's hope that nothing else comes up. :)

[Phillip Leder <phillip.leder@…>]

Now if only I knew why my user wasn't saved, even though the session key didn't change... just wanted to clarify that it was me with the reply, even though it should be clear.

[Russ Tyndall]

Whelp, lets hope it doesnt recur