1923870 - Perma taskcluster/test/test_generate_params.py::test_generate_graphs[mc-onpush] TEST-UNEXPECTED-FAIL | ValueError: time data '2024-10-11T09:41:48.305+00:00Z' does not match format '%Y-%m-%dT%H:%M:%S.%fZ

Status: RESOLVED FIXED

(Firefox Build System :: Task Configuration, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=477629781&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/AFZyWQmCQ3GRYUrhicEeiQ/runs/0/artifacts/public/logs/live_backing.log

---

 taskcluster/test/test_generate_params.py::test_generate_graphs[mb-onpush] PASSED
[task 2024-10-10T10:00:00.545Z] taskcluster/test/test_generate_params.py::test_generate_graphs[mc-onpush] TEST-UNEXPECTED-FAIL
[task 2024-10-10T10:00:00.545Z] taskcluster/test/test_generate_params.py::test_generate_graphs[mb-promote-firefox] PASSED
<...>
taskcluster/test/test_generate_params.py::test_generate_graphs[me-promote-firefox] PASSED
[task 2024-10-10T10:00:00.547Z] 
[task 2024-10-10T10:00:00.547Z] =================================== FAILURES ===================================
[task 2024-10-10T10:00:00.547Z] _______________________ test_generate_graphs[mc-onpush] ________________________
[task 2024-10-10T10:00:00.547Z] taskcluster/test/test_generate_params.py:55: in test_generate_graphs
[task 2024-10-10T10:00:00.547Z]     pytest.fail("An exception was raised during graph generation!")
[task 2024-10-10T10:00:00.547Z] E   Failed: An exception was raised during graph generation!
[task 2024-10-10T10:00:00.547Z] ----------------------------- Captured stdout call -----------------------------
[task 2024-10-10T10:00:00.547Z] concurrent.futures.process._RemoteTraceback:
[task 2024-10-10T10:00:00.547Z] """
[task 2024-10-10T10:00:00.547Z] Traceback (most recent call last):
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/fetches/python/lib/python3.8/concurrent/futures/process.py", line 239, in _process_worker
[task 2024-10-10T10:00:00.547Z]     r = call_item.fn(*call_item.args, **call_item.kwargs)
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/main.py", line 150, in format_taskgraph
[task 2024-10-10T10:00:00.547Z]     tg = getattr(tgg, options["graph_attr"])
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/generator.py", line 220, in morphed_task_graph
[task 2024-10-10T10:00:00.547Z]     return self._run_until("morphed_task_graph")
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/generator.py", line 430, in _run_until
[task 2024-10-10T10:00:00.547Z]     k, v = next(self._run)  # type: ignore
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/generator.py", line 404, in _run
[task 2024-10-10T10:00:00.547Z]     optimized_task_graph, label_to_taskid = optimize_task_graph(
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/optimize/base.py", line 71, in optimize_task_graph
[task 2024-10-10T10:00:00.547Z]     removed_tasks = remove_tasks(
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/optimize/base.py", line 242, in remove_tasks
[task 2024-10-10T10:00:00.547Z]     if opt.should_remove_task(task, params, arg):
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/optimize/base.py", line 519, in should_remove_task
[task 2024-10-10T10:00:00.547Z]     return self.reduce(results)
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/optimize/base.py", line 560, in reduce
[task 2024-10-10T10:00:00.547Z]     for rv in results:
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/optimize/base.py", line 515, in _generate_results
[task 2024-10-10T10:00:00.547Z]     yield getattr(sub, fname)(*passthru, arg)
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/taskcluster/gecko_taskgraph/optimize/strategies.py", line 129, in should_remove_task
[task 2024-10-10T10:00:00.547Z]     self.index_search.should_replace_task(task, params, deadline, [index])
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/checkouts/gecko/third_party/python/taskcluster_taskgraph/taskgraph/optimize/strategies.py", line 59, in should_replace_task
[task 2024-10-10T10:00:00.547Z]     ) < datetime.strptime(deadline, self.fmt):
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/fetches/python/lib/python3.8/_strptime.py", line 568, in _strptime_datetime
[task 2024-10-10T10:00:00.547Z]     tt, fraction, gmtoff_fraction = _strptime(data_string, format)
[task 2024-10-10T10:00:00.547Z]   File "/builds/worker/fetches/python/lib/python3.8/_strptime.py", line 349, in _strptime
[task 2024-10-10T10:00:00.547Z]     raise ValueError("time data %r does not match format %r" %
[task 2024-10-10T10:00:00.547Z] ValueError: time data '2024-10-11T09:41:48.305+00:00Z' does not match format '%Y-%m-%dT%H:%M:%S.%fZ'
[task 2024-10-10T10:00:00.547Z] """
[task 2024-10-10T10:00:00.547Z] 
[task 2024-10-10T10:00:00.547Z] The above exception was the direct cause of the following exception:
[task 2024-10-10T10:00:00.547Z] 
[task 2024-10-10T10:00:00.547Z] ValueError: time data '2024-10-11T09:41:48.305+00:00Z' does not match format '%Y-%m-%dT%H:%M:%S.%fZ'
[task 2024-10-10T10:00:00.547Z] 
[task 2024-10-10T10:00:00.547Z] 
[task 2024-10-10T10:00:00.547Z] 
[task 2024-10-10T10:00:00.547Z] ================== 1 failed, 33 passed in 1895.38s (0:31:35) ===================
[task 2024-10-10T10:00:00.547Z] 
[task 2024-10-10T10:00:00.547Z] 
[task 2024-10-10T10:00:00.547Z] Tests Completed: 100%|██████████| 6/6 [31:36<00:00, 316.03s/Test]Return code from mach python-test: 1
[task 2024-10-10T10:00:00.574Z] 
[taskcluster 2024-10-10 10:00:01.351Z] === Task Finished ===
[taskcluster 2024-10-10 10:00:01.351Z] Unsuccessful task run with exit code: 1 completed in 1941.384 seconds

Comment 1

[Sandor Molnar[:smolnar]]

@Julien, could you look at this py perma failure?
it is failing where it was green before.

Comment 2

[Julien Cristau [:jcristau]]

Bug 1919287 added a new optimization strategy that does:

        now = datetime.datetime.now(datetime.timezone.utc)
        deadline = resolve_timestamps(now, task.task["deadline"])

That looks like 2024-10-11T14:20:12.824+00:00Z, and the +00:00 doesn't match the format string in should_remove_task's call to strptime.

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1919287

Comment 4

[Julien Cristau [:jcristau]]

Fixed by backout
https://hg.mozilla.org/mozilla-central/rev/3176f083b259

Comment 5

[Intermittent Failures Robot]

6 failures in 4679 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• autoland: 5

Platform and build breakdown:

• linux1804-64: 6
  • opt: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1923870&startday=2024-10-07&endday=2024-10-13&tree=all