1008135 - Application update logs are not printed to the console

Status: RESOLVED WONTFIX

(Testing :: Firefox UI Tests, defect)

Description

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

When you run our update tests from the mozmill-tests repository, you will notice that the log entries, when the preference 'app.update.log' is enabled, are no longer printed to the console. I have checked the preferences we set by default, but all looks fine. Nothing regressed there. So maybe it's something with the environment or a mozbase package?

Andrei, could anyone with a dev environment on Windows do a regression test here? I would appreciate that.

Comment 1

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

Just to add, all that still works on OS X and Linux. So there is something Windows specific here. Maybe the switch to the IO completion ports. Maybe bug 1008086 is related but only visible when ConEmu is running?

Comment 2

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

Looks like it simply dumps to the console:
http://mxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/content/updates.js#72

I tested this earlier and a dump() in the test was also working. Not sure what might be the difference here.

Comment 3

[Andrei Eftimie]

This definitively regressed between mozmill 1.5.24.1 and mozmill 2.0

Working on narrowing this range down.

Comment 4

[Andrei Eftimie]

Narrowing this regression range will be much harder than initially thought.

Trying to make a testcase to ease this.
I see the NSIUpdateService logs the messages in 2 ways:
http://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/nsUpdateService.js#805-810
> function LOG(string) {
>  if (gLogEnabled) {
>    dump("*** AUS:SVC " + string + "\n");
>    Services.console.logStringMessage("AUS:SVC " + string);
>  }
>}

Henrik, do you know if we catch the dump or the logStringMessage output?

Comment 5

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

dump() is the method which logs to the console. The other one will end-up in the browser console only. When narrowing down keep in mind that you always have to run setup_development.py so that the mozbase packages are in sync.

Comment 6

[Andrei Eftimie]

The problem lies within mozmill-automation (or one of its dependencies).
Running the same tests directly via mozmill shows the log information correctly.

Comment 7

[Andrei Eftimie]

Actually that is not entirely true. I had _some_ messages shown when I ran it directly via mozmill, and I've also seen the same messages when I ran it via mozmill-automation right after.
And I can't reproduce that result anymore.

> testrun_update --repository=../mozmill-tests/ /c/Mozilla/Nightly/en-US/5/firefox/firefox.exe
> *** Creating backup of binary: c:\users\svuser\appdata\local\temp\tmp5onck_.workspace\binary_backup
> *** Application: Firefox 31.0a1 (c:\Mozilla\Nightly\en-US\5\firefox\firefox.exe)
> *** Platform: Win 6.2.9200 64bit
> *** Cloning test repository to 'c:\users\svuser\appdata\local\temp\tmp5onck_.workspace\mozmill-tests'
> *** Updating branch of test repository to 'default'
> *** Setting update channel to 'nightly'...
> *** Creating profile: c:\users\svuser\appdata\local\temp\tmp5onck_.workspace\profile
> TEST-START | test1.js | setupModule
> TEST-START | test1.js | teardownModule
> TEST-END | test1.js | finished in 5123ms
> *** AUS:SVC Downloader:onStopRequest - original URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/05/2014-05-11-03-02-03-mozilla-central/firefox-32.0a1.en-US.win32.complete.mar, final URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/05/2014-05-11-03-02-03-mozilla-central/firefox-32.0a1.en-US.win32.complete.mar, status: 2147500036
> *** AUS:SVC Downloader:onStopRequest - status: 2147500036, current fail: 0, max fail: 10, retryTimeout: 2000
> *** AUS:SVC Downloader:onStopRequest - setting state to: downloading
> TEST-START | test2.js | setupModule
> TEST-START | test2.js | testDirectUpdate_Download
> ERROR | Test Failure | {
>   "exception": {
>     "message": "An update has been found.",
>     "lineNumber": 27,
>     "name": "TimeoutError",
>     "fileName": "resource://mozmill/modules/errors.js"
>   }
> }
> TEST-UNEXPECTED-FAIL | test2.js | testDirectUpdate_Download

Comment 8

[Andrei Eftimie]

I'm close here. But I've gotten some inconsistent results during the last steps (probably due to either update caching and/or polluted environments).

The regression started somewhere around Setp/Oct 2012, probably one of the commits near the bottom-middle of this page https://github.com/mozilla/mozmill/commits/master?page=5

I'll need to run a few more tests to confirm anything...

Comment 9

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

There are some console logger changes, which might be responsible for that. Probably that output gets eaten and not delivered to the console.

Comment 10

[Andrei Eftimie]

To confirm yesterday's results.

Regressor is bug 793764:
https://github.com/mozilla/mozmill/commit/1558c2b7b8d982b2b9abc753545d8f4eaf501318

I'm not sure how this is behaving, but I can reproduce the results (with the old mozmill build)
I can't (at the moment) replicate these results on master. This particular line does not exist anymore. I'll track its history.

Comment 11

[Andrei Eftimie]

The line itself has been changed in bug 897957
https://github.com/mozilla/mozmill/commit/4f3379740703b8f345dd0117133626526b03c776

Comment 12

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

This might be a red herring. I cannot see how that change could have caused this behavior. It's absolutely not related to any kind of logger instance.

Would you mind to run Mozmill with different --console-level settings? Does that change something?

Comment 13

[Andrei Eftimie]

--console-level did not help.
Since going backwards didn't help, I tried reproducing the problem.

Tried to see if dump chokes on Unicode characters, or on long messages. Dump was solid.
Played with the update tests itself and managed to approximately locate the problem.

Working on a minimized testcase.

Comment 14

[Andrei Eftimie]

Attachment: testcase.js

controller.restartApplication() breaks `dump` on Windows

> $ mozmill -t ../testcase/testcase.js -b /c/Mozilla/Nightly/en-US/firefox-31.0a1.en-US.win32/firefox/firefox.exe
> TEST-START | c:\work\bugs\1008135\testcase\testcase.js | test1
> TEST-PASS | c:\work\bugs\1008135\testcase\testcase.js | test1
> TEST-END | c:\work\bugs\1008135\testcase\testcase.js | finished in 2ms
> 
> test1
> TEST-START | c:\work\bugs\1008135\testcase\testcase.js | test2
> TEST-PASS | c:\work\bugs\1008135\testcase\testcase.js | test2
> TEST-END | c:\work\bugs\1008135\testcase\testcase.js | finished in 1ms
> RESULTS | Passed: 2
> RESULTS | Failed: 0
> RESULTS | Skipped: 0

Comment 15

[Andrei Eftimie]

As a workaround, I'm not sure why we need to have a restart between test1 and test2. 
If we remove the call to restartApplication in test1 > teardownModule we have all our logs back.

Comment 16

[Andrei Eftimie]

Attachment: 1.patch

We'll have update logs again with this patch.

Tests are passing as seen: http://mozmill-crowd.blargon7.com/#/update/report/7a69d3e8424ecf8642bb6566e496c174
http://mozmill-crowd.blargon7.com/#/update/report/7a69d3e8424ecf8642bb6566e4970525

I'll file a bug for the restart vs dump issue. Not yet sure in which component it should go.

Comment 17

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

Comment on attachment 8426174 [details] [diff] [review]
1.patch

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

I don't understand what you are doing here. So to turn on application update logging, you will have to restart the browser. Otherwise logs will not be printed to the console. Removing the restart in test1.js doesn't make sense to me. Also if a restart would trigger that, we also have restarts in test2.js and test3.js. So later dumps would also be discarded.

If that bug continues to be a mozmill-test bug, you should really move it to the right component.

Comment 18

[Andrei Eftimie]

(In reply to Henrik Skupin (:whimboo) from comment #17)
> I don't understand what you are doing here. So to turn on application update
> logging, you will have to restart the browser. Otherwise logs will not be
> printed to the console. 

Are you sure this is the case?
Without a restart between test1 and test2 I had _all_ logs in the console. Maybe `app.update.log` does not need a restart anymore? If this is indeed the case we might get rid of the first test and set up everything in setupModule before starting the update.

> Removing the restart in test1.js doesn't make sense
> to me. Also if a restart would trigger that, we also have restarts in
> test2.js and test3.js. So later dumps would also be discarded.

Correct, but we are interested in the update log and that is generated in test2, so we do get the log we want. As stated this patch is a workaround if we want logs _now_.

> If that bug continues to be a mozmill-test bug, you should really move it to
> the right component.

I'll have more tests done and will probably report in bug 1013938

Comment 19

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

(In reply to Andrei Eftimie from comment #18)
> Are you sure this is the case?
> Without a restart between test1 and test2 I had _all_ logs in the console.
> Maybe `app.update.log` does not need a restart anymore? If this is indeed
> the case we might get rid of the first test and set up everything in
> setupModule before starting the update.

It might be that this has been changed. Best would be to test it out wo/ using Mozmill, and a fresh profile. Not sure if this goes back to 24esr. But if we can get rid off it, that would be nice! It saves us a couple of seconds too.

> > Removing the restart in test1.js doesn't make sense
> > to me. Also if a restart would trigger that, we also have restarts in
> > test2.js and test3.js. So later dumps would also be discarded.
> 
> Correct, but we are interested in the update log and that is generated in
> test2, so we do get the log we want. As stated this patch is a workaround if
> we want logs _now_.

Keep in mind that we also have the fallback updates. The necessary logs are not only from test2.js but also test3.js.

Comment 20

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

This is also an issue with the Firefox UI Tests. So to keep the information I will move this bug over into the new component.

Comment 21

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

We would have to do some investigation for Marionette to get an idea what's up. Please also see bug 1013938 for more information.

Comment 22

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

Logging works: https://treeherder.mozilla.org/logviewer.html#?job_id=2647378&repo=mozilla-aurora#L819
Logging missing: https://treeherder.mozilla.org/logviewer.html#?job_id=2644629&repo=mozilla-aurora#L775

Not sure what exactly is going on here, but I can clearly see the AUS logging for jobs which are failing. For those which pass we only have a single logging line or noting.

Given that we are only interested in that logging for failing jobs I wouldn't matter that much. :) I will keep an eye on it over the next days.

Comment 23

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

Robert, do you know if we have some weirdness around update logging on Windows? It works all fine on OS X and Linux with the logging preference set, but fails for Windows. As you can see by the bug number this is happening for a while now, but with all the recent failures on Windows it makes it hard for me to investigate them.

Comment 24

[Robert Strong (they/them - no direct email)]

This sounds like a test harness bug... update logging to the console just uses dump as you have noted and that is well outside of app update. Note: you haven't had to restart to turn on app update logging for quite a long time.

Comment 25

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

If it would be a harness bug then all platforms should be affected. But we clearly get AUS logging for OS X and Linux. Given that we have two failures for update tests those days (bug 1293404, bug 1285340) I would like to get this finally working for Windows. I will dive into this today.

Comment 26

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

Ok, so the problem seems to be related to how Firefox gets restarted from within the application. As it looks like we loose command line options (especially the one for logging to the console), and that's why the logging does not longer work after the first restart of Firefox. I can stop the behavior when not using in_app=True, but let the Marionette Python client force close and restart the application. In that case we correctly print out the logging lines to the console.

Here the code for the in_app restart feature of Marionette:

https://dxr.mozilla.org/mozilla-central/source/testing/marionette/client/marionette_driver/marionette.py#1036
https://hg.mozilla.org/mozilla-central/annotate/tip/testing/marionette/driver.js#l2568

So this is similar to what has been already seen for Mozmill in comment 14. Both harnesses use nsIStartup.quit() to restart the browser, and in both cases no dumped message is visible anymore after the first restart.

Comment 27

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

Attachment: Marionette testcase

Here a testcase for Marionette. It clearly prints the "GECKO DUMP" twice, but fails to do so the 3rd time.

Comment 28

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

I got this reproduced outside of Marionette. So this is clearly a bug in Firefox. We seem to really loose nearly every command line arguments with a restart from within Firefox.

Comment 29

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

Looks like this is basically bug 399317 which we seem to always hit here.

Comment 30

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

For now we won't implement this. It can be reopened when it becomes necessary again.