Time Tracking: "Logged" shows wrong value

Tobias Pohlmann September 28, 2017

After importing a batch of worklogs via the Rest-API the time tracking is not working properly.

I imported 66 worklogs via the REST-API which sum up to a total of 12h 15m but the time tracking only shows 55m of logged time. All worklogs are displayed correctly with starting time, duration and comment.

I could reproduce this error but with different values of "logged time". It seems that Jira is not able to fully handle the requests at some point. There is no error returned by the API.

 

Is there a way to rebuild the logged-time from the worklogs - ideally only for the single issue?

 

Cheers

Tobi

2 answers

0 votes
Andy Heinzer
Atlassian Team
Atlassian Team members are employees working across the company in a wide variety of roles.
October 6, 2017

Hi Tobias,
Thanks for providing all that information.  I was able to recreate this when I followed your steps.  I did end up having to tweak that .js script to get the line breaks to read different entries, but when I did this I was able to import all 66 worklog entries in one go.

But the worklog table is being updated correctly, that table does contain the correct entries as far as I can see.   However in the Time Tracking: Logged time, this field is not directly pulling its value from the sum of the values in the worklog table.  I could see why you might think it was doing that since these values are expected to line up.

But instead Jira is storing the Logged time value in the table name of 'jiraissue', specifically in the column called 'timespent'.

The problem here is that your script is adding these worklog entries so fast that Jira is clearly not prepared to handle the rapid calculations required to keep this value accurate.   I was able to turn on SQL logging in Jira and the recreate this import to my issue with the key "SCRUM-4".   

2017-10-06 10:37:24,177 http-nio-8750-exec-79 admin 637x540x6 12nrun9 /rest/api/2/issue/SCRUM-4/worklog 1ms "UPDATE public.jiraissue SET pkey='null', UPDATED='2017-10-06 10:37:24.174', TIMEESTIMATE='0', TIMESPENT='420' WHERE ID='10003'"
2017-10-06 10:37:24,178 http-nio-8750-exec-133 admin 637x579x45 jd33s8 /rest/api/2/issue/SCRUM-4/worklog 1ms "SELECT pkey, issuenum, PROJECT, REPORTER, ASSIGNEE, CREATOR, issuetype, SUMMARY, DESCRIPTION, ENVIRONMENT, PRIORITY, RESOLUTION, issuestatus, CREATED, UPDATED, DUEDATE, RESOLUTIONDATE, VOTES, WATCHES, TIMEORIGINALESTIMATE, TIMEESTIMATE, TIMESPENT, WORKFLOW_ID, SECURITY, FIXFOR, COMPONENT FROM public.jiraissue WHERE ID='10003'"
2017-10-06 10:37:24,178 http-nio-8750-exec-99 admin 637x545x11 1aef5my /rest/api/2/issue/SCRUM-4/worklog 5ms "SELECT ID, pkey, issuenum, PROJECT, REPORTER, ASSIGNEE, CREATOR, issuetype, SUMMARY, DESCRIPTION, ENVIRONMENT, PRIORITY, RESOLUTION, issuestatus, CREATED, UPDATED, DUEDATE, RESOLUTIONDATE, VOTES, WATCHES, TIMEORIGINALESTIMATE, TIMEESTIMATE, TIMESPENT, WORKFLOW_ID, SECURITY, FIXFOR, COMPONENT FROM public.jiraissue WHERE issuenum='4' AND PROJECT='10000'"
2017-10-06 10:37:24,178 http-nio-8750-exec-133 admin 637x579x45 jd33s8 /rest/api/2/issue/SCRUM-4/worklog 0ms "UPDATE public.jiraissue SET pkey='null', UPDATED='2017-10-06 10:37:24.176', TIMEESTIMATE='0', TIMESPENT='60' WHERE ID='10003'"


You can see from the first line to the last line, there are two update SQL statements being made to the same table for the same issue.  These two updates are happening 1/1000 of a second apart.   The first sets the value to 420 seconds (7 minutes), but then the next update changes that value down to 60 seconds (1 minute).   I think what is happening here is that both additions query the database at the same time to find the current timespent value. At the time they do this the value is 0.  So then both try to update the table with their value being added to the value they found, without any knowledge that there are 66 updates all trying to happen as fast as possible.

I did find that I could update that table to have a corrected value if I ran an update statement such as

update jiraissue set timespent = (select sum(wl.timeworked) from worklog wl where wl.issueid=10003) where id=10003;


Granted I was using postgres to test this out, so I'm not certain the SQL syntax will still be valid in Mysql, but this was able to update the timespent value to match the values in the worklog table.


It's not clear to me yet though it this is a bug in Jira, you could certainly make a good argument that this is a bug.  However I am wondering if perhaps this was designed in this way for a specific reason that eludes me.   If you like, I can certainly create a new bug in regards to this problem.  I might do so anyways just to better document this problem.  I was surprised I could not find much in the way of support cases or documented bugs of this nature.

I hope this helps.
Andy


Shane Lawrence October 12, 2017

I can confirm the above solution worked for me as well. I added a throttle to my batch import script, and the slower queries (2 per sec in my case) resulted in a correct total Logged amount.

Andy Heinzer
Atlassian Team
Atlassian Team members are employees working across the company in a wide variety of roles.
October 12, 2017

Hey @Shane Lawrencethanks for sharing.   I tried to get some kind of delay when I was playing with this in node.js, but I could never really get that work-around going.  Would you mind sharing the syntax of your throttle here?   I just thought it might help others that come across this problem.

Tobias Pohlmann October 13, 2017

The general "problem" - which isn't really a problem - is that node.js is async by design. Which in this case means, that it fires all requests in a seperate thread which results in many parallel requests. One solution came to my mind which requires some work on Jira: One could synchronize the process that updates the issue table. In Java this could be achieved easily.

0 votes
Andy Heinzer
Atlassian Team
Atlassian Team members are employees working across the company in a wide variety of roles.
September 29, 2017

Are all of these worklogs entries for a single issue in Jira?   Or are these worklogs tracking time spent on multiple issues?

If I understand your concerns here, the entries exist now in Jira, but it is not clear to me where this data is not displaying as expected.  Is this on the issue details page?  Or some other report on time tracking?

If there were recent changes made to the way the system is configured to track time, then it might be necessary to reindex Jira.  However the process of importing worklogs via the REST API is not something that would require a manual reindex of Jira.

Perhaps if we can grab a few screenshots of the problem you are seeing here, as well as the steps taken to reproduce this we can better understand what might be happening here.

Tobias Pohlmann October 5, 2017

Thanks for the reply! I'll try to answer your questions and hope that it helps to understand and reproduce the problem.

 

  1. All worklogs are for one single issue in Jira (default issue, no subissue, etc.)
  2. The worklogs exist in Jira for this issue and are listed correctly in the detail view under "worklog"
  3. The time tracking of the issue in issue detail view is not correct
  4. No changes were made to the system except for adding a new user and configuring a webhook which has nothing to do with time tracking but only with the issue status

 

I used a small NodeJS script to add the worklogs via the REST-API (code: https://pastebin.com/cny4fXpz). The data is read from a csv-file (sample data: https://pastebin.com/2AP4B8t0).

To reproduce the error I repeated the whole process again and took a screenshot: 2017-10-05 10_18_12-.png

 

Obviously the time displayed in time tracking is wrong. To confirm this I selected the data directly from the MySQL database:

2017-10-05 10_25_13-MySQL Workbench.png2017-10-05 10_26_47-MySQL Workbench.png

 

I hope this helps to understand and reproduce the problem.

Tobias

Suggest an answer

Log in or Sign up to answer