1828755 - [mozprocess] Process logging on Windows stops when the application gets restarted

Status: NEW

(Testing :: Mozbase, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1]]

While working on bug 1493796 I noticed that when Marionette restarts Firefox all the logging to the console via mozprocess suddenly stops. Here is an example:

https://treeherder.mozilla.org/logviewer?job_id=412834311&repo=mozilla-central&lineNumber=43692

[task 2023-04-18T11:34:36.111Z] 11:34:36     INFO -  DEBUG: Finished phase xpcom-will-shutdown
[task 2023-04-18T11:34:36.117Z] 11:34:36     INFO -  DEBUG: Starting phase web-workers-shutdown
[task 2023-04-18T11:34:36.118Z] 11:34:36     INFO -  DEBUG: Spinning the event loop
[task 2023-04-18T11:34:36.118Z] 11:34:36     INFO -  DEBUG: Finished phase web-workers-shutdown
[task 2023-04-18T11:34:38.534Z] 11:34:38     INFO -  TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation | took 2928ms
[task 2023-04-18T11:34:38.539Z] 11:34:38     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_get_current_url
[task 2023-04-18T11:34:38.906Z] 11:34:38     INFO -  TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_get_current_url | took 372ms

I'm not sure if the mozprocess output logging is bound to a specific profile and needs to be adjusted / restarted.

Andrew or Geoff, do you have an idea?

Comment 1

[Geoff Brown [:gbrown]]

You expect more output from the process after "Finished phase web-workers-shutdown" - is that the issue? But the process is ending, so there probably isn't much more output, right?

My first thought was that there might be a bug in the ProcessReader, but I don't see anything wrong: it seems to try to report any process output received, even after the process ends: https://searchfox.org/mozilla-central/rev/31f5847a4494b3646edabbdd7ea39cb88509afe2/testing/mozbase/mozprocess/mozprocess/processhandler.py#1166-1171.

I would have to also wonder, since Firefox is shutting down, are we sure that it actually output anything more?

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Note that in this case Firefox is actually restarted and a the new process is forked/spawned (not sure how it happens). So Marionette waits for it to appear, connects to it and continues with the test. But as it can be seen there is no more any output until a test actually quits Firefox and starts a complete new instance.

Comment 3

[Andrew Halberstadt [:ahal]]

Sorry, I don't have any ideas. It's been a long time since I've been involved with this code. I'm surprised it hasn't been noticed before though?

Comment 4

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

The severity field is not set for this bug.
:gbrown, could you have a look please?

For more information, please visit BugBot documentation.