1755879 - Permanent Linux debug py3(ref) KeyError: 'message' failure message for successful py3(ref) tasks - DO NOT USE FOR CLASSIFICATION

Status: NEW

(Testing :: Reftest, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=367168005&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/OPlEVvXZSQy7CfAdJi0c6g/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/OPlEVvXZSQy7CfAdJi0c6g/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

There 4 such failure messages, Treeherder only highlights the first one because the messages are identic. This is a regression from bug 1753555.

[task 2022-02-09T01:44:19.117Z]  1:53.46 =============================== warnings summary ===============================
[task 2022-02-09T01:44:19.117Z]  1:53.46 layout/tools/reftest/selftest/test_reftest_manifest_parser.py::test_parse_test_types
[task 2022-02-09T01:44:19.118Z]  1:53.46   /builds/worker/fetches/tests/bin/fix_stacks.py:20: DeprecationWarning: invalid escape sequence \d
[task 2022-02-09T01:44:19.118Z]  1:53.46     line_re = re.compile("#\d+: .+\[.+ \+0x[0-9A-Fa-f]+\]")
[task 2022-02-09T01:44:19.118Z]  1:53.46 
[task 2022-02-09T01:44:19.118Z]  1:53.46 -- Docs: https://docs.pytest.org/en/latest/warnings.html
[task 2022-02-09T01:44:19.118Z]  1:53.46 ==================== 3 passed, 1 warnings in 90.21 seconds =====================
[task 2022-02-09T01:44:19.118Z]  1:53.46 
[task 2022-02-09T01:46:38.740Z] 
[task 2022-02-09T01:46:38.740Z] mozlog.structuredlog: Failure calling log handler:
[task 2022-02-09T01:46:38.740Z] Traceback (most recent call last):
[task 2022-02-09T01:46:38.740Z]   File "/builds/worker/checkouts/gecko/testing/mozbase/mozlog/mozlog/structuredlog.py", line 294, in _handle_log
[task 2022-02-09T01:46:38.740Z]     handler(data)
[task 2022-02-09T01:46:38.740Z]   File "/builds/worker/checkouts/gecko/testing/mozbase/mozlog/mozlog/handlers/base.py", line 73, in __call__
[task 2022-02-09T01:46:38.740Z]     formatted = self.formatter(data)
[task 2022-02-09T01:46:38.741Z]   File "/builds/worker/checkouts/gecko/testing/mozbase/mozlog/mozlog/handlers/base.py", line 41, in __call__
[task 2022-02-09T01:46:38.741Z]     return self.inner(item)
[task 2022-02-09T01:46:38.741Z]   File "/builds/worker/fetches/tests/reftest/output.py", line 28, in __call__
[task 2022-02-09T01:46:38.741Z]     return "%s\n" % data["message"]
[task 2022-02-09T01:46:38.741Z] KeyError: 'message'

Comment 1

[Alex Hochheiden [:ahochheiden] [he/him]]

Couldn't reproduce on my local Windows machine, working on getting the docker image now to troubleshoot it.

Comment 2

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

Seems to only affect Linux debug, not opt or asan.

Comment 3

[Alex Hochheiden [:ahochheiden] [he/him]]

Sorry for the delay. I initially investigated it, but couldn't determine how my change could have caused the error so I put it on the back burner for a bit. I dug into it some more now, and ran a try with central and another with my changes removed.

Central: https://treeherder.mozilla.org/jobs?revision=60446529ee420678db58bcdbf2562e2a66cf9430&repo=try&selectedTaskRun=KuRYkAQKRoSZPVFMv9cmWQ.0
Log: https://firefoxci.taskcluster-artifacts.net/KuRYkAQKRoSZPVFMv9cmWQ/0/public/logs/live_backing.log
My changes Removed: https://treeherder.mozilla.org/jobs?repo=try&revision=7992d0fb1453c6451d711656e75791dd99713783&selectedTaskRun=JFdNH9G7RM-n1i0GXiZyAg.0
Log: https://firefoxci.taskcluster-artifacts.net/JFdNH9G7RM-n1i0GXiZyAg/0/public/logs/live_backing.log

I see the same error on both try runs, so unless I made a mistake in my test here, I think it wasn't my change that caused the regression. Unfortunately, I wasn't able to determine what change(s) did. The issue is that a formatter is being called and we're trying to access a message field that isn't provided in the map, so we always crash.

I could disable the test, but I'm not sure if that's the right way forward.

Comment 4

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

The failure got logged before but with the timestamp as part of the logged message which prevented Treeherder from identifying the failure (does subprocess not inherit settings)? The backout on Try didn't let the failure message disappear from Treeherder because bug 1754775 turned off the double logging of the timestamp in general.

The mozleak logging is missing the message attribute.