1173321 - Make sure a callback is invoked in the onerror case of GaiaDataLayer.getSetting

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: Gaia::UI Tests, defect)

Description

[Martijn Wargers (dead)]

Last failure from bug 1155815, comment 19 was a timeout failure in get_setting:
https://treeherder.mozilla.org/logviewer.html#?repo=b2g-inbound&job_id=2125498
01:25:36 INFO - TEST-START | test_gallery_handle_valid_image_file.py TestGalleryHandleValidPhoto.test_gallery_open_valid_image_file_load_progressive_jpg
01:26:14 ERROR - TEST-UNEXPECTED-ERROR | test_gallery_handle_valid_image_file.py TestGalleryHandleValidPhoto.test_gallery_open_valid_image_file_load_progressive_jpg | ScriptTimeoutException: ScriptTimeoutException: timed out
01:26:14 INFO - Traceback (most recent call last):
01:26:14 INFO - File "/home/worker/build/venv/local/lib/python2.7/site-packages/marionette/marionette_test.py", line 277, in run
01:26:14 INFO - self.setUp()
01:26:14 INFO - File "/home/worker/gaia/tests/python/gaia-ui-tests/gaiatest/gaia_test.py", line 906, in setUp
01:26:14 INFO - self.cleanup_gaia(full_reset=False)
01:26:14 INFO - File "/home/worker/gaia/tests/python/gaia-ui-tests/gaiatest/gaia_test.py", line 968, in cleanup_gaia
01:26:14 INFO - if self.data_layer.get_setting('lockscreen.enabled'):
01:26:14 INFO - File "/home/worker/gaia/tests/python/gaia-ui-tests/gaiatest/gaia_test.py", line 259, in get_setting
01:26:14 INFO - 'return GaiaDataLayer.getSetting("%s")' % name)
01:26:14 INFO - File "/home/worker/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1510, in execute_async_script
01:26:14 INFO - debug_script=debug_script)
01:26:14 INFO - File "/home/worker/build/venv/local/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
01:26:14 INFO - return func(*args, **kwargs)
01:26:14 INFO - File "/home/worker/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 711, in _send_message
01:26:14 INFO - self._handle_error(response)
01:26:14 INFO - File "/home/worker/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 747, in _handle_error
01:26:14 INFO - raise errors.lookup(status)(message, stacktrace=stacktrace)
01:26:14 INFO - TEST-INFO took 33835ms 

I think the getSetting in data_layer.js was getting an error somehow and the onerror handler doesn't have a callback(result), which causes then would cause the timeout failure:
http://mxr.mozilla.org/gaia/source/tests/atoms/gaia_data_layer.js#219

I think it would be good if the onerror handler would have callback function.

Comment 1

[Martijn Wargers (dead)]

Attachment: https://github.com/mozilla-b2g/gaia/pull/30518

Dave, something like this?

Comment 2

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Comment on attachment 8617887 [details] [review]
https://github.com/mozilla-b2g/gaia/pull/30518

Comment added to pull request.

Comment 3

[Martijn Wargers (dead)]

For Jenkins runs, a catlog.txt is stored, where you could see the console.log() message.

For taskcluster results, it should be the gecko.log file, but for this failure I couldn't find the console.log() instance, see bug 1155815, comment 22.

Dave mentioned that as an alternative, I could perhaps throw a js error exception there.

Comment 4

[Martijn Wargers (dead)]

Dave, do you know why I can't find the console.log() instance in the gecko.log file for the test_gallery_handle_valid_image_file.py unexpected error? 
https://s3-us-west-2.amazonaws.com/taskcluster-public-artifacts/Jp44YvMCSnmiYIL-wwCcfA/0/public/logs/live_backing.log
This corresponds to this gecko log: https://s3-us-west-2.amazonaws.com/taskcluster-public-artifacts/Jp44YvMCSnmiYIL-wwCcfA/0/public/test_info//gecko-1433899321.log

I would have expected here to hit the req.onerror case, because that one doesn't return marionetteScriptFinished, which then makes the test timeout, but the we would get the "console.log('error getting setting ' + req.error.name);" message.

Comment 5

[Dave Hunt [:davehunt] [he/him] ⌚BST]

(In reply to Martijn Wargers [:mwargers] (QA) from comment #4)
> Dave, do you know why I can't find the console.log() instance in the
> gecko.log file for the test_gallery_handle_valid_image_file.py unexpected
> error? 
> https://s3-us-west-2.amazonaws.com/taskcluster-public-artifacts/
> Jp44YvMCSnmiYIL-wwCcfA/0/public/logs/live_backing.log
> This corresponds to this gecko log:
> https://s3-us-west-2.amazonaws.com/taskcluster-public-artifacts/
> Jp44YvMCSnmiYIL-wwCcfA/0/public/test_info//gecko-1433899321.log
> 
> I would have expected here to hit the req.onerror case, because that one
> doesn't return marionetteScriptFinished, which then makes the test timeout,
> but the we would get the "console.log('error getting setting ' +
> req.error.name);" message.

Are you sure this is the correct gecko.log? The only test I can see referenced is test_privileged_app_device_picture_prompt.py:test_get_pictures_prompt, which is not in the console log. Perhaps there's an issue with the artifacts TaskCluster is gathering?

Comment 6

[Dave Hunt [:davehunt] [he/him] ⌚BST]

(In reply to Martijn Wargers [:mwargers] (QA) from comment #3)
> Dave mentioned that as an alternative, I could perhaps throw a js error
> exception there.

This is worth experimenting with as script execution will halt if an exception is thrown, and the trace should be displayed in the main console.

Comment 7

[Martijn Wargers (dead)]

(In reply to Dave Hunt (:davehunt) from comment #5)
> Are you sure this is the correct gecko.log? The only test I can see
> referenced is
> test_privileged_app_device_picture_prompt.py:test_get_pictures_prompt, which
> is not in the console log. Perhaps there's an issue with the artifacts
> TaskCluster is gathering?

This is what I did:
http://docs.taskcluster.net/tools/task-inspector/
Filled in as taskId: Jp44YvMCSnmiYIL-wwCcfA
Then I get all the logs related to that failure. I only see that 1 gecko.log and that's indeed only showing test_privileged_app_device_picture_prompt.py:test_get_pictures_prompt.
It should contain the logs of all the tests that were running.
James Lal, do you know why that happens?

Comment 8

[Martijn Wargers (dead)]

Chris, do you perhaps know the answer to comment 4?
I can't find the gecko log for test_gallery_handle_valid_image_file.py. It seems the gecko log stores only the last test in taskcluster or something.

Comment 9

[Chris Manchester (limited bugmail, email directly)]

I'm fairly sure this is a longstanding behavior where marionette loses the gecko log when restarting the gecko process. I fixed this for desktop recently in bug 1174766, I'm not sure offhand why that same fix didn't have the desired effect for Gaia tests.

Comment 10

[Chris Manchester (limited bugmail, email directly)]

(In reply to Chris Manchester [:chmanchester] from comment #9)
> I'm fairly sure this is a longstanding behavior where marionette loses the
> gecko log when restarting the gecko process. I fixed this for desktop
> recently in bug 1174766, I'm not sure offhand why that same fix didn't have
> the desired effect for Gaia tests.

I just tried this locally and with marionette driver 0.10 it's fixed (all gecko.log output is concatenated in a single file).

Comment 11

[Martijn Wargers (dead)]

Ok, thanks for your help! With the failure I mentioned in comment 0, I see that marionette-driver 0.8 is installed: https://s3-us-west-2.amazonaws.com/taskcluster-public-artifacts/Jp44YvMCSnmiYIL-wwCcfA/0/public/logs/live_backing.log
I guess the version number needs to be increased here then?
http://mxr.mozilla.org/mozilla-central/source/testing/marionette/client/requirements.txt#1
marionette-driver >= 0.8

Comment 12

[Martijn Wargers (dead)]

Attachment: 1173321.diff

So like this.

Comment 13

[Martijn Wargers (dead)]

Marking WONTFIX, sorry for the bug spam. If somebody still wants to work on this, please file a new bug for it.