Closed Bug 1150573 Opened 5 years ago Closed 5 years ago

test_play_3gp_video.py: "JavascriptException: JavascriptException: unload was called" x3 tests { 3gp, ogg, ogv }

Categories

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

ARM
Gonk (Firefox OS)
defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: onelson, Assigned: martijn.martijn)

References

()

Details

Attachments

(2 files)

Description:
http://jenkins1.qa.scl3.mozilla.com/view/UI/job/flame-kk.ui.adhoc/lastCompletedBuild/testReport/

Videoplayer encountered issues in the following tests:
test_play_3gp_video -- 1/5 pass
test_play_ogg_video -- 3/5 pass 
test_play_ogv_video -- 2/5 pass

When the phone attempts to perform video related tests, the tests stop and produce a screenshot either loading the videos or from the list of available videos.

Traceback (most recent call last):
  File "/var/jenkins/1/workspace/flame-kk.ui.adhoc/.env/local/lib/python2.7/site-packages/marionette_client-0.9-py2.7.egg/marionette/marionette_test.py", line 290, in run
    testMethod()
  File "/var/jenkins/1/workspace/flame-kk.ui.adhoc/tests/python/gaia-ui-tests/gaiatest/tests/functional/videoplayer/test_play_ogg_video.py", line 23, in test_play_ogg_video
    video_player.wait_for_thumbnails_to_load(1, 'Video files found on device: %s' %self.data_layer.video_files)
  File "/var/jenkins/1/workspace/flame-kk.ui.adhoc/tests/python/gaia-ui-tests/gaiatest/gaia_test.py", line 416, in video_files
    'return GaiaDataLayer.getAllVideos();')
  File "/var/jenkins/1/workspace/flame-kk.ui.adhoc/.env/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 1420, in execute_async_script
    debug_script=debug_script)
  File "/var/jenkins/1/workspace/flame-kk.ui.adhoc/.env/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/decorators.py", line 36, in _
    return func(*args, **kwargs)
  File "/var/jenkins/1/workspace/flame-kk.ui.adhoc/.env/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 670, in _send_message
    self._handle_error(response)
  File "/var/jenkins/1/workspace/flame-kk.ui.adhoc/.env/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 725, in _handle_error
    raise errors.JavascriptException(message=message, status=status, stacktrace=stacktrace)
JavascriptException: JavascriptException: unload was called


Does not reproduce manually: 5/5 attempts
QA Whiteboard: [QAnalyst-Triage?][fxosqa-auto-backlog?]
Flags: needinfo?(pbylenga)
The issue appears to be here in the traceback:
  video_player.wait_for_thumbnails_to_load(1, 'Video files found on device: %s' %self.data_layer.video_files)
  File "/var/jenkins/1/workspace/flame-kk.ui.adhoc/tests/python/gaia-ui-tests/gaiatest/gaia_test.py", line 416, in video_files
    'return GaiaDataLayer.getAllVideos();')

Unsure why the screenshot is able to break either while the phone has the dropdown while loading, or after the fact, but that may be the difference between these 3 tests. I could write up a bug for the 3 tests, but their tracebacks all appeared similar so I think they're borrowing the same code for videoplayer.
Summary: test_play_3gp_video.py: "JavascriptException: JavascriptException: unload was called" → test_play_3gp_video.py: "JavascriptException: JavascriptException: unload was called" x3 tests { 3gp, ogg, ogv }
(In reply to Oliver Nelson [:oliverthor] from comment #0)
> Description:
> http://jenkins1.qa.scl3.mozilla.com/view/UI/job/flame-kk.ui.adhoc/
> lastCompletedBuild/testReport/
> 
> Videoplayer encountered issues in the following tests:
> test_play_3gp_video -- 1/5 pass
> test_play_ogg_video -- 3/5 pass 
> test_play_ogv_video -- 2/5 pass

http://jenkins1.qa.scl3.mozilla.com/view/UI/job/flame-kk.ui.adhoc/ doesn't show the failure in the video tests, do you have the correct link for that?
Attached patch ogg.diffSplinter Review
Something like this makes the test pass. This is of course no solution, but it makes it clear that something goes wrong with the wait_for_thumbnails_to_load function:
http://mxr.mozilla.org/gaia/source/tests/python/gaia-ui-tests/gaiatest/apps/videoplayer/app.py#26
QA Whiteboard: [QAnalyst-Triage?][fxosqa-auto-backlog?] → [QAnalyst-Triage+][fxosqa-auto-backlog?]
Flags: needinfo?(pbylenga)
I wonder if this could be somehow a regression from bug 1122079?
It might also be a regression from bug 1139206 somehow. This was backed out, so that means this test would pass today.
Still failing in today's build, so I guess it's not a regression from bug 1139206.
Hi David, we were starting to get this error on our automation environment (on-device) and wondering what could have possibly caused this.  This js exception occurs when loading the thumbnails of video after opening the video app. But as seen in Comment 4, 5 seconds of wait seems to help. AFAIK, all GaiaDataLayer.getAllVideos(); does is (See Comment 1)

getAllVideos: function() {
    this.getFiles('videos');
  },

And we're not sure why all of a sudden this would cause the issue.  Could you offer any reason why it might be happening?
Flags: needinfo?(dflanagan)
Have you tried reverting this patch from bug 1074117? https://github.com/mozilla-b2g/gaia/pull/29197/files

It modifies the definition of wait_for_thumbnails_to_load and it landed relatively recently, so maybe related?

I barely understand these python tests, but with that as caveat, here's what I notice.  The line in the actual test file that causes the problem is:

        video_player.wait_for_thumbnails_to_load(1, 'Video files found on device: %s' %self.data_layer.video_files)

If I understand it, this is going to wait for one thumbnail to appear in the video app before proceeding. But before it waits, it is going to create a message string where the message is "Video files found on device:" followed by a list of all the video files on the device. I don't know why this list is useful, and it will certainly make the test much slower to require it to fully scan the entire sdcard before the video app can even start displaying thumbnails.

In any case, if I'm reading the stack trace correctly, the error comes in computing data_layer.video_files. That is part of the test infrastructure. Not part of the video app and not part of the video app tests. This seems to be purely a marionette / gaia ui test infrastructure / device storage failure of some sort.

As far as I can tell, there isn't any reason to enumerate all of the video files anyway, so maybe you could fix things in these three tests by just removing the message, or at least replacing it with a static message that does not go off and spend multiple seconds enumerating all the files on the sdcard!

I'll also note that the getFiles() method in tests/atoms/gaia_data_layer.js only enumerates the default storage area (I think). On devices with both an internal and external sdcard, it will only list files on the default one.  The video app and other media apps enumerate both. I don't know why that would matter, though.

Hmm. Have you recently switched devices to have bigger sdcards or switched to devices like nexus 5 that have large internal storage sizes? Or have you added tests that put a lot of files into device storage?  If changing the timeout helps with this, then maybe the issue is simply that enumerating all the media files on the sdcard takes a long time and your test is timing out.  (What does "unload was called" in the stack trace indicate? Does that indicate that a test was cancelled and "unloaded" because it timeed out?)
Flags: needinfo?(dflanagan)
I've now tried reverting the patch from bug 1074117, that doesn't make any difference.
I haven't changed devices at all or changed anything (apart from updating the build).
Oh, the time.sleep is not necessary at all, it turns out, this is not causing the failure either:
--- a/tests/python/gaia-ui-tests/gaiatest/tests/functional/videoplayer/test_play_ogg_video.py
+++ b/tests/python/gaia-ui-tests/gaiatest/tests/functional/videoplayer/test_play_ogg_video.py
@@ -20,7 +20,9 @@ class TestPlayOGGVideo(GaiaTestCase):
 
         video_player = VideoPlayer(self.marionette)
         video_player.launch()
-        video_player.wait_for_thumbnails_to_load(1, 'Video files found on device: %s' %self.data_layer.video_files)
+        video_player.wait_for_thumbnails_to_load(1, 'Video files found on device: ')
+        print(self.data_layer.video_files)
 
So for some reason, calling self.data_layer.video_files in the message of wait_for_thumbnails_to_load is causing this failure, it seems.
That is strange, because afaict, Marionette should be only calling the message contents when it's timing out:
http://mxr.mozilla.org/gaia/source/tests/python/gaia-ui-tests/gaiatest/apps/videoplayer/app.py#28
http://mxr.mozilla.org/mozilla-central/source/testing/marionette/driver/marionette_driver/wait.py#137

Dave Hunt, do you know why self.data_layer.video_files is being called at all here, where I would expect it not to be called at all?
Flags: needinfo?(dave.hunt)
Comment on attachment 8589068 [details] [review]
[gaia] mwargers:self.data_layer.video_files > mozilla-b2g:master

Unless Dave Hunt has a solution/explanation for comment 13, perhaps this is the way to go then, since it's not really an essential part of the test anyway, I think.
Attachment #8589068 - Flags: review?(dave.hunt)
(In reply to Martijn Wargers [:mwargers] (QA) from comment #11)
> Dave Hunt, do you know why self.data_layer.video_files is being called at
> all here, where I would expect it not to be called at all?

It's being called in the construction of the message string, which is not a good idea as the string is constructed far too early for the value containing any diagnostic information to be relevant.

As for why the call to video_files is failing, it's likely a regression or recently revealed race condition in Gaia that's causing a JavaScript exception during this Marionette async script execution: https://github.com/mozilla-b2g/gaia/blob/f2c980badda69ed30a00d95e42c9503b50a07374/tests/python/gaia-ui-tests/gaiatest/gaia_test.py#L414
Flags: needinfo?(dave.hunt)
Comment on attachment 8589068 [details] [review]
[gaia] mwargers:self.data_layer.video_files > mozilla-b2g:master

The new message is misleading. Either make it accurate or just remove it.
Attachment #8589068 - Flags: review?(dave.hunt) → review-
(In reply to Dave Hunt (:davehunt) from comment #14)
> (In reply to Martijn Wargers [:mwargers] (QA) from comment #11)
> > Dave Hunt, do you know why self.data_layer.video_files is being called at
> > all here, where I would expect it not to be called at all?
> 
> It's being called in the construction of the message string, which is not a
> good idea as the string is constructed far too early for the value
> containing any diagnostic information to be relevant.

Ok, I don't really understand why it's doing that, as this stuff should only be called when the assertion is failing.
Comment on attachment 8589068 [details] [review]
[gaia] mwargers:self.data_layer.video_files > mozilla-b2g:master

Ok, I removed the whole message now.
Attachment #8589068 - Flags: review?(jlorenzo)
Attachment #8589068 - Flags: review?(dave.hunt)
Attachment #8589068 - Flags: review-
Assignee: nobody → martijn.martijn
Comment on attachment 8589068 [details] [review]
[gaia] mwargers:self.data_layer.video_files > mozilla-b2g:master

Grep couldn't find any other string build with self.data_layer.video_files. r+

Try is not green, the only failure in Gip is unrelated to this patch. However, I don't see any recent PR failing on the same error. I re-triggered Gip11 to make sure we're green.
Attachment #8589068 - Flags: review?(jlorenzo) → review+
(In reply to Martijn Wargers [:mwargers] (QA) from comment #16)
> 
> Ok, I don't really understand why it's doing that, as this stuff should only
> be called when the assertion is failing.

The error message will only be displayed if the assertion fails. But the message string has to be created in order to be passed to wait_for_thumbnails_to_load().  The arguments to a function have to be evaluated before the function can be called, unless maybe you were using some kind of macro language.

So you've either got a fundamental mis-understanding here of how python works, or you're being tripped up by the fact that self.data_layer.video_files looks like a simple property access, but it is in fact running a getter function that does a massive amount of time-consuming computation, scanning the entire sdcard for video files.
Attachment #8589068 - Flags: review?(dave.hunt) → review+
Thanks for the explanation, David.

https://github.com/mozilla-b2g/gaia/commit/b5c1c7282be314de49a2be67cfb964b00344c160
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Blocks: 1152940
You need to log in before you can comment on or make changes to this bug.