1416977 - ValueError: I/O operation on closed file during mozlog.structuredlog on Windows

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Mike Hommey [:glandium] (high latency)]

STR:
- Open Treeherder on e.g. mozilla-central
- Select a green windows build
- Select "failure classification"
- See the 7 "ValueError: I/O operation on closed file" items with links into the build log.

Expected result:
- "No error lines reported"

While it's not really a problem on green jobs, it becomes one when the jobs are red because of a make check error, because you now have those 7 errors along with your own, and you first have to figure out that those 7 errors have nothing to do with your changes, and have been there for a while, even on green runs.

Comment 1

[Henrik Skupin (:whimboo) [⌚️UTC+2]]

Whichever test job I select I always see `No error lines reported`. Can you please point out a specific job which shows this problem?

Comment 2

[Mike Hommey [:glandium] (high latency)]

(In reply to Henrik Skupin (:whimboo) from comment #1)
> Whichever test job I select I always see `No error lines reported`. Can you
> please point out a specific job which shows this problem?

Choose a *build* job, not a test job. Those tests are running during make check during the build.

Comment 3

[Henrik Skupin (:whimboo) [⌚️UTC+2]]

I see. So here a query for autoland:

https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=build%20windows&bugfiler&filter-resultStatus=success&filter-resultStatus=runnable

https://treeherder.mozilla.org/logviewer.html#?job_id=144872600&repo=autoland&lineNumber=39115

08:30:46     INFO - mozlog.structuredlog: Failure calling log handler:
08:30:46     INFO - Traceback (most recent call last):
08:30:46     INFO -   File "z:\build\build\src\testing\mozbase\mozlog\mozlog\structuredlog.py", line 237, in _handle_log
08:30:46     INFO -     handler(data)
08:30:46     INFO -   File "z:\build\build\src\testing\mozbase\mozlog\mozlog\handlers\base.py", line 101, in __call__
08:30:46     INFO -     self.stream.write(formatted.encode("utf-8", "replace"))
08:30:46     INFO - ValueError: I/O operation on closed file

Comment 4

[Mike Hommey [:glandium] (high latency)]

Please fix this, because it makes other errors misattributed to bug 1420472.

Comment 5

[Geoff Brown [:gbrown]]

I debugged this a little and determined that the ValueError is thrown by the handler created by test_utf8str_write.

Comment 6

[Geoff Brown [:gbrown]]

Attachment: remove handler before its file is closed

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0117ae8d6d0bbc2a7709d12fadc66c3102a35449

Comment 7

[Andrew Halberstadt [:ahal]]

Comment on attachment 8939094 [details] [diff] [review]
remove handler before its file is closed

Review of attachment 8939094 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for debugging this Geoff!

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/311f264cc818
Ensure handler removed before file closed in test_structured.py; r=ahal

Comment 9

[Andrei Ciure[:andrei_ciure]]

https://hg.mozilla.org/mozilla-central/rev/311f264cc818