557121 - After following the jetpack-sdk-0.2 docs introduction, 'cfx run' runs the example with a "Program terminated unsuccessfully" message, returns the command prompt, then echoes out "info: Hello world! OK" twice more.

Status: RESOLVED FIXED

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

Description

[stenington]

User-Agent:       Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-US; rv:1.9.2.3) Gecko/20100401 Firefox/3.6.3
Build Identifier: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-US; rv:1.9.2.3) Gecko/20100401 Firefox/3.6.3 jetpack-sdk-0.2

Output is:
(jetpack-sdk-0.2)Macintosh-2:my-first-package mlarsson$ cfx run
info: Hello world!
OK
Total time: 0.404998 seconds
Program terminated unsuccessfully.
(jetpack-sdk-0.2)Macintosh-2:my-first-package mlarsson$ info: Hello world!
OK
info: Hello world!
OK

at which point hitting enter returns my command prompt. This behavior is consistent across multiple runs.

Reproducible: Always

Steps to Reproduce:
1. source bin/activate
2. cd to package/my-first-package
3. cfx run
Actual Results:  
(jetpack-sdk-0.2)Macintosh-2:my-first-package mlarsson$ cfx run
info: Hello world!
OK
Total time: 0.404998 seconds
Program terminated unsuccessfully.
(jetpack-sdk-0.2)Macintosh-2:my-first-package mlarsson$ info: Hello world!
OK
info: Hello world!
OK

Expected Results:  
Successful termination and no echo

Comment 1

[Atul Varma [:atul]]

I talked to stenington and it looks like this happens with both Firefox 3.5 and 3.6.

Comment 2

[Atul Varma [:atul]]

I've been able to reproduce this on jetpack-sdk trunk with Firefox 3.6.3, though my output is slightly different:

> (jetpack-sdk)atul-computer:my-first-package varmaa$ cfx run
> info: Hello world!
> OK
> info: Hello world!
> OK
> Total time: 1.002300 seconds
> Program terminated successfully.
> (jetpack-sdk)atul-computer:my-first-package varmaa$

Comment 3

[Atul Varma [:atul]]

It looks like the harness.js XPCOM component is being evaluated twice, possibly because the app is restarting itself.

i.e., adding this to the top of harness.js:

> dump("Now evaluating harness.js.\n"); 

Results in the following output:

> (jetpack-sdk)atul-computer:my-first-package varmaa$ cfx run
> Now evaluating harness.js.
> info: Hello world!
> OK
> Now evaluating harness.js.
> info: Hello world!
> OK
> Total time: 1.055813 seconds
> Program terminated successfully.
> (jetpack-sdk)atul-computer:my-first-package varmaa$ 

Curiously, though, running 'cfx run -a firefox' makes everything work fine.

Comment 4

[stenington]

Same result for 'cfx run -a firefox' for me: everything is fine, including a successful termination.

Comment 5

[Atul Varma [:atul]]

Attachment: Fixes 'cfx run' but breaks 'cfx test'

Comment 6

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

Atul has taken a look at this, but he was unable to quite figure out what's going on.  His patch, originally called "fixes", is now called "fixes 'cfx run' but breaks 'cfx test'" because it causes regressions, and it's not clear how to resolve those problems.

It seems valuable to fix this for 0.3, given that it's aberrant behavior that you encounter when following the tutorial's instructions.  This may be an issue with multiple invocations of the nsGetModule code that bootstraps Jetpack.

Dietrich: is there someone on the Firefox team who might be able to dive in and help out here?

Comment 7

[Dietrich Ayala (:dietrich)]

not seeing this on linux for firefox 3.6. eg, this does not exhibit the bug:

cfx --binary=/usr/bin/firefox-3.6 

Atul, if you can reproduce this, can you confirm for sure that harness.js is getting executed twice (ie, that it's a restart)?

It could be that the way cuddlefish is loading the application is causing the registration restart that occurs when extensions and whatnot that require xpcom registration are installed.

If that's the case, then maybe app-startup is too early for init, and maybe you need to wait until final-ui-startup notification.

Comment 8

[Dietrich Ayala (:dietrich)]

I take it back. I wasn't following the STR correctly. I can reproduce the problem now with trunk and 3.6.

Comment 9

[Dietrich Ayala (:dietrich)]

Heh, with this patch applied, "cfx test" is hanging because NSGetModule() is being called in an infinite loop. Looking...

Comment 10

[Dietrich Ayala (:dietrich)]

I captured the raw command output of mozrunner. When I run that on the command line, the app is only run once. However, when mozrunner does it, the app is run twice.

Still looking...

Comment 11

[Dietrich Ayala (:dietrich)]

XRE_main is being executed twice, so which indicates that we're triggering the registration/extension install/app-update restart somehow.

Comment 12

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

Given that this is the last day of the 0.3 development cycle and this is unassigned, it doesn't seem likely that a fix will make 0.3.  That's ok, as this isn't a blocker (you can still use |cfx run| to manually test addons despite this suboptimal behavior).

Nevertheless, it would be useful to get this fixed, since it's noticeable and confusing to developers.  Retargeting to 0.4.

Dietrich: it looks like you've dug into this a bit; is this something you would be able to work more on?

Comment 13

[Dietrich Ayala (:dietrich)]

Yep, taking.

Comment 14

[Dietrich Ayala (:dietrich)]

the problem is that the harness is both initialized *and* executed in the scoped-xpcom-startup cycle (ie, that mini-startup where any new components are added, they're registered and then the app is restarted for reals).

the solution is to ensure that no jetpack code runs during scoped-xpcom-startup. scoped-xpcom startup sends app-startup as well as profile-after-change. which means that final-ui startup is what we want to initialize on. before that point, addons that want to launch at app-startup can fail in many ways, because so many core services are not running.

i see that the test harness is aware of this, and doesn't run tests until final-ui-startup (in the xulrunner case, for example). i'm not comfortable with this kind of low-level awareness being in higher-level pieces, due to problems like this bug (for instance, when i fixed the double-startup, tests failed because they were running before the harness was initialized!).

my proposal to fix both problems is this:

- change harness.js to execute harness.load() at final-ui-startup.
- add a new notification, that's basically the jetpack equivalent of jquery's $(document).ready(), and send it from the harness, using the per-app notification scheme currently used in run-tests.js.
- remove the application-specific notification stuff in run-tests.js and listen for the new "ready" topic instead.

code-wise, these changes are actually pretty minor, so we might still want this for 0.3. we *really* want a system better than the current startup notifications. that sytem has caused no end of problems for us in Firefox-land. even if the .ready() approach gets changed later, it's clean and simple enough for now i think, and definitely fixes these immediate problems.

Comment 15

[Dietrich Ayala (:dietrich)]

another note: for add-ons that need to hook in very early in the startup path, we can add newer and clearer support for that later. we don't need to solve that problem now.

Comment 16

[Dietrich Ayala (:dietrich)]

changing to P1, since modules could be activated long before there's a usable browser environment, but expecting there to be.

Comment 17

[Atul Varma [:atul]]

Yeah, I dig it!

Let's do it.

Comment 18

[Dietrich Ayala (:dietrich)]

Attachment: v1

passes all unit tests.

one addition to the changes described above, is a move towards Jetpack-defined notification topics, that aren't platform version dependent, use consts instead of raw strings, and that can be scoped to individual jetpack-derived extensions.

the change was required so that jetpack-derived extensions wouldn't broadcast self-scoped notifications to other jetpack-derived extensions. however, it provides all the other benefits i just listed as well.

we should espouse use of this in our module development and documentation, instead of relying on the old mozilla notifications.

Comment 19

[Atul Varma [:atul]]

Comment on attachment 440626 [details] [diff] [review]
v1

This looks great. I also tested the change with a number of my Jetpack-based addons and it works fine.

Comment 20

[Dietrich Ayala (:dietrich)]

ack, never marked fixed!

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

Comment 21

[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".