1727565 - Intermittent decision task ValueError: time data '2021-08-26T12:59:03Z' 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: 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'

Comment 1

[Intermittent Failures Robot]

1 failures in 2580 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• gecko-decision: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1727565&startday=2021-08-23&endday=2021-08-29&tree=all

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Attachment: Bug 1727565 - enforce microseconds value in timestamp even if value is 0 to match parser expectation in graph builder. r=pmoore

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.

Comment 3

[Intermittent Failures Robot]

1 failures in 3375 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• gecko-decision: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1727565&startday=2021-09-13&endday=2021-09-19&tree=all

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/804159afc4db
enforce microseconds value in timestamp even if value is 0 to match parser expectation in graph builder. r=pmoore

Comment 5

[Alexandru Michis [:malexandru]]

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.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a0112238afb4
enforce microseconds value in timestamp even if value is 0 to match parser expectation in graph builder. r=pmoore

Comment 7

[Natalia Csoregi [:nataliaCs]]

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

Comment 8

[Intermittent Failures Robot]

1 failures in 3376 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• gecko-decision: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1727565&startday=2021-09-27&endday=2021-10-03&tree=all

Comment 9

[Andra Esanu (needinfo me)]

(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:

Ratio	Test	Platform	Options	Absolute values (old vs new)
0.11%	installer size	osx-shippable	instrumented	113,591,102.67 -> 113,714,693.58

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

Comment 10

[Ryan VanderMeulen [:RyanVM]]

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

Comment 11

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

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).

Comment 12

[Andra Esanu (needinfo me)]

(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!