Bug 1185446 - task start time and finish time are reported as the same
Summary: task start time and finish time are reported as the same
Alias: None
Product: Pulp
Classification: Retired
Component: async/tasks
Version: 2.6 Beta
Hardware: Unspecified
OS: Unspecified
Target Milestone: ---
: 2.6.0
Assignee: Dennis Kliban
QA Contact: Irina Gulina
Depends On:
TreeView+ depends on / blocked
Reported: 2015-01-23 18:31 UTC by Dennis Kliban
Modified: 2015-02-28 23:21 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Last Closed: 2015-02-28 23:21:08 UTC

Attachments (Terms of Use)

System ID Private Priority Status Summary Last Updated
Pulp Redmine 675 0 None None None Never

Description Dennis Kliban 2015-01-23 18:31:07 UTC
Description of problem:

Version-Release number of selected component (if applicable):

How reproducible:

Steps to Reproduce:
1. Create repo
2. Sync and publish repo
3. View task list

Actual results:

Each task has the same time listed for start and finish.

Expected results:

Start and finish time should be at least 1 second apart.  You can see this by looking at the out put in the logs.  

Additional info:

Comment 1 Dennis Kliban 2015-01-29 15:40:15 UTC
The title of the bug is misleading.  After some investigation I was able to determine that this occurs for tasks that inherit from pulp.server.async.tasks.Task and that call another Task synchronously.  Celery assigned the Task called synchronously the same id as the task that called it.  Because we use an upsert when creating a TaskStatus, the start time gets changed when the synchronous Task is run. 

To avoid this problem we should not have an Task call any other Task synchronously.  This will always create erroneous TaskStatus start times.  However, regular celery tasks can still be called synchronously.

The fix for this will be part of the fix for https://bugzilla.redhat.com/show_bug.cgi?id=1120671

Comment 2 Dennis Kliban 2015-02-06 21:10:51 UTC
This was fixed when another bug got fixed. Here is the PR that fixed both:


Comment 3 Chris Duryee 2015-02-10 22:33:00 UTC

Comment 4 Irina Gulina 2015-02-13 15:11:57 UTC
>> rpm -qa pulp-server

>> pulp-admin tasks list
Operations:  sync
Resources:   epel_6_1 (repository)
State:       Successful
Start Time:  2015-02-13T14:03:21Z
Finish Time: 2015-02-13T14:41:21Z
Task Id:     36d8e151-ae58-45ea-8bbc-3f19935ff4df

Operations:  delete
Resources:   epel_6_1 (repository)
State:       Successful
Start Time:  2015-02-13T14:53:43Z
Finish Time: 2015-02-13T14:53:46Z
Task Id:     4da8d6bf-4163-4241-b53b-1ade249f6e90

Operations:  publish
Resources:   epel_6_1 (repository)
State:       Successful
Start Time:  2015-02-13T14:41:21Z
Finish Time: 2015-02-13T14:42:40Z
Task Id:     605d3858-bb17-46b2-a49f-36dc5a5bd9a7

Operations:  publish
Resources:   epel_6_1 (repository)
State:       Successful
Start Time:  2015-02-13T14:50:42Z
Finish Time: 2015-02-13T14:51:30Z
Task Id:     5406d2da-fce3-4008-8e13-9b433bb649c8

celery.worker.job:INFO: Task pulp.server.managers.repo.sync.sync[36d8e151-ae58-45ea-8bbc-3f19935ff4df] succeeded in 2279.51823536s: <pulp.server.async.tasks.TaskResult object at 0x36bb290>

celery.worker.job:INFO: Task pulp.server.managers.repo.publish.publish[605d3858-bb17-46b2-a49f-36dc5a5bd9a7] succeeded in 78.835292676s: {'exception': None, 'repo_id': u'epel_6_1', 'traceback': None, 'started': '2015-02-13T14:41:21Z', '_ns':...

 celery.worker.job:INFO: Task pulp.server.managers.repo.publish.publish[5406d2da-fce3-4008-8e13-9b433bb649c8] succeeded in 48.202181368s: {'exception': None, 'repo_id': u'epel_6_1', 'traceback': None, 'started': '2015-02-13T14:50:42Z', '_ns':...

  celery.worker.job:INFO: Task pulp.server.tasks.repository.delete[4da8d6bf-4163-4241-b53b-1ade249f6e90] succeeded in 2.726432841s: <pulp.server.async.tasks.TaskResult object at 0x7f5424011910>

Comment 5 Brian Bouterse 2015-02-28 23:21:08 UTC
Moved to https://pulp.plan.io/issues/675

Note You need to log in before you can comment on or make changes to this bug.