Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=349527752&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/DO-qj86BTGanVqYxpXUrvg/runs/0/artifacts/public/logs/live_backing.log

[task 2021-08-25T12:59:03.040Z] https://firefox-ci-tc.services.mozilla.com:443 "GET /api/index/v1/task/gecko.cache.level-3.toolchains.v3.linux64-mingw32-nsis.hash.f0652c2855085997cef2b510353d5e8c44ab92b3027ef770f7238a798771e3ad HTTP/1.1" 200 251
[task 2021-08-25T12:59:03.064Z] https://firefox-ci-tc.services.mozilla.com:443 "GET /api/queue/v1/task/aYzanaTFT0am1H07cirCiQ/status HTTP/1.1" 200 836
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.391425774000254, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.3803252699999575, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.11637890400015749, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.09558467599981668, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.10131675899992842, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.0905416079999668, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.08589195500007918, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.0902007859999685, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.0875502899998537, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.09154635499999131, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "bugbug_push_schedules_time", "value": 0.09378672399998322, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}, {"name": "bugbug_push_schedules_retries", "value": 0, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[task 2021-08-25T12:59:03.067Z] Traceback (most recent call last):
[task 2021-08-25T12:59:03.067Z]   File "/builds/worker/checkouts/gecko/taskcluster/mach_commands.py", line 273, in taskgraph_decision
[task 2021-08-25T12:59:03.067Z]     ret = taskgraph_commands["decision"].func(options)
[task 2021-08-25T12:59:03.067Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/main.py", line 350, in decision
[task 2021-08-25T12:59:03.067Z]     taskgraph_decision(options)
[task 2021-08-25T12:59:03.067Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/decision.py", line 248, in taskgraph_decision
[task 2021-08-25T12:59:03.067Z]     write_artifact("task-graph.json", tgg.morphed_task_graph.to_json())
[task 2021-08-25T12:59:03.067Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/generator.py", line 221, in morphed_task_graph
[task 2021-08-25T12:59:03.067Z]     return self._run_until("morphed_task_graph")
[task 2021-08-25T12:59:03.067Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/generator.py", line 430, in _run_until
[task 2021-08-25T12:59:03.067Z]     k, v = next(self._run)
[task 2021-08-25T12:59:03.067Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/generator.py", line 407, in _run
[task 2021-08-25T12:59:03.067Z]     strategy_override=strategies,
[task 2021-08-25T12:59:03.067Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/optimize/__init__.py", line 81, in optimize_task_graph
[task 2021-08-25T12:59:03.067Z]     removed_tasks=removed_tasks,
[task 2021-08-25T12:59:03.067Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/optimize/__init__.py", line 306, in replace_tasks
[task 2021-08-25T12:59:03.067Z]     repl = opt.should_replace_task(task, params, deadline, arg)
[task 2021-08-25T12:59:03.067Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/optimize/strategies.py", line 46, in should_replace_task
[task 2021-08-25T12:59:03.067Z]     ) < datetime.strptime(deadline, self.fmt):
[task 2021-08-25T12:59:03.067Z]   File "/usr/lib/python3.6/_strptime.py", line 565, in _strptime_datetime
[task 2021-08-25T12:59:03.067Z]     tt, fraction = _strptime(data_string, format)
[task 2021-08-25T12:59:03.067Z]   File "/usr/lib/python3.6/_strptime.py", line 362, in _strptime
[task 2021-08-25T12:59:03.067Z]     (data_string, format))
[task 2021-08-25T12:59:03.067Z] ValueError: time data '2021-08-26T12:59:03Z' does not match format '%Y-%m-%dT%H:%M:%S.%fZ'

Bug 1690947 started to parse timestamp strings provided for task expiration and
deadline which lacked the milliseconds part if the microseconds including
milliseconds had a value of 0 (because Python's isoformat() method got used
without enforcing the precision).

This caused the graph builder in the Gecko decision task to fail.

Backed out changeset 804159afc4db (Bug 1727565) for causing python failures in test_util_parameterization.py & test_util_time.py
Backout link: https://hg.mozilla.org/integration/autoland/rev/2430f68352ef48dd38d2fc599020eae9171525e7
Push with failures, failure log.

https://hg.mozilla.org/mozilla-central/rev/a0112238afb4

(In reply to Alexandru Michis [:malexandru] from comment #5)

Backed out changeset 804159afc4db (Bug 1727565) for causing python failures in test_util_parameterization.py & test_util_time.py
Backout link: https://hg.mozilla.org/integration/autoland/rev/2430f68352ef48dd38d2fc599020eae9171525e7
Push with failures, failure log.

== Change summary for alert #31614 (as of Fri, 01 Oct 2021 21:48:48 GMT) ==

Regressions:

For up to date results, see: https://treeherder.mozilla.org/perfherder/alerts?id=31614

https://hg.mozilla.org/releases/mozilla-esr91/rev/0124fa25f70e

The performance alert is triggered for an earlier push (bug 1728853) which actually is the regressing change because it adds new images (and the previous push still has the smaller file size).

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #11)

The performance alert is triggered for an earlier push (bug 1728853) which actually is the regressing change because it adds new images (and the previous push still has the smaller file size).

Thank you for noticing!