1257155 - Output stdout to the console on Windows

Status: RESOLVED FIXED

(Firefox Build System :: Mach Core, enhancement)

Comment 1

[Paul Adenot (:padenot)]

Attachment: patch

This looks like the right thing to do, but does not work, maybe something else is needed ?

Comment 2

[(not currently active) Ted Mielczarek]

I don't know offhand, but this comment in AttachConsole is interesting:
https://dxr.mozilla.org/mozilla-central/rev/7773387a9a2f1fd10e4424ea923c6185063f620b/toolkit/xre/nsNativeAppSupportWin.cpp#348

Comment 3

[Ben Kelly [:bkelly, not reviewing]]

What is the problem here?  Is this the known issue about e10s sandboxing blocking the console output on child process?

Comment 4

[Paul Adenot (:padenot)]

Oh yes that might be it. That said, I mentioned on IRC, doing `| tee` after `./mach run` makes it work.

Comment 5

[(not currently active) Ted Mielczarek]

I assume that makes it work because the output is a pipe, not a console, then? bkelly: is there a bug filed on that issue?

Comment 6

[(not currently active) Ted Mielczarek]

Comment on attachment 8731270 [details] [diff] [review]
patch

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

Since this doesn't fix the issue right now it's clearly not worth landing. If we find a bug on the e10s console bit, we could make it block this. Alternately, we could change the invocation part to not pass `pass_thru=True` when we aren't trying to run under a debugger:
https://dxr.mozilla.org/mozilla-central/rev/494289c72ba3997183e7b5beaca3e0447ecaf96d/python/mozbuild/mozbuild/mach_commands.py#1243

Comment 7

[:Gijs (out for now; he/him)]

So this is officially Really Annoying, to the point that people file stack overflow issues ( http://stackoverflow.com/questions/36720019/printf-to-console-on-firefox-build/36766260 ) and bemusedly ask around on IRC. Pinging some engineering productivity folks - can we get someone to look at this and fix whatever is breaking it?

Comment 8

[Armen [:armenzg]]

I have waited to see someone would have some idea of what is going on. I can't tell from the bug what could be.
What are the steps to reproduce?
Would calling Firefox in a command line have the same problem as running it through mach run?

Comment 9

[Ben Kelly [:bkelly, not reviewing]]

Armen, this is a known issue with sandboxing on windows.  Please see bug 1189223 which I marked as a dependency above.

Comment 10

[Armen [:armenzg]]

Thanks Ben.

Gijs, can we remove the NIs?

Comment 11

[:Gijs (out for now; he/him)]

(In reply to Armen Zambrano [:armenzg] - Engineering productivity from comment #10)
> Thanks Ben.
> 
> Gijs, can we remove the NIs?

From what I saw last week I don't think Ben is correct. In particular, I think the behaviour with and without ./mach run is currently different. I'm mid-build; I'll update the bug with more details in the next 10 minutes.

Comment 12

[:Gijs (out for now; he/him)]

(In reply to :Gijs Kruitbosch from comment #11)
> (In reply to Armen Zambrano [:armenzg] - Engineering productivity from
> comment #10)
> > Thanks Ben.
> > 
> > Gijs, can we remove the NIs?
> 
> From what I saw last week I don't think Ben is correct. In particular, I
> think the behaviour with and without ./mach run is currently different. I'm
> mid-build; I'll update the bug with more details in the next 10 minutes.

So I was wrong - --console and -console don't work regardless. I presume that's the sandboxing issue in bug 1189223.

However, -attach-console works, but --attach-console doesn't, and as the patch on this bug suggests, it should really be the default for ./mach run, rather than something we have to pass just to get working logs.

Note that all this output shows up when running mochitests, but doesn't when running with ./mach run, which is confusing.

Comment 13

[Armen [:armenzg]]

Maybe it has to do if the Python logger is properly initialized at the right time.
I don't know if this is what is happening but it could be if running mochitest does it. However, I don't know why this would not be an issue for other platforms.

Where's the entry point for |./mach run|?

If we're calling run_process [1], then it would be a matter to know if mochitests also use that way of executing Firefox. 
Maybe mozprocess [2] is used instead.

This piece of code shows what happens if the Python logger is not set up the right time.

> import logging
> import sys
> 
> logger = logging.getLogger()
> logger.info("This won't print") # This won't fail
> 
> logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)
> 
> logger.info("This will print")

[1] https://dxr.mozilla.org/mozilla-central/source/python/mach/mach/mixin/process.py#43
[2] https://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozprocess

Comment 14

[(not currently active) Ted Mielczarek]

(In reply to :Gijs Kruitbosch from comment #12)
> However, -attach-console works, but --attach-console doesn't, and as the
> patch on this bug suggests, it should really be the default for ./mach run,
> rather than something we have to pass just to get working logs.

Does the patch on this bug work? If so, we should just land it. When it was written padenot said it did not fix the issue.

> Note that all this output shows up when running mochitests, but doesn't when
> running with ./mach run, which is confusing.

When running tests, we redirect the browser's output to a pipe so we can parse test status messages from stdout. Redirecting stdout fixes this issue because it's a pipe, not a console. You can test this locally by running `./mach run | tee`. `mach run` doesn't redirect output by default (but it could, if that would be the best fix for this issue).

Comment 15

[Gregory Szorc [:gps]]

What Ted said.

Comment 16

[:Gijs (out for now; he/him)]

(In reply to Ted Mielczarek [:ted.mielczarek] (Vacation May 5th-11th) from comment #14)
> > Note that all this output shows up when running mochitests, but doesn't when
> > running with ./mach run, which is confusing.
> 
> When running tests, we redirect the browser's output to a pipe so we can
> parse test status messages from stdout. Redirecting stdout fixes this issue
> because it's a pipe, not a console. You can test this locally by running
> `./mach run | tee`. `mach run` doesn't redirect output by default (but it
> could, if that would be the best fix for this issue).

I don't know if that's the "best fix" - I'm not a domain expert on pipes and what is "expected" stdout/stderr behaviour. It just strikes me as odd that things "just work" on Linux and OS X and don't on Windows. As far as I'm concerned, we should do whatever it takes to make things "Just Work" on Windows, too. From what you're saying mach run doesn't redirect output, so how come it "just works" on Linux/OSX, then? Am I just misunderstanding what that means?

(ni to :gps because ted's on vacation.)

Comment 17

[Gregory Szorc [:gps]]

`mach run` passes the original {stdin,stderr,stdout} file descriptors to firefox.exe. So firefox.exe is bound to a terminal/console and can do magic there. Other mach commands (like the ones that launch tests) typically start firefox via mozprocess, which uses pipes for the standard file descriptors (and probably doesn't provide a stdin).

There are various reasons `mach run` doesn't use mozprocess. One is buffering. Another is debugging. We've had issues where interactive debuggers work best if there is no intermediate mechanism between firefox and the terminal.

So, `mach run` needs to continue using the terminal's file descriptors (not pipes). The proper fix is to use something like the code linked in comment #6 to get the Firefox processes to properly attach and write to the Windows console in e-10s mode.

Alternatively, we /might/ be able to use mozprocess when we're not using a debugger. But IIRC there are still issues with pipes with things like running inside of emacs. There have been enough bugs filed over the years regarding `mach run` standard file descriptor behavior that I'd rather not change `mach run`.

Comment 18

[(not currently active) Ted Mielczarek]

(In reply to :Gijs Kruitbosch from comment #16)
> I don't know if that's the "best fix" - I'm not a domain expert on pipes and
> what is "expected" stdout/stderr behaviour. It just strikes me as odd that
> things "just work" on Linux and OS X and don't on Windows. As far as I'm
> concerned, we should do whatever it takes to make things "Just Work" on
> Windows, too. From what you're saying mach run doesn't redirect output, so
> how come it "just works" on Linux/OSX, then? Am I just misunderstanding what
> that means?

Windows and Linux/OSX differ in the way they handle stdio. On Windows, we build Firefox as a GUI application, which means it doesn't get a "console" by default, so you don't see a Windows console when you run it (which is the right thing). Unfortunately, when you run a GUI application *from* a console on Windows, you *still* don't get a console by default, so your stdio goes nowhere. We have supported a `-console` argument for a long time that does force us to create one, but this doesn't do what you want when you're running from an existing console (it pops up a brand-new one). We attempted to make Firefox do the right thing when you ran it from an existing console some time ago (bug 673383), but this broke some users' use cases (running Firefox from batch files), so we instead added `-attach-console` (bug 787313) which is sort of a crummy workaround.

`-attach-console` *should* produce the desired behavior (attach stdio to the current console), and is what padenot's patch implements in `mach run`, but padenot indicated that it did not work, which might just be bug 1189223.

Comment 19

[Decathlon]

I'm using Thunderbird and this is now working for me starting from version 53.0a1 (Build ID 20170115030207) while it wasn't working until Thunderbird 52.

Comment 20

[Luke Wagner [:luke]]

Is this something we can make progress on?  This issue consistently wastes hours of my time when I need to switch to Windows to debug a problem.

Comment 21

[:Gijs (out for now; he/him)]

Paul said on IRC that this patch might work better these days?

Comment 22

[Paul Adenot (:padenot)]

Attachment: Bug 1257155 - WIP console windows, works with sandbox disabled, but with e10s

Comment 23

[Paul Adenot (:padenot)]

This does something at least. It looks like we can't attach the console to the parent's console sometimes, because we already have a console.

With this patch, I can use stdout (for example window.dump or printf) on Windows, e10s, but with sandbox disabled. I don't know why this is needed yet.

Comment 24

[:Gijs (out for now; he/him)]

Attachment: Bug 1257155 - make mach run create console output by default on windows so dump/printf works in the parent process, r?froydnj

Comment 25

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c54d2a89bc37
make mach run create console output by default on windows so dump/printf works in the parent process, r=froydnj

Comment 26

[Alexandru Michis [:malexandru]]

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