1152460 - Error: Unexpected node name, expected: updates, got: parsererror

Status: RESOLVED INVALID

(Testing :: Firefox UI Tests, defect)

Description

[Armen [:armenzg]]

We got one of the updates to fail:
*** AUS:SVC Checker:onLoad - request completed downloading document
*** AUS:SVC Checker:_updates get - unexpected node name!
*** AUS:SVC Checker:onLoad - there was a problem checking for updates. Exception: Error: Unexpected node name, expected: updates, got: parsererror
*** AUS:SVC Checker:onLoad - request.status: 503
*** AUS:SVC getStatusTextFromCode - transfer error: A frissítés XML-fájlja nem található. (404), default code: 404
*** AUS:SVC recordInHealthReport - updateCheckFailed - 1503

The code "unexpected node name" comes from here:
https://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/nsUpdateService.js#3545

STR (I only hit it once):
virtualenv --no-site-packages venv
pip install firefox-ui-tests==0.2 --find-links=http://pypi.pub.build.mozilla.org/pub --no-index
wget http://stage.mozilla.org/pub/mozilla.org//firefox/releases/38.0b1/linux-x86_64/hu/firefox-38.0b1.tar.bz2
mozinstall -d . firefox-38.0b1.tar.bz2
export DISPLAY=:2
time firefox-ui-update --binary firefox/firefox --update-direct-only --update-channel beta-localtest | tee run.txt

This is the update URL:
https://aus4.mozilla.org/update/3/Firefox/38.0/20150330154247/Linux_x86_64-gcc3/hu/beta-localtest/Linux%202.6.32-504.3.3.el6.x86_64%20(GTK%202.20.1)/default/default/update.xml?force=1

We get this message from 


Full log:
NOTE: Ignore the million "downloads" in the path for now.

Retrieving 'http://stage.mozilla.org/pub/mozilla.org//firefox/releases/38.0b1/linux-x86_64/hu/firefox-38.0b1.tar.bz2' from cache...
Running Marionnete tests.
/home/cltbld/temp/build-tools/release/updates/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/downloads/38.0/firefox/firefox
 0:00.00 LOG: MainThread INFO Creating a copy of the application at "/tmp/tmpVwTlXW.binary-update-tests".
 0:05.90 LOG: MainThread INFO starting httpd
 0:05.90 LOG: MainThread INFO running webserver on http://127.0.0.1:33273/
 0:05.90 LOG: MainThread mozversion INFO application_buildid: 20150330154247
 0:05.90 LOG: MainThread mozversion INFO application_changeset: 604367e1fa5e
 0:05.90 LOG: MainThread mozversion INFO application_display_name: Firefox
 0:05.90 LOG: MainThread mozversion INFO application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
 0:05.90 LOG: MainThread mozversion INFO application_name: Firefox
 0:05.90 LOG: MainThread mozversion INFO application_remotingname: firefox
 0:05.90 LOG: MainThread mozversion INFO application_repository: https://hg.mozilla.org/releases/mozilla-beta
 0:05.90 LOG: MainThread mozversion INFO application_vendor: Mozilla
 0:05.90 LOG: MainThread mozversion INFO application_version: 38.0
 0:05.90 LOG: MainThread mozversion INFO platform_buildid: 20150330154247
 0:05.90 LOG: MainThread mozversion INFO platform_changeset: 604367e1fa5e
 0:05.90 LOG: MainThread mozversion INFO platform_repository: https://hg.mozilla.org/releases/mozilla-beta
 0:05.90 LOG: MainThread mozversion INFO platform_version: 38.0
 0:05.90 SUITE_START: MainThread 1
 0:05.90 TEST_START: MainThread test_direct_update.py TestDirectUpdate.test_update
 6:08.39 LOG: MainThread WARNING Failed to gather test failure debug.
Traceback (most recent call last):

  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette/runner/base.py", line 554, in gather_debug
    rv['source'] = marionette.page_source

  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1095, in page_source
    response = self._send_message('getPageSource', 'value')

  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
    return func(*args, **kwargs)

  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 697, in _send_message
    "Connection timed out", status=errors.ErrorCodes.TIMEOUT)

 6:08.39 TEST_END: MainThread FAIL, expected PASS
Traceback (most recent call last):
  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette/marionette_test.py", line 296, in run
    testMethod()
  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/firefox_ui_tests/update/direct/test_direct_update.py", line 20, in test_update
    self.download_and_apply_available_update(force_fallback=False)
  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/firefox_ui_harness/testcases/update.py", line 149, in download_and_apply_available_update
    self.assertTrue(update_available)
AssertionError: False is not true

12:08.49 LOG: MainThread INFO Update test results: [{'patch': {'download_duration': None, 'channel': u'beta-localtest'}, 'fallback': False, 'build_pre': {'disabled_addons': None, 'mar_channels': set([u'firefox-mozilla-beta', u'firefox-mozilla-release']), 'user_agent': u'Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Firefox/38.0', 'version': u'38.0', 'buildid': u'20150330154247', 'locale': u'hu', 'url_aus': u'https://aus4.mozilla.org/update/3/Firefox/38.0/20150330154247/Linux_x86_64-gcc3/hu/beta-localtest/Linux%202.6.32-504.3.3.el6.x86_64%20(GTK%202.20.1)/default/default/update.xml?force=1', 'channel': u'beta-localtest'}, 'success': False, 'build_post': None}]
18:08.60 LOG: MainThread ERROR test_end for test_direct_update.py TestDirectUpdate.test_update logged while not in progress. Logged with data: {"status": "ERROR", "extra": {}, "expected": "PASS", "test": "test_direct_update.py TestDirectUpdate.test_update", "message": "MarionetteException: MarionetteException: Malformed packet, expected key 'error' to be a dict: {u'message': u'this.curBrowser is null', u'error': u\"error occurred while processing 'executeScript\"}\n\n", "stack": "Traceback (most recent call last):\n  File \"/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette/marionette_test.py\", line 326, in run\n    self.tearDown()\n  File \"/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/firefox_ui_tests/update/direct/test_direct_update.py\", line 17, in tearDown\n    UpdateTestCase.tearDown(self)\n  File \"/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/firefox_ui_harness/testcases/update.py\", line 232, in tearDown\n    FirefoxTestCase.tearDown(self)\n  File \"/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/firefox_ui_harness/testcase.py\", line 69, in tearDown\n    MarionetteTestCase.tearDown(self, *args, **kwargs)\n  File \"/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette/marionette_test.py\", line 650, in tearDown\n    (self.filepath.replace('\\\\', '\\\\\\\\'), self.methodName))\n  File \"/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/marionette.py\", line 1438, in execute_script\n    filename=os.path.basename(frame[0]))\n  File \"/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/decorators.py\", line 36, in _\n    return func(*args, **kwargs)\n  File \"/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/marionette.py\", line 716, in _send_message\n    self._handle_error(response)\n  File \"/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/marionette.py\", line 745, in _handle_error\n    \"Malformed packet, expected key 'error' to be a dict: %s\" % response)\n"}
18:08.60 LOG: MainThread INFO 
SUMMARY
-------
18:08.60 LOG: MainThread INFO passed: 0
18:08.60 LOG: MainThread INFO failed: 2
18:08.60 LOG: MainThread INFO todo: 0
18:08.60 LOG: MainThread INFO 
FAILED TESTS
-------
18:08.60 LOG: MainThread INFO test_direct_update.py test_direct_update.TestDirectUpdate.test_update
18:08.60 LOG: MainThread INFO test_direct_update.py test_direct_update.TestDirectUpdate.test_update
18:08.61 SUITE_END: MainThread 
Summary
=======

Ran 1 tests
Expected results: 0
Unexpected results: 1 (FAIL: 1)

gecko.log:
*** AUS:SVC getLocale - getting locale from file: resource://gre/update.locale, locale: hu
*** AUS:SVC Checker:getUpdateURL - update URL: https://aus4.mozilla.org/update/3/Firefox/38.0/20150330154247/Linux_x86_64-gcc3/hu/beta-localtest/Linux%202.6.32-504.3.3.el6.x86_64%20(GTK%202.20.1)/default/default/update.xml?force=1
*** AUS:SVC recordInHealthReport - updateCheckStart - 0
*** AUS:SVC Checker:checkForUpdates - sending request to: https://aus4.mozilla.org/update/3/Firefox/38.0/20150330154247/Linux_x86_64-gcc3/hu/beta-localtest/Linux%202.6.32-504.3.3.el6.x86_64%20(GTK%202.20.1)/default/default/update.xml?force=1
*** AUS:SVC Checker:onLoad - request completed downloading document
*** AUS:SVC Checker:_updates get - unexpected node name!
*** AUS:SVC Checker:onLoad - there was a problem checking for updates. Exception: Error: Unexpected node name, expected: updates, got: parsererror
*** AUS:SVC Checker:onLoad - request.status: 503
*** AUS:SVC getStatusTextFromCode - transfer error: A frissítés XML-fájlja nem található. (404), default code: 404
*** AUS:SVC recordInHealthReport - updateCheckFailed - 1503
*** UTM:SVC TimerManager:notify - notified timerID: browser-cleanup-thumbnails
*** UTM:SVC TimerManager:notify - notified @mozilla.org/browser/search-service;1
*** AUS:SVC Checker:getUpdateURL - update URL: https://aus4.mozilla.org/update/3/Firefox/38.0/20150330154247/Linux_x86_64-gcc3/hu/beta-localtest/Linux%202.6.32-504.3.3.el6.x86_64%20(GTK%202.20.1)/default/default/update.xml
*** AUS:SVC Checker: checkForUpdates, force: false
*** AUS:SVC Checker:getUpdateURL - update URL: https://aus4.mozilla.org/update/3/Firefox/38.0/20150330154247/Linux_x86_64-gcc3/hu/beta-localtest/Linux%202.6.32-504.3.3.el6.x86_64%20(GTK%202.20.1)/default/default/update.xml

Comment 1

[Armen [:armenzg]]

bhearsum: could you please have a look at this gecko.log output?
I believe we got a 503 when trying to download the update from stage/ftp.

*** AUS:SVC Checker:onLoad - request completed downloading document
*** AUS:SVC Checker:_updates get - unexpected node name!
*** AUS:SVC Checker:onLoad - there was a problem checking for updates. Exception: Error: Unexpected node name, expected: updates, got: parsererror
*** AUS:SVC Checker:onLoad - request.status: 503
*** AUS:SVC getStatusTextFromCode - transfer error: A frissítés XML-fájlja nem található. (404), default code: 404
*** AUS:SVC recordInHealthReport - updateCheckFailed - 1503

STR (it only happened once)
virtualenv --no-site-packages venv
source venv/bin/activate
pip install firefox-ui-tests==0.2 --find-links=http://pypi.pub.build.mozilla.org/pub --no-index
wget http://stage.mozilla.org/pub/mozilla.org//firefox/releases/38.0b1/linux-x86_64/hu/firefox-38.0b1.tar.bz2
mozinstall -d . firefox-38.0b1.tar.bz2
export DISPLAY=:2
time firefox-ui-update --binary firefox/firefox --update-channel beta-localtest

Comment 2

[Armen [:armenzg]]

Attachment: handle the AssertionError

chmanchester: how can we make firefox-ui-updates retry few times? That would be in case aus is not available at the moment.

chmanchester: I also attached a patch that makes us fail faster (instead of waiting 5 minutes).

You can test this patch by:
wget https://ftp.mozilla.org/pub/mozilla.org/firefox/candidates/38.0b2-candidates/build1/linux-x86_64/en-US/firefox-38.0b2.tar.bz2
mozinstall -d . firefox-38.0b2.tar.bz2
./venv/bin/firefox-ui-update --binary firefox/firefox --update-direct-only

I don't know how to handle this exception:
    "Connection timed out", status=errors.ErrorCodes.TIMEOUT)

With regards to the Marionette exception.
We probably need to wrap the key 'error' to inside of a dict. See output below. [1]

What I think it happened in here is that aus was temporarily unavailable, hence, failing to have an update.
From the gecko output, I think we received <parsererror/> since there was an empty XML:
https://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/tests/unit_aus_update/remoteUpdateXML.js#229

###
[1]
{'expected': 'PASS',
 'extra': {},
 'message': 'MarionetteException: MarionetteException: Malformed packet, expected key \'error\' to be a dict: {u\'message\': u\'this.curBrowser is null\', u\'error\': u"error occurred while processing \'executeScript"}\n\n',
 'stack': (SEE OUTPUT BELOW)
 'status': 'ERROR',
 'test': 'test_direct_update.py TestDirectUpdate.test_update'}

Pprint of 'stack'
#################
['Traceback (most recent call last):',
 '  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette/marionette_test.py", line 326, in run',
 '    self.tearDown()',
 '  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/firefox_ui_tests/update/direct/test_direct_update.py", line 17, in tearDown',
 '    UpdateTestCase.tearDown(self)',
 '  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/firefox_ui_harness/testcases/update.py", line 232, in tearDown',
 '    FirefoxTestCase.tearDown(self)',
 '  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/firefox_ui_harness/testcase.py", line 69, in tearDown',
 '    MarionetteTestCase.tearDown(self, *args, **kwargs)',
 '  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette/marionette_test.py", line 650, in tearDown',
 "    (self.filepath.replace('\\\\', '\\\\\\\\'), self.methodName))",
 '  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1438, in execute_script',
 '    filename=os.path.basename(frame[0]))',
 '  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _',
 '    return func(*args, **kwargs)',
 '  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 716, in _send_message',
 '    self._handle_error(response)',
 '  File "/home/cltbld/temp/build-tools/release/updates/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 745, in _handle_error',
 '    "Malformed packet, expected key \'error\' to be a dict: %s" % response)',
 '']

Comment 3

[Armen [:armenzg]]

Attachment: failed to apply

In this attachement we can see another update failure.
It's unclear to me why.
It seems that we failed the direct update test somewhere between "able to apply updates" and actually applying it.

It seems that we managed to download the partial update [1]
* setting state to: pending
* status: applied
* Notifying observers that the update was staged
* able to apply updates
and then out of nowhere:
* status: failed: 6, path: /tmp/tmpC6UoQw.binary-update-tests/updates/0/update.status

On another note, in this first test, we fail to use the partial update and immediately go for the complete update.
However, for the second test, it seems that we resume the partially complete update from the previous test (see "resuming download" message):
 *** AUS:SVC Downloader:onProgress - progress: 12375/45992037
 *** AUS:UI gUpdates:onLoad - setting current page to startpage errorpatching
 *** AUS:SVC Downloader: cancel
 *** AUS:SVC Downloader: cancel
 *** AUS:SVC Creating Downloader
 *** AUS:SVC UpdateService:_downloadUpdate
 *** AUS:SVC readStatusFile - status: downloading, path: /tmp/tmpC6UoQw.binary-update-tests/updates/0/update.status
 *** AUS:SVC Downloader:_selectPatch - found existing patch with state: downloading
 *** AUS:SVC Downloader:_selectPatch - resuming download

Should we stop running the second test if the first fails?
Could we start from a clean state for the second test?


 *** AUS:SVC Downloader:onStopRequest - original URI spec: http://stage.mozilla.org/pub/mozilla.org/firefox/candidates/38.0b2-candidates/build1/update/linux-x86_64/af/firefox-38.0b1-38.0b2.partial.mar, final URI spec: http://stage.mozilla.org/pub/mozilla.org/firefox/candidates/38.0b2-candidates/build1/update/linux-x86_64/af/firefox-38.0b1-38.0b2.partial.mar, status: 0
 *** AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
 *** AUS:SVC recordInHealthReport - partialUpdateSuccess - 0
 *** AUS:SVC Downloader:_verifyDownload called
 *** AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
 *** AUS:SVC Downloader:_verifyDownload hashes match.
 *** AUS:SVC Downloader:onStopRequest - setting state to: pending
 *** AUS:SVC canStageUpdatesSession - testing write access /tmp/tmpC6UoQw.binary-update-tests/update.test
 *** AUS:SVC canStageUpdatesSession - testing write access /tmp/update.test
 *** AUS:SVC canStageUpdatesSession - able to stage updates
 *** AUS:SVC Downloader:onStopRequest - attempting to stage update: Firefox 38.0 Beta 2
 *** AUS:SVC readStatusFile - status: applied, path: /tmp/tmpC6UoQw.binary-update-tests/updates/0/update.status
 *** AUS:SVC UpdateManager:refreshUpdateStatus - Notifying observers that the update was staged. state: applied, status: applied
 *** AUS:SVC Creating UpdateService
 *** AUS:SVC gCanCheckForUpdates - able to check for updates
 *** AUS:SVC gCanApplyUpdates - testing write access /tmp/tmpC6UoQw.binary-update-tests/update.test
 *** AUS:SVC gCanApplyUpdates - able to apply updates
 *** AUS:SVC readStatusFile - status: failed: 6, path: /tmp/tmpC6UoQw.binary-update-tests/updates/0/update.status
 *** AUS:SVC readStatusFile - status: failed: 6, path: /tmp/tmpC6UoQw.binary-update-tests/updates/0/update.status
 *** AUS:SVC handleFallbackToCompleteUpdate - install of partial patch failed, downloading complete patch
 *** AUS:SVC Creating Downloader
 *** AUS:SVC UpdateService:_downloadUpdate
 *** AUS:SVC readStringFromFile - file doesn't exist: /tmp/tmpC6UoQw.binary-update-tests/updates/0/update.status
 *** AUS:SVC readStatusFile - status: null, path: /tmp/tmpC6UoQw.binary-update-tests/updates/0/update.status
 *** AUS:SVC Downloader:_selectPatch - found existing patch with state: null

Comment 4

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8590302 [details] [diff] [review]
handle the AssertionError

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

::: firefox_ui_tests/update/direct/test_direct_update.py
@@ +21,5 @@
> +            self.download_and_apply_available_update(force_fallback=False)
> +            self.check_update_applied()
> +        except AssertionError, e:
> +            self.tearDown()
> +            raise e

Have we seen this improving things? My understanding is that tearDown will always be run by the unittest library in case of a test failure/AssertionError, which will be very close to this behavior.

Comment 5

[Chris Manchester (limited bugmail, email directly)]

Regarding comment 3, "gecko.log" gets wiped out when we restart the browser, so the logs there might be somewhat misleading. Passing "--gecko-log -" to the runner will cause that output to go to stdout along with the test results, which may be helpful at least in the short term for debugging some of this.

Comment 6

[Armen [:armenzg]]

I will use the gecko.log trick.

(In reply to Chris Manchester [:chmanchester] from comment #4)
> ::: firefox_ui_tests/update/direct/test_direct_update.py
> @@ +21,5 @@
> > +            self.download_and_apply_available_update(force_fallback=False)
> > +            self.check_update_applied()
> > +        except AssertionError, e:
> > +            self.tearDown()
> > +            raise e
> 
> Have we seen this improving things? My understanding is that tearDown will
> always be run by the unittest library in case of a test
> failure/AssertionError, which will be very close to this behavior.

My expectations are the same as yours, however, I can actually see the difference with and without the patch.
In one we wait for 5/6 minutes and for the other one we fail fast.

These are the steps I used:
wget https://ftp.mozilla.org/pub/mozilla.org/firefox/candidates/38.0b2-candidates/build1/linux-x86_64/en-US/firefox-38.0b2.tar.bz2
mozinstall -d . firefox-38.0b2.tar.bz2
./venv/bin/firefox-ui-update --binary firefox/firefox --update-direct-only

Comment 7

[Chris Manchester (limited bugmail, email directly)]

Ok, I tried this locally and this indicates we're failing in tearDown (but succeeding as a side effect of tearDown if we call it twice). I should have thought of this before, but tearDown is attempting to do something in content scope when we're in a window (the about window) that has no content listener, so we hang. I believe bug 1141519 is meant to address this issue.

Comment 8

[Chris Manchester (limited bugmail, email directly)]

(In reply to Chris Manchester [:chmanchester] from comment #7)
> Ok, I tried this locally and this indicates we're failing in tearDown (but
> succeeding as a side effect of tearDown if we call it twice). I should have
> thought of this before, but tearDown is attempting to do something in
> content scope when we're in a window (the about window) that has no content
> listener, so we hang. I believe bug 1141519 is meant to address this issue.

More precisely, this problem arises in some code run by the marionette harness between the test failure and tearDown (some callbacks are invoked that attempt to take a screenshot and get the source of the current web page). There's actually a passage in the update tests' own tearDown message that would prevent this problem by switching back to the main browser window, but we're too late by that point.

Comment 9

[Armen [:armenzg]]

Let's keep this bug for this issue:
> Error: Unexpected node name, expected: updates, got: parsererror

If I see this issue again I will file it seperately:
> AUS:SVC readStatusFile - status: failed: 6, path: /tmp/tmpC6UoQw.binary-update-tests/updates/0/update.status

Comment 10

[Armen [:armenzg]]

I am thinking that I could try closing and opening the about window a number of times until AUS returns the right value.
I would also like to take a screenshot to see what could be happening.

Comment 11

[Chris Manchester (limited bugmail, email directly)]

(In reply to Armen Zambrano G. (:armenzg - Toronto) from comment #10)
> I am thinking that I could try closing and opening the about window a number
> of times until AUS returns the right value.
> I would also like to take a screenshot to see what could be happening.

Bug 1141519 is the issue here, I'm fairly sure. I don't know the status of that bug but if it doesn't seem like it's landing anytime soon we can think up a workaround.

Comment 12

[[e-mail] (:bhearsum)]

Any 503s you got are probably caused by https://bugzilla.mozilla.org/show_bug.cgi?id=1126825.

Comment 13

[Armen [:armenzg]]

(In reply to Chris Manchester [:chmanchester] from comment #11)
> (In reply to Armen Zambrano G. (:armenzg - Toronto) from comment #10)
> > I am thinking that I could try closing and opening the about window a number
> > of times until AUS returns the right value.
> > I would also like to take a screenshot to see what could be happening.
> 
> Bug 1141519 is the issue here, I'm fairly sure. I don't know the status of
> that bug but if it doesn't seem like it's landing anytime soon we can think
> up a workaround.

chmanchester: I believe we should take a screenshot in cases like this to help debug situations like this; what do you think?

Comment 14

[Chris Manchester (limited bugmail, email directly)]

(In reply to Armen Zambrano G. (:armenzg - Toronto) from comment #13)
> (In reply to Chris Manchester [:chmanchester] from comment #11)
> > (In reply to Armen Zambrano G. (:armenzg - Toronto) from comment #10)
> > > I am thinking that I could try closing and opening the about window a number
> > > of times until AUS returns the right value.
> > > I would also like to take a screenshot to see what could be happening.
> > 
> > Bug 1141519 is the issue here, I'm fairly sure. I don't know the status of
> > that bug but if it doesn't seem like it's landing anytime soon we can think
> > up a workaround.
> 
> chmanchester: I believe we should take a screenshot in cases like this to
> help debug situations like this; what do you think?

The code that triggers this bug is itself attempting to take a screenshot and get the source of the currently displayed web page. Once it's fixed we can pass "--log-html <path>" to the runner which will generate an html report that includes screenshots.

Comment 15

[Armen [:armenzg]]

chmanchester: I looked at your last comments and my intention on this bug is to focus to the case when AUS is sporadically not available, hence, not giving an update to Firefox. See [1]

bhearsum: I see that update verify in general fails a lot and needs inspection. What should we do in here? Should we simply make firefox-ui-updates say that we could not determine the updates from AUS? Try few times?

Currently we raise an "AssertionError: False is not true"

[1]
> *** AUS:SVC Checker:onLoad - request completed downloading document
> *** AUS:SVC Checker:_updates get - unexpected node name!
> *** AUS:SVC Checker:onLoad - there was a problem checking for updates. Exception: Error: Unexpected node name, expected: updates, got: parsererror
> *** AUS:SVC Checker:onLoad - request.status: 503

Comment 16

[[e-mail] (:bhearsum)]

I'm not entirely certain what this bug is about, but here's specific comments to your questions.

(In reply to Armen Zambrano G. (:armenzg - Toronto) from comment #15)
> chmanchester: I looked at your last comments and my intention on this bug is
> to focus to the case when AUS is sporadically not available, hence, not
> giving an update to Firefox. See [1]
> 
> bhearsum: I see that update verify in general fails a lot and needs
> inspection.

I'm not sure what you mean by this. We sometimes hit issues where update verify overwhelms AUS with requests, but in general update verify should be passing. If you're seeing a large amount of intermittent issues that retrying doesn't solve, there may be a larger issue at hand.

> What should we do in here? Should we simply make
> firefox-ui-updates say that we could not determine the updates from AUS? Try
> few times?
> 
> Currently we raise an "AssertionError: False is not true"

That is not a very helpful error message. In order to set the status os "FAILED" you'll need to make sure "FAIL" is in the output somewhere. The output from the update attempt (eg, the "AUS:SVC" messages) are really good to have too. It's almost impossible to debug failures without them.

Comment 17

[Armen [:armenzg]]

(In reply to Ben Hearsum [:bhearsum] from comment #16)
> I'm not entirely certain what this bug is about, but here's specific
> comments to your questions.
> 
> (In reply to Armen Zambrano G. (:armenzg - Toronto) from comment #15)
> > chmanchester: I looked at your last comments and my intention on this bug is
> > to focus to the case when AUS is sporadically not available, hence, not
> > giving an update to Firefox. See [1]
> > 
> > bhearsum: I see that update verify in general fails a lot and needs
> > inspection.
> 
> I'm not sure what you mean by this. We sometimes hit issues where update
> verify overwhelms AUS with requests, but in general update verify should be
> passing. If you're seeing a large amount of intermittent issues that
> retrying doesn't solve, there may be a larger issue at hand.
> 
I believe we could add rety logic to "check for updates" few times.

> > What should we do in here? Should we simply make
> > firefox-ui-updates say that we could not determine the updates from AUS? Try
> > few times?
> > 
> > Currently we raise an "AssertionError: False is not true"
> 
> That is not a very helpful error message. In order to set the status os
> "FAILED" you'll need to make sure "FAIL" is in the output somewhere. The
> output from the update attempt (eg, the "AUS:SVC" messages) are really good
> to have too. It's almost impossible to debug failures without them.

We always attach the gecko.log which contains the AUS values and I add "FAIL" to the output after firefox-ui-updates runs and returns a return code different than zero.

firefox-ui-updates raises that AssertionError but it doesn't know why there was no update. Inspecting the AUS messages can help us understand why there is no update available.

Comment 18

[Armen [:armenzg]]

I thought more about this and if AUS starts misbehaving more than this will start failing and many locales would fail.
The only thing to make sense in here if we believe is necessary is to improve the output.