Closed Bug 1008135 Opened 6 years ago Closed 2 years ago

Application update logs are not printed to the console

Categories

(Testing :: Firefox UI Tests, defect)

All
Windows
defect
Not set

Tracking

(Not tracked)

RESOLVED WONTFIX

People

(Reporter: whimboo, Unassigned)

References

(Depends on 1 open bug)

Details

Attachments

(1 file, 2 obsolete files)

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.
Flags: needinfo?(andrei.eftimie)
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?
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.
Summary: With Mozmill 2.0 application update logs are no longer print to the console → With Mozmill 2.0 application update logs are no longer printed to the console
This definitively regressed between mozmill 1.5.24.1 and mozmill 2.0

Working on narrowing this range down.
Flags: needinfo?(andrei.eftimie)
Flags: needinfo?(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?
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.
The problem lies within mozmill-automation (or one of its dependencies).
Running the same tests directly via mozmill shows the log information correctly.
Flags: needinfo?(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
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...
There are some console logger changes, which might be responsible for that. Probably that output gets eaten and not delivered to the console.
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.
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?
Blocks: 797898
--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.
Assignee: nobody → andrei.eftimie
Status: NEW → ASSIGNED
Attached file testcase.js (obsolete) —
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
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.
Attached patch 1.patch (obsolete) — Splinter Review
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.
Attachment #8426174 - Flags: review?
Attachment #8426174 - Flags: review?(hskupin)
Attachment #8426174 - Flags: review?(andreea.matei)
Attachment #8426174 - Flags: review?
Depends on: 1013938
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.
Attachment #8426174 - Flags: review?(hskupin)
Attachment #8426174 - Flags: review?(andreea.matei)
Attachment #8426174 - Flags: review-
(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
Component: Mozmill → Mozmill Tests
Product: Testing → Mozilla QA
Summary: With Mozmill 2.0 application update logs are no longer printed to the console → Application update logs are not printed to the console
(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.
Whiteboard: [mozmill-2.1?]
Assignee: andrei → nobody
Status: ASSIGNED → NEW
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.
Component: Mozmill Tests → Firefox UI Tests
OS: Windows 8 → Windows
We would have to do some investigation for Marionette to get an idea what's up. Please also see bug 1013938 for more information.
No longer blocks: 797898
No longer depends on: 1013938
Product: Mozilla QA → Testing
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.
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.
Flags: needinfo?(robert.strong.bugs)
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.
Flags: needinfo?(robert.strong.bugs)
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.
Assignee: nobody → hskupin
Blocks: 1285340
Status: NEW → ASSIGNED
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.
Attachment #8426153 - Attachment is obsolete: true
Attachment #8426174 - Attachment is obsolete: true
Attached file Marionette testcase
Here a testcase for Marionette. It clearly prints the "GECKO DUMP" twice, but fails to do so the 3rd time.
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.
Looks like this is basically bug 399317 which we seem to always hit here.
Depends on: 399317
Assignee: hskupin → nobody
Status: ASSIGNED → NEW
Depends on: 1299601
For now we won't implement this. It can be reopened when it becomes necessary again.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.