1598561 - [mozlog] AssertionError: assert not self._closed at File "/usr/lib64/python2.7/multiprocessing/queues.py", line 100, in put

Status: RESOLVED FIXED

(Testing :: web-platform-tests, defect, P2)

Description

[Simon Giesecke [:sg] [he/him]]

When running MOZ_ACCELERATED=1 MOZ_WEBRENDER=1 ./mach test wpt --headless testing/web-platform/tests/IndexedDB/key_valid.html, I get the following error output just before the "Overall Summary":

 2:24.87 INFO STDERR: Traceback (most recent call last):
 2:24.87 INFO STDERR:   File "/usr/lib64/python2.7/logging/__init__.py", line 889, in emit
 2:24.87 INFO STDERR:     stream.write(fs % msg)
 2:24.87 INFO STDERR:   File "/home/simon/work/mozilla-unified/testing/mozbase/mozlog/mozlog/capture.py", line 52, in write
 2:24.87 INFO STDERR:     self.queue.put(data)
 2:24.87 INFO STDERR:   File "/usr/lib64/python2.7/multiprocessing/queues.py", line 100, in put
 2:24.87 INFO STDERR:     assert not self._closed
 2:24.87 INFO STDERR: AssertionError
 2:24.87 INFO STDERR: Logged from file font.py, line 49
 2:24.87 INFO STDERR: Traceback (most recent call last):
 2:24.87 INFO STDERR:   File "/usr/lib64/python2.7/logging/__init__.py", line 889, in emit
 2:24.87 INFO STDERR:     stream.write(fs % msg)
 2:24.87 INFO STDERR:   File "/home/simon/work/mozilla-unified/testing/mozbase/mozlog/mozlog/capture.py", line 52, in write
 2:24.87 INFO STDERR:     self.queue.put(data)
 2:24.87 INFO STDERR:   File "/usr/lib64/python2.7/multiprocessing/queues.py", line 100, in put
 2:24.87 INFO STDERR:     assert not self._closed
 2:24.87 INFO STDERR: AssertionError
 2:24.87 INFO STDERR: Logged from file font.py, line 49
 2:24.87 INFO STDERR: Traceback (most recent call last):
 2:24.87 INFO STDERR:   File "/usr/lib64/python2.7/logging/__init__.py", line 889, in emit
 2:24.87 INFO STDERR:     stream.write(fs % msg)
 2:24.87 INFO STDERR:   File "/home/simon/work/mozilla-unified/testing/mozbase/mozlog/mozlog/capture.py", line 52, in write
 2:24.87 INFO STDERR:     self.queue.put(data)
 2:24.87 INFO STDERR:   File "/usr/lib64/python2.7/multiprocessing/queues.py", line 100, in put
 2:24.87 INFO STDERR:     assert not self._closed
 2:24.87 INFO STDERR: AssertionError
 2:24.87 INFO STDERR: Logged from file font.py, line 49
 2:24.87 INFO STDERR: Traceback (most recent call last):
 2:24.87 INFO STDERR:   File "/usr/lib64/python2.7/logging/__init__.py", line 889, in emit
 2:24.87 INFO STDERR:     stream.write(fs % msg)
 2:24.87 INFO STDERR:   File "/home/simon/work/mozilla-unified/testing/mozbase/mozlog/mozlog/capture.py", line 52, in write
 2:24.87 INFO STDERR:     self.queue.put(data)
 2:24.87 INFO STDERR:   File "/usr/lib64/python2.7/multiprocessing/queues.py", line 100, in put
 2:24.87 INFO STDERR:     assert not self._closed
 2:24.87 INFO STDERR: AssertionError
 2:24.87 INFO STDERR: Logged from file font.py, line 49
 2:24.87 INFO STDERR: INFO:root:Removed font: Ahem.ttf
 2:24.87 INFO STDERR: INFO:root:Removed font: Ahem.ttf

Comment 1

[Geoff Brown [:gbrown]]

I'm not sure, but I suspect the issue is not that mozlog asserts, but that the caller is logging after

Comment 2

[Geoff Brown [:gbrown]]

(Oops.)

I'm not sure, but I suspect the issue is not that mozlog asserts, but that the caller is logging after the log is closed.

"Logged from file font.py, line 49" looks like:

https://searchfox.org/mozilla-central/rev/3483fb259b4edbe4594cfcc3911db97d5441b67d/testing/web-platform/tests/tools/wptrunner/wptrunner/font.py

Comment 3

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

The priority flag is not set for this bug.
:jgraham, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 4

[James Graham [:jgraham]]

Attachment: Bug 1598561 - Use mozlog logger in FontInstaller,

This is the right thing to do, and prevents a race where we try to log
after the stdout capture queue is closed

Comment 5

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

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:jgraham, could you have a look please?
For more information, please visit auto_nag documentation.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2a0e33dbb9c8
Use mozlog logger in FontInstaller, r=maja_zf

Comment 7

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/20997 for changes under testing/web-platform/tests

Comment 8

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Can't merge web-platform-tests PR due to failing upstream checks:
Github PR https://github.com/web-platform-tests/wpt/pull/20997
* Community-TC (pull_request) (https://community-tc.services.mozilla.com/tasks/groups/C1dM3c_iTBS2Bv_aegz2MA)

Comment 9

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream web-platform-tests status checks passed, PR will merge once commit reaches central.

Comment 10

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/2a0e33dbb9c8

Comment 11

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream PR merged by moz-wptsync-bot

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9a781a026409
[wpt PR 20997] - [Gecko Bug 1598561] Use mozlog logger in FontInstaller, a=testonly

Comment 13

[Dorel Luca [:dluca]]

https://hg.mozilla.org/mozilla-central/rev/9a781a026409