A lot of updates on every pull from azure devops

[wimpunk]

Hi,

I'm running the develop version of bugwarrior and I pull from Azure DevOps. On every pull, there a lot of updates, although there aren't that much updates on the repository. As far as I see, it's mostly about timestamps getting updated while there is no update needed. These a few lines of a latest run:

May 22 19:51:53 euler bugwarrior[577083]: INFO:bugwarrior.db:Updating task f7b0ea3c-5265-476d-9436-f5d159e8dc8b, [ADO-2278] Zeus: update documentation; entry: datetime.datetime(2024, 5, 17, 8, 18, 29, tzinfo=tzutc()) -> datetime.datetime(2024, 5, 17, 8, 18, 29, 90000, tzinfo=tzutc())
May 22 19:51:53 euler bugwarrior[577083]: INFO:bugwarrior.db:Updating task dcd310bd-1bca-4c54-a57a-82cefa29afbb, [ADO-2279] Zeus: setup backup; entry: datetime.datetime(2024, 5, 17, 8, 19, 37, tzinfo=tzutc()) -> datetime.datetime(2024, 5, 17, 8, 19, 37, 877000, tzinfo=tzutc())
May 22 19:51:53 euler bugwarrior[577083]: INFO:bugwarrior.db:Updating task 43ad00fd-784b-43cf-a56f-f860eada7720, [ADO-2280] Amun: extend diskspace; entry: datetime.datetime(2024, 5, 17, 8, 19, 46, tzinfo=tzutc()) -> datetime.datetime(2024, 5, 17, 8, 19, 46, 740000, tzinfo=tzutc())
May 22 19:51:53 euler bugwarrior[577083]: INFO:bugwarrior.db:Updating task 7360a361-c2f9-4ac0-90f2-4b852069fb42, [ADO-2283] Horus: DSM update; entry: datetime.datetime(2024, 5, 21, 7, 30, 2, tzinfo=tzutc()) -> datetime.datetime(2024, 5, 21, 7, 30, 2, 170000, tzinfo=tzutc())
May 22 19:51:54 euler bugwarrior[577083]: INFO:bugwarrior.db:Updating task b901a9c0-59f3-4e7c-a8c7-274cdf1fcbdf, [ADO-2284] Horus: cache review; entry: datetime.datetime(2024, 5, 21, 7, 30, 36, tzinfo=tzutc()) -> datetime.datetime(2024, 5, 21, 7, 30, 36, 450000, tzinfo=tzutc())

It looks like it tries to add microseconds to the time stamp but those are ignored by taskwarrior. Or at least that's how I interpret the output.

[wimpunk]

I think it's not the timestamp which creates an update but changes like this:

May 28 12:18:38 euler bugwarrior[1728783]: INFO:bugwarrior.db:Updating task f34fafe9-27dc-41b4-88f0-375d7cda1cbb, [ADO-2277] Zeus: setup monitoring; status: 'completed' -> 'pending'; end: datetime.datetime(2024, 5, 28, 9, 18, 8, tzinfo=tzutc()) -> datetime.datetime(2024, 5, 21, 14, 2, 16, 403000, tzinfo=tzutc()); entry: datetime.datetime(2024, 5, 17, 8, 17, 23, tzinfo=tzutc()) -> datetime.datetime(2024, 5, 17, 8, 17, 23, 740000, tzinfo=tzutc())

The task is changed from completed to pending, but that wasn't done by taskwarrior. Inspecting the task by running task f34fafe9-27dc-41b4-88f0-375d7cda1cbb shows a lot of changes. This is the last part:

2024-05-28 08:15:44 End deleted.
                    Status changed from 'completed' to 'pending'.
2024-05-28 08:15:44 End set to '2024-05-28 08:15:44'.                                                                
                    Status changed from 'pending' to 'completed'.                                                    
2024-05-28 11:18:08 End deleted.
                    Status changed from 'completed' to 'pending'.
2024-05-28 11:18:08 End set to '2024-05-28 11:18:08'.                                                                
                    Status changed from 'pending' to 'completed'.                                                    
2024-05-28 12:18:38 End deleted.
                    Status changed from 'completed' to 'pending'.
2024-05-28 12:18:38 End set to '2024-05-28 12:18:38'.                                                                
                    Status changed from 'pending' to 'completed'.                                                    

The user story is closed on devops but the parent is still active.

[ryneeverett]

Could you share a little about your configuration? Are you using a custom query?

The way bugwarrior is supposed to work is:

• If the given issue is not returned, bugwarrior closes it's task.
• If a closed issue is returned, bugwarrior re-opens it's task.

So if bugwarrior were working properly, that would indicate that azure devops is returning these issues sometimes and not other times. Another possibility that comes to mind is that bugwarrior isn't recognizing azure devops' failure mode and is thinking it succeeded when it really failed (e.g. rate ban) or only returned a subset of the requested issues.

[ryneeverett]

Here's a suspect:

bugwarrior/bugwarrior/services/azuredevops.py

Lines 77 to 88 in 71efc97

	def get_work_items_from_query(self, query):
	data = str({"query": query})
	resp = self.session.post(f"{self.base_url}/wiql", data=data, params=self.params)
	if resp.status_code == 401:
	log.critical("HTTP 401 - Error authenticating! Please check 'PAT' in the configuration")
	sys.exit(1)
	if resp.status_code == 400 and resp.json(
	)['typeKey'] == "WorkItemTrackingQueryResultSizeLimitExceededException":
	log.critical("Too many azure devops results in query, please "
	"narrow the search by updating the ado.wiql_filter")
	sys.exit(1)
	return [workitem['id'] for workitem in resp.json()["workItems"]]

So anything other than those precise error conditions will be interpreted as success.

It should probably be the other way around where anything other than 200 is interpreted as failure. (Or maybe anything >=400? There are probably best practices here.)

[wimpunk]

Hi,

Yes, I'm using a custom filter:

ado.wiql_filter = [System.AssignedTo] = @me and [System.TeamProject] = 'Dataflow'

So if I understand your response correctly, I should exclude the closed items in my query.

[ryneeverett]

I don't have a solution for you at this point but I think the most interesting avenue for you to explore is if the service is intermittently getting bad http responses.

So if I understand your response correctly, I should exclude the closed items in my query.

I believe the way most services work is that closed issues are excluded by default and I have no reason to think azure devops is otherwise. If azure devops did default to including closed issues, that wouldn't explain why the tasks are getting closed in the first place. Again, bugwarrior only closes tasks which are not returned by the service and in that case the closed issues should be returned by the service every time.

[wimpunk]

I now have excluded the closed items and there a much less updates. I think we can clause this one, although it would be nice if that info could be added to the documentation.

[ryneeverett]

Great! Could you share your updated ado.wiql_filter to exclude closed tasks?

I suspect we should add this to the default query rather than merely documenting it.

[brianebeling]

Hello,

I'm experiencing a similar problem, where I get a bunch of logs like this:
INFO:bugwarrior.db:Updating task f9cff0b2-85bd-453e-846d-f8e41b8efa53, (bw)#32496 - Coupon/ (...).. https://dev.azure.com/x/d3bdfc58-2ed1-4f15-b426-d92c858991fd/_workitems/edit/32496; entry: datetime.datetime(2024, 6, 3, 8, 38, 37, tzinfo=tzutc()) -> datetime.datetime(2024, 6, 3, 8, 38, 37, 527000, tzinfo=tzutc())

I'm using this wiql_filter: "[System.AssignedTo] = @Me AND [System.State] <> 'Completed' AND [System.State] <> 'Closed' AND [System.TeamProject] = 'x'"

which should exclude work items that are completed or closed. In case anyone is wondering, the "<>" denotes "Unequals" whereas the "=" is "Equals". And it does so splenfidly.

Unfortunately, I'm still receiving these updated tasks with a "new" datetime.

Any ideas?

I installed bugwarrior from source, because I had issues with the AUR release and Pydantic on Arch, but I don't think that should make any difference.