554241 - cfx should have a --logfile option

Status: RESOLVED FIXED

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

Description

[Atul Varma [:atul]]

Since there's no way to actually print anything to stdout on windows and the optional console output is lost when the console is closed, there's no way to capture test output on Windows machines during continuous integration. If we provide an optional --logfile parameter to cfx, though, we can log output to a file, which a buildbot can include in its results.

Furthermore, on Windows we can just log to a temporary file even if --logfile isn't specified; then we can just display the contents of this file as a program runs instead of printing stuff to a separate console window, which would make windows cfx behavior match linux and os x behavior.

Comment 1

[Atul Varma [:atul]]

Attachment: patch

Comment 2

[Atul Varma [:atul]]

Note that this bug doesn't (yet) actually follow the behavior outlined in the second paragraph of the bug description. That is, the patch does add the --logfile option, but it does not make cfx on windows behave like cfx on osx/linux.

Comment 3

[Atul Varma [:atul]]

Note also that if we do make cfx on windows behave like it does on osx/linux, this should obviate the need for the bug-ridden --no-quit command (see bug 553744).

Comment 4

[Atul Varma [:atul]]

Attachment: patch 2, now echoing logfile to stdout and force-enabling it on windows

Comment 5

[Atul Varma [:atul]]

Attachment: Added doctest for cuddlefish.runner.follow_file()

Comment 6

[Atul Varma [:atul]]

This patch seems to work on my Windows 7 VM, though I get two identical tracebacks when cfx exits (right after running 'cfx test' in the jetpack-core dir):

Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "c:\python26\lib\atexit.py", line 24, in _run_exitfuncs
    func(*targs, **kargs)
  File "C:\jetpack-sdk\python-lib\cuddlefish\runner.py", line 108, in maybe_remo
ve_logfile
    os.remove(logfile)
WindowsError: [Error 32] The process cannot access the file because it is being
used by another process: 'c:\\users\\varmaa\\appdata\\local\\temp\\harness_log'
Error in sys.exitfunc:
Traceback (most recent call last):
  File "c:\python26\lib\atexit.py", line 24, in _run_exitfuncs
    func(*targs, **kargs)
  File "C:\jetpack-sdk\python-lib\cuddlefish\runner.py", line 108, in maybe_remo
ve_logfile
    os.remove(logfile)
WindowsError: [Error 32] The process cannot access the file because it is being
used by another process: 'c:\\users\\varmaa\\appdata\\local\\temp\\harness_log'

This is a common, annoying error with Windows: the OS seems to hang on to files a lot longer than other OSes, which results in weird race conditions like this. Only thing I can think of doing is waiting for a bit after trying to remove the file and trying again.

Comment 7

[Atul Varma [:atul]]

Also, if we take this patch, I suspect we should remove the --no-quit command and also prevent -console from being passed to Firefox/Thunderbird/etc.  Having a separate console pop up while cfx is running, which displays exactly what's being displayed at the command-line, is confusing and distracting and not terribly useful.

Comment 8

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

I see those tracebacks too when running in MozillaBuild; but when running in standard cmd.exe, I get a different traceback:

(Z:\myk\Projects\jetpack-sdk) Z:\myk\Projects\jetpack-sdk>cfx testall --binary="
C:\Program Files\Mozilla Firefox\firefox.exe"
Testing all available packages: test-harness, org.mozilla.myk, frame, jetpack-co
re, mykzample, bar, foo, panel.
Traceback (most recent call last):
  File "Z:\myk\Projects\jetpack-sdk\bin\cfx", line 6, in <module>
    cuddlefish.run()
  File "Z:\myk\Projects\jetpack-sdk\python-lib\cuddlefish\__init__.py", line 220
, in run
    test_all_packages(env_root, defaults=options.__dict__)
  File "Z:\myk\Projects\jetpack-sdk\python-lib\cuddlefish\__init__.py", line 181
, in test_all_packages
    defaults=defaults)
  File "Z:\myk\Projects\jetpack-sdk\python-lib\cuddlefish\__init__.py", line 437
, in run
    logfile=options.logfile)
  File "Z:\myk\Projects\jetpack-sdk\python-lib\cuddlefish\runner.py", line 168,
in run_app
    popen = subprocess.Popen(cmdline, env=env, **popen_kwargs)
  File "C:\Python26\lib\subprocess.py", line 621, in __init__
    errread, errwrite)
  File "C:\Python26\lib\subprocess.py", line 830, in _execute_child
    startupinfo)
WindowsError: [Error 2] The system cannot find the file specified

Comment 9

[Atul Varma [:atul]]

Hmm, something really weird is going on. Between your traceback and the problem you mentioned in Bug 553739 comment 4, I'm guessing that Python is somehow having issues with your VM that it doesn't normally have; it seems to be dying in your traceback because it doesn't think there's a file at "C:\Program Files\Mozilla Firefox\firefox.exe", and similarly, MozRunner isn't finding Firefox at that default location either, even though it is automatically finding Firefox at the exact same location on my system. So at the very least, I'm guessing your traceback above and your problem in Bug 553739 are actually caused by the same underlying problem.

Comment 10

[Atul Varma [:atul]]

Attachment: patch with '-console' removed from cmdline and file-in-use errors fixed, using killableprocess instead of subprocess.

Comment 11

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

I dug in deeper, and my problems were actually user error.  Firefox is not installed where I thought it was on my system, which is 64-bit, so Windows installs 32-bit applications in C:\Program Files (x86)\.  After specifying the binary, the patch works as expected, although there is a test failure:

(Z:\myk\Projects\jetpack-sdk) Z:\myk\Projects\jetpack-sdk>cfx testall --binary="
C:\Program Files (x86)\Mozilla Firefox\firefox.exe"
Testing all available packages: test-harness, jetpack-core.
................................................................................
................................................................................
.....................................error: fail: file.read() on dir should rais
e error ("XPCOM error: Component returned failure code: 0x80520015 (NS_ERROR_FIL
E_ACCESS_DENIED) [nsIFileInputStream.init]" doesn't match /^The stream was opene
d on a directory/)
info: Traceback (most recent call last):
  File "resource://testall-jetpack-core-lib/timer.js", line 57, in notify
    this._callback.apply(null, []);
  File "resource://testall-jetpack-core-lib/unit-test.js", line 201, in anonymou
s
    timer.setTimeout(function() { onDone(self); }, 0);
  File "resource://testall-jetpack-core-lib/unit-test.js", line 224, in runNextT
est
    self.start({test: test, onDone: runNextTest});
  File "resource://testall-jetpack-core-lib/unit-test.js", line 238, in start
    this.test(this);
  File "resource://testall-jetpack-core-lib/unit-test.js", line 56, in runTest
    test(runner);
  File "resource://testall-jetpack-core-tests/test-file.js", line 60, in anonymo
us
    "file.read() on dir should raise error"
  File "resource://testall-jetpack-core-lib/unit-test.js", line 145, in assertRa
ises
    this.assertMatches(errorMessage, predicate, message);
  File "resource://testall-jetpack-core-lib/unit-test.js", line 127, in assertMa
tches
    this.fail(message);
  File "resource://testall-jetpack-core-lib/unit-test.js", line 107, in fail
    console.trace();
..........
Malloc bytes allocated (in use by application): 6914848
Malloc bytes mapped (not necessarily committed): 13631488
Malloc bytes committed (readable/writable): 12066816
Malloc bytes dirty (committed unused pages): 3317760
Tracked memory objects in testing sandbox: 2

207 of 208 tests passed.
Total time: 5.673000 seconds
Program terminated unsuccessfully.

Comment 12

[Atul Varma [:atul]]

Oh ok! So it sounds like we need to add "C:\Program Files (x86)\Mozilla Firefox" as a place for Mozrunner to look then. I've just filed bug 554709 for this.

I actually get the same traceback myself, and just filed bug 554712 for it.

Does it look like this bug is resolved, though? Should I mark it as fixed and commit the patch to the repo?

Comment 13

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

(In reply to comment #12)
> Does it look like this bug is resolved, though? Should I mark it as fixed and
> commit the patch to the repo?

Yes!

Comment 14

[Atul Varma [:atul]]

Woot! It is done:

  http://hg.mozilla.org/labs/jetpack-sdk/rev/d17ba02cc041

Comment 15

[Atul Varma [:atul]]

Now we just need to obsolete --no-quit; I've added bug 554720 for that.

Comment 16

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

The Add-on SDK is no longer a Mozilla Labs experiment and has become a big enough project to warrant its own Bugzilla product, so the "Add-on SDK" product has been created for it, and I am moving its bugs to that product.

To filter bugmail related to this change, filter on the word "looptid".