1045072 - Update tests failure with "Execution of test-run aborted: client process shutdown unsuccessful"

Status: RESOLVED FIXED

(Mozilla QA Graveyard :: Mozmill Tests, defect, P2)

Description

[Andrei Eftimie]

The report itself is broken:
http://mozmill-daily.blargon7.com/#/update/report/3fc32167988fd0bfcd02892a7340fdf5

From the console log, this is the relevant part:
> [..]
> 04:50:20 *** AUS:SVC cleanUpMozUpdaterDirs - Cleaning MozUpdater folder
> 04:50:20 *** UTM:SVC TimerManager:registerTimer - id: browser-cleanup-thumbnails
> 04:52:20 *** UTM:SVC TimerManager:notify - notified timerID: browser-cleanup-thumbnails
> 04:54:20 *** AUS:SVC getLocale - getting locale from file: resource://gre/update.locale, locale: en-US
> 04:54:20 *** AUS:SVC Checker:getUpdateURL - update URL: https://aus4.mozilla.org/update/3/Firefox/34.0a1/20140728030201/Linux_x86_64-gcc3/en-US/nightly/Linux%203.2.0-58-generic%20(GTK%202.24.10)/default/default/update.xml
> 04:54:20 *** AUS:SVC Checker: checkForUpdates, force: false
> 04:54:20 *** AUS:SVC Checker:getUpdateURL - update URL: https://aus4.mozilla.org/update/3/Firefox/34.0a1/20140728030201/Linux_x86_64-gcc3/en-US/nightly/Linux%203.2.0-58-generic%20(GTK%202.24.10)/default/default/update.xml
> 04:54:20 *** UTM:SVC TimerManager:notify - notified @mozilla.org/updates/update-service;1
> 04:56:20 *** UTM:SVC TimerManager:notify - notified @mozilla.org/browser/search-service;1
> 04:56:27 RESULTS | Passed: 2
> 04:56:27 RESULTS | Failed: 2
> 04:56:27 RESULTS | Skipped: 0
> 04:56:27 Report document created at 'http://mozauto.iriscouch.com/mozmill-daily/3fc32167988fd0bfcd02892a7340fdf5'
> 04:56:27 *** Removing profile: /home/mozauto/jenkins/workspace/mozilla-central_update/data/profile
> 04:56:27 *** Execution of test-run aborted: client process shutdown unsuccessful
> 04:56:27 *** Removing updates staging folder: /home/mozauto/jenkins/workspace/mozilla-central_update/data/binary/firefox/updates/0
> 04:56:27 *** Uninstalling build: /home/mozauto/jenkins/workspace/mozilla-central_update/data/binary/firefox
> 04:56:27 *** Removing test repository '/home/mozauto/jenkins/workspace/mozilla-central_update/data/mozmill-tests'
> 04:56:27 Archiving artifacts
> 04:56:27 Recording test results
> 04:56:27 Build step 'Publish JUnit test result report' changed build result to UNSTABLE
> 04:56:27 IRC notifier plugin: Sending notification to: #automation
> 04:56:27 Email was triggered for: Unstable (Test Failures)
> 04:56:27 Sending email for trigger: Unstable (Test Failures)
> 04:56:27 Sending email to: [e-mail]
> 04:56:28 Finished: UNSTABLE

Compare with the same snippet from a testrun that PASSES:
> 07:49:41 *** AUS:SVC cleanUpMozUpdaterDirs - Cleaning MozUpdater folder
> 07:49:41 *** UTM:SVC TimerManager:registerTimer - id: browser-cleanup-thumbnails
> 07:49:45 TEST-START | test4.js | setupModule
> 07:49:45 TEST-START | test4.js | testFallbackUpdate_AppliedAndNoUpdatesFound
> 07:49:45 *** AUS:SVC Checker: checkForUpdates, force: true
> 07:49:45 *** AUS:SVC getLocale - getting locale from file: resource://gre/update.locale, locale: en-US
> 07:49:45 *** AUS:SVC Checker:getUpdateURL - update URL: https://aus4.mozilla.org/update/3/Firefox/34.0a1/20140728030201/Linux_x86_64-gcc3/en-US/nightly/Linux%203.2.0-58-generic%20(GTK%202.24.10)/default/default/update.xml?force=1
> 07:49:45 *** AUS:SVC recordInHealthReport - updateCheckStart - 0
> 07:49:45 *** AUS:SVC Checker:checkForUpdates - sending request to: https://aus4.mozilla.org/update/3/Firefox/34.0a1/20140728030201/Linux_x86_64-gcc3/en-US/nightly/Linux%203.2.0-58-generic%20(GTK%202.24.10)/default/default/update.xml?force=1
> 07:49:46 *** AUS:SVC Checker:onLoad - request completed downloading document
> 07:49:46 *** AUS:SVC Checker:onLoad - number of updates available: 0
> 07:49:46 *** AUS:SVC recordInHealthReport - updateCheckSuccess - 0
> 07:49:46 TEST-PASS | test4.js | testFallbackUpdate_AppliedAndNoUpdatesFound
> 07:49:46 TEST-START | test4.js | teardownModule
> 07:49:46 TEST-END | test4.js | finished in 474ms
> 07:49:46 RESULTS | Passed: 3
> 07:49:46 RESULTS | Failed: 0
> 07:49:46 RESULTS | Skipped: 0
> 07:49:47 Report document created at 'http://mozauto.iriscouch.com/mozmill-daily/3fc32167988fd0bfcd02892a734c133b'
> 07:49:47 *** Removing profile: /home/mozauto/jenkins/workspace/mozilla-central_update/data/profile
> 07:49:47 *** Removing updates staging folder: /home/mozauto/jenkins/workspace/mozilla-central_update/data/binary/firefox/updates/0
> 07:49:47 *** Uninstalling build: /home/mozauto/jenkins/workspace/mozilla-central_update/data/binary/firefox
> 07:49:47 *** Removing test repository '/home/mozauto/jenkins/workspace/mozilla-central_update/data/mozmill-tests'
> 07:49:47 Archiving artifacts
> 07:49:47 Recording test results
> 07:49:47 No emails were triggered.
> 07:49:47 Finished: SUCCESS

We have test4 missing completely. I wasn't able to reproduce it. Rebuilding these makes it PASS.

I see this being either:
- fallout from bug 972912, or
- something else, which affects update tests and we fail to properly reopen the browser window (or something)

Comment 1

[Daniel Gherasim]

This happened for 4 times today again.
Basically the 4th test from testFallbackUpdate was not run & the testrun was marked with UNSTABLE, even though the build was successfully updated.
Locally the testrun with the same parameters runs fine (on ubuntu 14.04 x86)

Status: 35 out of 164 testruns marked as UNSTABLE. All of them were on linux.
Started: After the channel was opened again on 26 July.

Actually almost all of our testruns on linux show UNSTABLE.

Comment 2

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

(In reply to Andrei Eftimie from comment #0)
> The report itself is broken:
> http://mozmill-daily.blargon7.com/#/update/report/
> 3fc32167988fd0bfcd02892a7340fdf5

You can check with a json viewer. You would have seen that it is the same issue as reported as https://github.com/mozilla/mozmill-dashboard/issues/116. We should get this fixed.

> We have test4 missing completely. I wasn't able to reproduce it. Rebuilding
> these makes it PASS.

Test3 and test4 caused an application disconnect. This must have been during startup, given that no additional info like the filename is available. I assume the underlying behavior here is bug 974971.

Comment 3

[Andreea Matei [:AndreeaMatei]]

Happened again several times this week, with aurora.
I'll retrigger those jobs and look for a pattern and investigate a bit.

Comment 4

[Andreea Matei [:AndreeaMatei]]

Compared to comment 0, when I retriggered these they failed. I watched a testrun and in test3.js I see the window for update behind the main window, then quickly the Restart button is orange (focused/clicked) and the restart happens. In test4.js I only see the main window opened, nothing else happens and that's it.

Comment 5

[Andrei Eftimie]

This exact thing happened with Nightly 34
(broken report http://mozmill-daily.blargon7.com/#/update/report/2f56cb3a3728c2c47cd1b44f770378da)

I think we've only seen this with Aurora until now.

Comment 7

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

I will work on a solution for bug 794020 soon. It might fix it with Mozmill 2.1.

Comment 8

[Liz Henry (:lizzard) (relman/hg->git project)]

This is still happening with Aurora so I thought I'd record it here: http://mm-ci-master.qa.scl3.mozilla.com:8080/job/mozilla-aurora_update/9770/console

Comment 9

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

That's strange. There are two failures mentioned but I cannot find any of those in the console log. Not sure if we missed to run test4, or what else happened. Also the report does not open:

http://mozmill-daily.blargon7.com/#/update/report/12a8568e34c97b929089c7a61fb18f84

Comment 10

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

So actually we experienced an application disconnect for test4.js. As it can be seen in the plain report the function name where the disconnect happened is "test4.js". This is strange because that is actually the filename. So something messed up here for application.restart().

As long as it doesn't happen that rarely - we haven't seen such an instance yet - we wont be able to do any action on it.

Comment 11

[Daniel Gherasim]

This didn't reproduce locally in 10 testruns with a build that failed on CI (linux 13.10). I tested on linux 14.04 with this command:

----
tar -xvf ~/work/builds/test_updates/*35*.tar.bz2 -C ~/work/builds/test_updates/ && testrun_update --repository=~/work/mozmill-tests/testing/mozmill-tests/ ~/work/builds/test_updates/firefox/firefox && rm -r ~/work/builds/test_updates/firefox/
---

Comment 12

[Andrei Eftimie]

This is still failing, almost on a daily basis. Hopefully the upcoming changes and release of mozmill 2.1 will either fix this issue, or improve it's reporting.

Another sample report:
http://mozmill-daily.blargon7.com/#/update/report/2f982f72826307fed840a3b11c98f9c0

Unfortunately we don't have a Top Failure list for update tests.

Comment 13

[Andrei Eftimie]

I've noticed something in the Jenkins reporting. This doesn't appear in the console log (we just miss the tests there). But Jenkins does have this reported in the job itself.

> Failed
> testFallbackUpdate.test4.test4.js (from firefox-update)

And compare it with a passed test:
> Passed
> testFallbackUpdate.test3.testFallbackUpdate_ErrorPatching (from firefox-update)

Seems it failed before it got to know the module name (hence it calls it by the filename).

With any luck the refactoring from bug 1071590 will fix this issue (or at least improve its reporting).

Comment 14

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

My patch on bug 1071590 will not fix the real underlying issue why Mozmill misses some tests, but it should fix this disconnect problem for sure. So we should no longer see this!

Any remaining work is part of bug 972912.

Comment 15

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

I want to add that whenever we miss testUpdate.js now, the whole direct or fallback test is not getting executed! I have seen it once the last days.