665250 - dump() output discarded when Firefox is run by Jetpack

Status: RESOLVED FIXED

(Add-on SDK Graveyard :: General, defect, P2)

Description

[Mark Hammond [:markh] [:mhammond]]

If you execute FF via the SDK (ie, cfx run), the output of any dump() statements can't be seen.  This is true even when you use "cfx run --binary-args=-console").  If instead, you use "cfx run --no-run", then manually execute the command-line printed and append "-console", the output is seen as normal.  This is true for dump calls both in the addon and in regular content.

This isn't a huge problem for addons - they have a working console.log.  However, in my case my addon displays a regular web page in a panel and (even with firebug and chromebug installed) doesn't have a console.log which works.  Therefore, this HTML content really only has (had) dump() available for debug output - but that output is lost when run under the SDK.

I suspect this is Windows only - I did have a little play with the popen and redirection code in cuddlefish but failed to find a clue.  My work-around is to use the --no-run option to prepare the profile, then execute FF manually with -console.

Comment 1

[Mark Hammond [:markh] [:mhammond]]

I played a little more with this.  It appears things are complicated by the fact firefox.exe is a "gui" process (ie, is not automatically attached to a console) so the default redirection mechanism doesn't work (I suspect the problem is that we set stdout etc to our "console", but when the process starts it becomes immediately disconnected from the console).

If anyone cares, this can be seen by experimenting with the simple Python script below.  If you run it so python.exe is used as the child-process, things work as expected (ie, you see the output) but if you modify the script to point at a pythonw.exe the output from the child process is discarded.

import sys
import subprocess
exe = sys.executable
#exe = r"o:\src\python-2.6\pcbuild\pythonw.exe"
cmd = [exe, "-c", "import sys; sys.stdout.write('hello stdout\\n'); sys.stderr.write('hello stderr\\n')"]
p = subprocess.Popen(cmd, stdout=sys.stdout, stderr=sys.stderr)
p.wait()

The only way I could make it work was to create a subprocess "pipe" between the 2 processes, then create a new thread which reads the pipe and dumps what it reads to stdout - the new thread is necessary as read() calls block.  With this patch I see the expected dump output (with no need to run the child process with the -console arg)

Comment 2

[Mark Hammond [:markh] [:mhammond]]

Attachment: Use a pipe and thread to collect child process output.

Comment 3

[Mark Hammond [:markh] [:mhammond]]

Unfortunately, even with the patch there is some buffering of stdout in the child process (ie, inside FF itself) which means not all output is visible immediately.

I think this is the same problem as bug 430967 and might even be the same as bug 476773

Comment 4

[Myk Melez [:myk] [@mykmelez]]

Comment on attachment 540675 [details] [diff] [review]
Use a pipe and thread to collect child process output.

This fixes the problem for me with the standard Windows terminal, whether or not I'm using MozillaBuild.

Unfortunately, it seems to make things worse with mintty, buffering dump output until I quit the browser.

My test involves entering URLs like <javascript:dump("foo\n")> into the location bar.  When I "cfx run" from the standard Windows terminal without the patch, nothing ever gets printed to the terminal, whereas with the patch it does.

The SDK doesn't explicitly support mintty, so the mintty issues aren't a blocker, although it sure would be nice to figure them out, since mintty is a nice terminal.

FWIW, I use mintty in place of the standard Windows terminal by copying it into MozillaBuild's bin directory and modifying MozillaBuild's start-msvc10.bat script:

- start /d "%USERPROFILE%" "" "%MOZILLABUILD%"\msys\bin\bash --login -i
+ start /d "%USERPROFILE%" "" "%MOZILLABUILD%"\msys\bin\mintty /bin/bash --login -i

Brian: you're the better reviewer for Python stuff, and I'm particularly unfamiliar with threading in Python; can you take a look at this as well?

Comment 5

[Mark Hammond [:markh] [:mhammond]]

> Unfortunately, it seems to make things worse with mintty, buffering 
> dump output until I quit the browser.

Interesting - so without the patch but using mintty, you see dump() output and see it unbuffered?  That implies mintty is doing something smart wrt redirection that we could also do if only we knew what that was :)

I've assumed the buffering is something that only the child process can control.  I don't have a locally built moz handy, but it would be very interesting to know if the printf() done by dump - which I think is at:

http://mxr.mozilla.org/seamonkey/source/dom/src/base/nsGlobalWindow.cpp#3907

was followed by a fflush(stdout) - I think that would solve the buffered output problem.  In bug 476773, ROC implies this might be a reasonable thing to do.

Comment 6

[Alexandre Poirot [:ochameau]]

I faced a related issue while working on jetpack runner,
I ended up seing differences between dump() function from documents (i.e. from nsGlobalWindow) and dump() function in xpcom:
http://mxr.mozilla.org/mozilla-central/source/js/src/xpconnect/shell/xpcshell.cpp#439

There is, at least one other implementation of dump:
http://mxr.mozilla.org/mozilla-central/source/js/src/xpconnect/loader/mozJSComponentLoader.cpp#189

In my case, dump from nsGlobalWindow was working whereas I wasn't able to catch xpcom ones.

Finally, between stdout issue and windows that doesn't show up, I ended up writting crazy windows command line pipe:
https://github.com/ochameau/jetpack-runner/blob/master/lib/moz-launcher.js
This "thing" allow me to catch all kinds of dump() *and* make firefox windows appear!

Comment 7

[Myk Melez [:myk] [@mykmelez]]

(In reply to comment #5)
> Interesting - so without the patch but using mintty, you see dump() output
> and see it unbuffered?  That implies mintty is doing something smart wrt
> redirection that we could also do if only we knew what that was :)

Yeah. :-)


> I've assumed the buffering is something that only the child process can
> control.  I don't have a locally built moz handy, but it would be very
> interesting to know if the printf() done by dump - which I think is at:
> 
> http://mxr.mozilla.org/seamonkey/source/dom/src/base/nsGlobalWindow.cpp#3907
> 
> was followed by a fflush(stdout) - I think that would solve the buffered
> output problem.  In bug 476773, ROC implies this might be a reasonable thing
> to do.

I can build Mozilla, but the version of dump on mozilla-central is different from the one in SeaMonkey, and it already does flush after writing:

http://mxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.cpp#4473

Comment 8

[Drew Willcoxon :adw]

(In reply to comment #7)
> I can build Mozilla, but the version of dump on mozilla-central is different
> from the one in SeaMonkey, and it already does flush after writing:
> 
> http://mxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.
> cpp#4473

There's another dump implementation, the one that's used for dump() calls inside sandboxes:

http://mxr.mozilla.org/mozilla-central/source/js/src/xpconnect/src/xpccomponents.cpp#2951

Unlike nsGlobalWindow::Dump, this one doesn't flush its stream.  (But Boris says it should in bug 570291 comment 4.)  I'm not sure which dump()s you guys are talking about, but given all the sandboxes in Jetpack I thought this might be relevant.  Sorry if not.

Comment 9

[Brian Warner [:warner :bwarner]]

Comment on attachment 540675 [details] [diff] [review]
Use a pipe and thread to collect child process output.

Sorry for the delay.. threads always make me nervous, and I'm reluctant to
let them creep into any project.

I'm also confused as to how this patch is accomplishing the fix (I totally
believe you that it does, I'm just puzzled as to how). It redirects the
child's stdout+stderr to a pipe, then manually copies this pipe off to cfx's
stdout. The default behavior (without this patch) should be to let the
child's stdout write directly to cfx's stdout, and the child's stderr to
cfx's stderr. I'm always in favor of a "straight paper path": if there's a
way to just set up the subprocess.Popen() args differently, I'd prefer it.

Could it be that FF is detecting whether its own stdout/stderr is a pipe or a
tty, and changing its behavior as a result? Shells normally open a pty for
their subprocesses, so (at least in the unix world that I'm familiar with)
cfx's stdout will look different than the pipe created by this patch. You
might try running 'cfx run >outfile' (without the patch) and see if it
correctly captures the dump() output. If so, .. hm, if so, then this patch is
still the easiest way to make it work (and FF's behavior should be fixed:
non-interactive programs should behave the same way against pipes as they do
against tty/ptys).

But, if the stdout-pipe-poller is the way to go, then I'm ok with the thread.
The most obvious alternative to a thread is to set the pipe to be
non-blocking and do a polling loop, but 1) that's messy without a framework
to handle it for you, and 2) probably wouldn't work on windows anyways.

It looks to me that the final join() is dependent upon the child process
terminating correctly (the thread doesn't exit until it reads EOF). Does this
handle a timeout properly, when the child process is killed by mozrunner? We
might consider having a are-we-shutting-down flag, so the 'while True' loop
would become 'while not self.shutting_down'. I suspect that'd be overly
paranoid, though.

You probably want a sys.stdout.flush() in that loop: you might be getting
data buffered inside *python* at this point, since sys.stdout is typically
buffered by default (this might explain Myk's mintty buffering observation).
Also, I think you can read() more than a single byte without causing it to
block, which would make things a lot more efficient (the docs say 'read at
most size bytes')..

Given Myk's observation about mintty, is it worth making this behavior
conditional upon a command-line argument rather than just switching on
are-we-on-windows?

If you can find a simpler way to make this work, that'd be better. But if
not, and if you can make it keep working with Myk's mintty setup, I'm r+ on
it.

(Would it suffice to figure out how to get -console passed to FF correctly?
Sounds like that'd leave windows users without a working dump unless they go
through extra hoops, though.)

Comment 10

[Brian Warner [:warner :bwarner]]

Ok, after talking with Myk, I'm going to land this with an extra stdout.flush() in the polling loop. Myk is going to test the result against mintty and see if the flush helps anything. And I'll ask Gabor to look into how the various dump() and console.log() paths in the platform might be inconsistently flushing their output: life will probably be easier if all those paths behave the same way.

Comment 11

[Brian Warner [:warner :bwarner]]

Landed in https://github.com/mozilla/addon-sdk/commit/0a6b27b3b23966d3f5ddb0fe40f1b3eb8beaf478 .

Forget what I said about reading more than one byte at a time: I tested that and the output stalled until more text was written. I did add the flush(), just in case it helps Myk's mintty problems.

Hopefully this will solve the problem. I'd like to learn what the actual problem is, since I really don't understand how this fix helps, and if we can find a simpler solution, let's not hesitate to remove this change and land a better one.

Comment 12

[Mark Hammond [:markh] [:mhammond]]

What appears to be happening is:

* The parent Python process is a 'console' process with its stdout attached to the console.
* The child process, which is *not* marked as a console process, it started with its stdout being duplicated copies of the parent - ie, the console.
* As the child is not a console process, it is detached from the console and the output is discarded.

Note the above is quite different from Unix - on Windows, the executable itself has a flag to indicate if it is a "console" process or not and Windows will create a new console if necessary before the process starts.  Firefox.exe etc are all marked as "windows" programs even though they optionally create their own console once started.  This would be quite different if we were spawning a process marked as being a "console" process (and firefox must be marked as a "windows" process or Windows would automatically create a console every time it is launched from a non-console environment, such as the shell)

So the patch arranges for an anonymous pipe between the parent and the child for stdout and this pipe survives OK.

The reason this pipe is read on a separate thread is due to the reads on that pipe blocking until the requested number of bytes have been read.  If this read - even for 1 char - was in the main thread, that thread would be blocked until something was written to the pipe by the child.  As the parent's main thread is already looping we would interfere with that loop.

Regarding the final join: I think the join is safe so long as the child process has terminated - that will close the pipes so the thread will terminate.  I don't think a flag will work as that thread will generally be blocked in a read() anyway.  Non-blocking reads on the handle might work, although that would require either re-adding pywin32 as a dep (hey - I'm the author of that package, so that would be fine with me ;) or lots of ugly ctypes hacking, which I don't think is worthwhile.

Comment 13

[Gabor Krizsanits (INACTIVE)]

Just an idea... Using setInterval from the javascript word that polls the pipe with a PeekNamedPipe (which is non blocking) and then if there is something to read on the pipe, only then it reads it (again non blocking). Could this be an alternative for the thread?

Comment 14

[Myk Melez [:myk] [@mykmelez]]

(In reply to comment #11)
> I did add the flush(), just in case it helps Myk's mintty problems.

It does!  With the version of the patch that landed, mintty displays dump output the moment I dump it.

Comment 15

[Mark Hammond [:markh] [:mhammond]]

(In reply to comment #13)
> Just an idea... Using setInterval from the javascript word that polls the
> pipe with a PeekNamedPipe (which is non blocking) and then if there is
> something to read on the pipe, only then it reads it (again non blocking).
> Could this be an alternative for the thread?

It would probably work fine - but unless I misunderstand, that non-blocking code needs to be in the Python side of the world and Python doesn't expose these APIs directly - meaning pywin32 or ctypes would be needed.  IMO, using a fairly simple thread is the lesser of these 2 evils.

Comment 16

[Alexandre Poirot [:ochameau]]

cfx always worked fine on Windows (my main desktop OS). 
I'm using Windows 7 and regular windows command line.

Here is an example of what I get on command line:
#####
Using binary at 'C:\Program Files (x86)\Mozilla Firefox\firefox.exe'.
Using profile at 'c:\users\coup2b~1\appdata\local\temp\tmp0k1m6n.mozrunner'.
Running tests on Firefox 5.0/Gecko 5.0 ({ec8030f7-c20a-464f-9b0e-13a3a9e97384})
under WINNT/x86-msvc.

0 of 0 tests passed.
No tests were run
Running tests on Firefox 5.0/Gecko 5.0 ({ec8030f7-c20a-464f-9b0e-13a3a9e97384})
under WINNT/x86-msvc.

0 of 0 tests passed.
No tests were run
FAIL
Total time: 2.285000 seconds
Program terminated unsuccessfully.
#####

Just before cfx quit, it dump the whole stdout again.
Am I the only one to had it working before this patch?!

Comment 17

[Mark Hammond [:markh] [:mhammond]]

(In reply to Alexandre Poirot (:alex) from comment #16)
...
> Here is an example of what I get on command line:

None of that output seems to come from "dump()" in a content script.  Before this patch, if you loaded a html file with a call to dump(), that output was discarded when run by cfx.  console.log() from jetpack modules etc always worked fine.

Comment 18

[Brian Warner [:warner :bwarner]]

Mark: ah, ok, that makes sense to me. Thanks.

Is it safe to close this now?

Comment 19

[Mark Hammond [:markh] [:mhammond]]

I reckon so!

Comment 20

[Alexandre Poirot [:ochameau]]

Hum. Ok I didn't saw the real improvement of this patch, but the regression is still here. I thought we would have to reopen bugs that come with big regression?
In any case I opened bug 679313.

Comment 21

[Mark Hammond [:markh] [:mhammond]]

I;m sorry, but I didn't understand you where also reporting a regression caused by this fix.  I've added comments on the new bug.

Comment 22

[Mark Hammond [:markh] [:mhammond]]

This patch has caused some output to be duplicated.  I suspect it will take a little time to address this properly, so in the short term I suggest we revert this patch, re-open this bug and close bug 679313.  Sorry 'bout that :)

Comment 23

[Myk Melez [:myk] [@mykmelez]]

Sounds like a plan, so reverted:

https://github.com/mozilla/addon-sdk/commit/1dca14fd724907997f0fc0068e90c01781824621

And reversion cherry-picked to stabilization branch:

https://github.com/mozilla/addon-sdk/commit/ba1749ccb1a7d16efff7e45989eeb5698b63a7b9

Comment 24

[Mark Hammond [:markh] [:mhammond]]

Attachment: A simple little project to help diagnose this

A simple little project to help diagnose this:

* When doing "cfx run" and immediately closing the browser you should see in the output:
  dump: addin loading
  ...
  dump: addin terminating

* When doing "cfx test" you should see:
  hello from the dumper
  ...
  this is a dump in a test

Comment 25

[Mark Hammond [:markh] [:mhammond]]

Attachment: updated patch

Finally found the duplicated output problem in the tests.  The problem is that cuddlefish's runner.py has some special hacks for Windows to work around the underlying problem.  These hacks mean that most 'print' calls in the test infrastructure wind up calling dump() *and* appends the data to a log file - and the runner is watching the log file for output and printing it.  So once we arrange for the dump() calls to be seen we wind up seeing them twice.

The new patch includes the original changes, but also removes these hacks from the test infrastructure, resulting in the expected output on Windows.

Note this patch might cause a regression when using cygwin Python - the "redirect and thread" part of the patch will only be enabled when using normal Windows Python, but the logFile portion of the patch checked for both normal python and cygwin python - but I can't make the sdk work with cygwin at all (either using the unix instructions (ie, source bin/activate) from a cygwin bash shell, or using the windows instructions (ie, activate.bat) when only the cygwin Python can be located.

Comment 26

[Brian Warner [:warner :bwarner]]

Comment on attachment 556481 [details] [diff] [review]
updated patch

Seems reasonable to me, and I love removing code. I don't have a windows box to test on, but it doesn't break anything on OS-X. The only change I'd make is to remove the unused imports from runner.py (atexit, and shutil while you're at it).

Myk: what do we know about the state of cygwin? If this regresses a working cfx there then we should investigate further, but if it's already broken (or if it happens to work), then I can land this.

Comment 27

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 556481 [details] [diff] [review]
updated patch

More playing shows there might be some buffering issues I didn't see before.  Sad to say that I might need to continue to investigate a few things...

Comment 28

[Mark Hammond [:markh] [:mhammond]]

FYI, I tracked the buffering issues down and opened bug 683400 to fix the underlying issue - however, I still need to ponder the best way to address that in Jetpack given the underlying issue won't be fixed until FF9 at the earliest.

Comment 29

[Myk Melez [:myk] [@mykmelez]]

(In reply to Brian Warner [:warner :bwarner] from comment #26)

> Myk: what do we know about the state of cygwin? If this regresses a working
> cfx there then we should investigate further, but if it's already broken (or
> if it happens to work), then I can land this.

I don't know what the state is, and I understand the concern, but I don't think we can afford to slide into supporting environments just because they happen to work at some point.

We currently recommend two Windows environments: the standard Windows terminal (BYO Python) and MozillaBuild, which uses the standard Windows terminal and provides Python plus MSYS.  And even that feels schizophrenic to me.  So I would be very cautious about also blocking on Cygwin support (and, as I mentioned before, Mintty support is also not a blocker, as much as I like that terminal app and want it to work).

Comment 30

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

(Pushing all open bugs to the --- milestone for the new triage system)

Comment 31

[Mark Hammond [:markh] [:mhammond]]

I believe bug 692554 has caused this problem to now be on all platforms and has caused one further regression - *all* dump() output is now discarded, not only dump() called from content scripts.

The root cause is that now the firefox process has its output redirected to /dev/nul, so only output specifically generated by jetpack is shown.  Output generated by anything else, including dump, is now discarded.

Comment 32

[Mark Hammond [:markh] [:mhammond]]

Attachment: Redirect stdout/stderr to a file and follow_file it

Attaching another patch which redirects to a file and follows that.  It is pretty inefficient - but just as inefficient as following the log file and I think threads are going to be frowned upon :)

Comment 33

[Mark Hammond [:markh] [:mhammond]]

Note that the patch isn't perfect - the actual order of the output may differ from what it should be - eg, code like:

dump("hello from dump\n")
console.log("hello from the console");

might result in the second line appearing before the first.  But at least both appear :)

Comment 34

[Myk Melez [:myk] [@mykmelez]]

Comment on attachment 569003 [details] [diff] [review]
Redirect stdout/stderr to a file and follow_file it

*sigh*

Perhaps one day all `dump`s in the platform will write to the same place and we can get rid of all our convoluted code for getting output to the terminal.  In the meantime, I can't think of a better option than this one.

Comment 35

[Myk Melez [:myk] [@mykmelez]]

https://github.com/mozilla/addon-sdk/commit/e57a29e9a1ba3b9c1fff1855ded43688c3bfecff