949730 - Investigate test_cleanup_scard unittest failure

Status: VERIFIED FIXED

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

Description

[Stephen Donner [:stephend] Not actively reading bugmail]

Gecko revision: http://hg.mozilla.org/mozilla-central/rev/1ad9af3a2ab8
Gaia is: https://github.com/mozilla-b2g/gaia/commit/8952898bbc98dd31e25b647203791cf129867ff1

13:23:14 test_cleanup_scard (test_cleanup_sdcard.TestCleanupSDCard) ... FAIL
13:23:14 
13:23:14 ======================================================================
13:23:14 FAIL: None
13:23:14 ----------------------------------------------------------------------
13:23:14 Traceback (most recent call last):
13:23:14   File "/var/jenkins/workspace/b2g.hamachi.mozilla-central.unittests/.env/local/lib/python2.7/site-packages/marionette_client-0.7.0-py2.7.egg/marionette/marionette_test.py", line 143, in run
13:23:14     testMethod()
13:23:14   File "/var/jenkins/workspace/b2g.hamachi.mozilla-central.unittests/tests/python/gaia-ui-tests/gaiatest/tests/unit/test_cleanup_sdcard.py", line 20, in test_cleanup_scard
13:23:14     self.assertEqual(len(self.data_layer.media_files), 0)
13:23:14 TEST-UNEXPECTED-FAIL | test_cleanup_sdcard.py test_cleanup_sdcard.TestCleanupSDCard.test_cleanup_scard | AssertionError: 1 != 0
13:23:14 ----------------------------------------------------------------------
13:23:14 Ran 1 test in 43.661s

I'm re-running with a dedicated, single test, so I can get a cleaner logcat, which I'll attach.

Comment 1

[Stephen Donner [:stephend] Not actively reading bugmail]

Attachment: logcat.txt

Comment 2

[Stephen Donner [:stephend] Not actively reading bugmail]

(In reply to Stephen Donner [:stephend] from comment #1)
> Created attachment 8346899 [details]
> logcat.txt

I tried creating a single-test run, but got our dreaded "socket timeout" error, so this is the full logcat from an earlier unittest-suite run: http://qa-selenium.mv.mozilla.com:8080/view/B2G%20Hamachi/job/b2g.hamachi.mozilla-central.unittests/16/

Comment 3

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

Is this happening often? It would be useful to know what files are being found. Perhaps we could add some debug to the test to output the list of files on failure.

Comment 4

[Stephen Donner [:stephend] Not actively reading bugmail]

(In reply to Dave Hunt (:davehunt) from comment #3)
> Is this happening often? It would be useful to know what files are being
> found. Perhaps we could add some debug to the test to output the list of
> files on failure.

Yeah, happens 100% of the time.  Bebe, can you have someone take a look, please?

Comment 5

[Bob Silverberg [:bsilverberg]]

I tried running this unit test on my Hamachi with the latest build and it passes 100% of the time for me. Is this happening on one specific phone?

Comment 6

[Bob Silverberg [:bsilverberg]]

Oh, I was able to get a failure, after 6 runs. Here's what ls says is on the card:

root@android:/sdcard # ls -l
d---rwx--- system   sdcard_rw          2013-12-17 17:41 tests

Does that help?

Comment 7

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

It looks like there's a 'tests' directory on the sdcard. Is there anything inside it? What permissions does it have? Are you able to delete it?

Comment 8

[Bob Silverberg [:bsilverberg]]

There is nothing in the directory. I assumed that the output of that ls -l command showed the permissions - is there a way to see more detailed permissions? I *am* able to remove the directory with rmdir.

Comment 9

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

(In reply to Bob Silverberg [:bsilverberg] from comment #8)
> There is nothing in the directory. I assumed that the output of that ls -l
> command showed the permissions - is there a way to see more detailed
> permissions? I *am* able to remove the directory with rmdir.

Sorry, you're right about the permissions.. they're included in comment 6. Can you tell me how you're replicating this? Are you just running the test_cleanup_sdcard over and over? Any idea where this 'tests' folder is coming from? I couldn't find anything obvious in the UI tests.

I'm thinking we may want to try to clear the sdcard during our flash script, and also make the cleanup_sdcard more robust, perhaps by checking if each item has been deleted and repeating the rm until it's gone.

Comment 10

[Bob Silverberg [:bsilverberg]]

Yes, I reproduced this by just running that one test in a loop. I have no idea where that 'tests' folder is coming from, but I can try to investigate. I will also take a look at making `cleanup_sdcard` more robust, as you suggest.

Comment 11

[Bob Silverberg [:bsilverberg]]

I believe what is happening is that the call to `device.manager.removeDir` [1] is running asynchronously, so sometimes the deletion isn't complete before the assertion at [2].

I observed this by adding logging into `cleanup_sdcard` and saw that sometimes the deletion doesn't happen immediately. I think the best solution to this is to change the test to wait for `data_layer.media_files` files to empty, instead of just asserting it immediately.

I will do that in a PR and attach it to this bug. 

[1] https://github.com/mozilla-b2g/gaia/blob/master/tests/python/gaia-ui-tests/gaiatest/gaia_test.py#L837
[2] https://github.com/mozilla-b2g/gaia/blob/master/tests/python/gaia-ui-tests/gaiatest/tests/unit/test_cleanup_sdcard.py#L20

Comment 12

[Florin Strugariu [:Bebe]]

looks like Bob is on the case 
Thanks for taking care of this

Comment 13

[Bob Silverberg [:bsilverberg]]

Attachment: Link to Github pull-request: https://github.com/mozilla-b2g/gaia/pull/14809

Comment 14

[Florin Strugariu [:Bebe]]

Comment on attachment 8349379 [details] [review]
Link to Github pull-request: https://github.com/mozilla-b2g/gaia/pull/14809

Agree with Dave on this one 
We just fix the test here not the issue

Comment 15

[Bob Silverberg [:bsilverberg]]

I wasn't sure if the existing mozdevice behaviour was expected, so rather than monkey with that I figured I'd just make sure that the test would work. Now I understand that the behaviour is not intended so I have submitted a patch to mozbase via bug 951773. Once that lands and is brought into the project I will test it again. My local tests with a patched mozbase do show that the problem is gone.

Comment 16

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

Awesome, thanks Bob.

Comment 17

[Bob Silverberg [:bsilverberg]]

Attachment: Link to Github pull-request: https://github.com/mozilla-b2g/gaia/pull/14816

Comment 18

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

Comment on attachment 8349552 [details] [review]
Link to Github pull-request: https://github.com/mozilla-b2g/gaia/pull/14816

Looks good! The Travis-CI failure appears to be unrelated.

Comment 19

[Bob Silverberg [:bsilverberg]]

Landed on master in https://github.com/mozilla-b2g/gaia/commit/cf0ab53b442d78529bb160c2a27115ceff92fe0f

Comment 20

[Carsten Book [:Tomcat]]

had to back this out because breaking gaia ui tests like https://tbpl.mozilla.org/php/getParsedLog.php?id=32216951&tree=B2g-Inbound

Comment 21

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

jgriffin: How do we get TBPL to pick up the latest version of mozdevice?

Comment 22

[Jonathan Griffin (:jgriffin)]

(In reply to Dave Hunt (:davehunt) from comment #21)
> jgriffin: How do we get TBPL to pick up the latest version of mozdevice?

This is already in the works as part of bug 949600, which moves mozbase from github to the tree.

However, if you need this sooner, we could mirror only mozdevice (and any dependencies) separately.

Comment 23

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

No rush, this is for fixing an issue we have only seen on device, and that's already fixed because we were previously not pinning the mozdevice version anyway.

Comment 24

[Bob Silverberg [:bsilverberg]]

Can this bug be closed? Do we need to wait for something to happen so we can pin mozdevice, or should we just keep it unpinned? What do you think, Dave?

Comment 25

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

We shouldn't close this until it's fixed. See comment 22 and the dependent bugs.

Comment 26

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

Now that bug 949600 is resolved and TBPL is on mozdevice 0.33, I have relanded this change:
https://github.com/mozilla-b2g/gaia/commit/c6d6c106494745b54d562434936689419b4c5996

Comment 27

[Stephen Donner [:stephend] Not actively reading bugmail]

Verified FIXED; sorry for the delay!