800102 - Emulator sometimes stalls while Marionette is installing a new gecko in it resulting in a "Timeout exceeded for _checkCmd call"

Status: RESOLVED FIXED

(Testing :: Marionette Client and Harness, defect)

Description

[Jonathan Griffin (:jgriffin)]

When passing --gecko-path to Marionette, the "adb push" call which copies a new gecko to the emulator sometimes stalls for an indefinite period.  It usually can be woken up again by doing a few simple adb calls in another terminal, e.g., "adb shell".

I have no idea why this happens, but I have a patch that fixes it on my machine.

Comment 1

[Jonathan Griffin (:jgriffin)]

Attachment: Delete *.so files before updating gecko in the emulator

I have no idea why this works, but I haven't seen this issue at all with this patch.I didn't do a more aggressive 'rm -rf *' because it deletes files that aren't part of the separate gecko builds...I'm guessing they're unpacked during the initial boot.

Comment 2

[Andrew Halberstadt [:ahal]]

Comment on attachment 670091 [details] [diff] [review]
Delete *.so files before updating gecko in the emulator

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

r+. I was hoping to test it out, but by murphy's law I stopped being able to reproduce the issue when I went to do so. But this change shouldn't hurt anything at the least so if it works for you then lgtm.

Comment 3

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/mozilla-central/rev/8e047a9698f0

Comment 4

[Jonathan Griffin (:jgriffin)]

Comment on attachment 670091 [details] [diff] [review]
Delete *.so files before updating gecko in the emulator

[Approval Request Comment]
Bug caused by (feature/regressing bug #): N/A
User impact if declined: We won't be able to run Marionette tests on TBPL on aurora without this patch.
Testing completed (on m-c, etc.): N/A
Risk to taking this patch (and alternatives if risky): None
String or UUID changes made by this patch: N/A

Comment 5

[bhavana bajaj [:bajaj]]

Comment on attachment 670091 [details] [diff] [review]
Delete *.so files before updating gecko in the emulator

Approving , as this is much needed for tests

Comment 6

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/fd0dcda77b60

Comment 7

[Jonathan Griffin (:jgriffin)]

Sadly, this appears not be fixed, as it's showing up on cedar.

Comment 8

[Jonathan Griffin (:jgriffin)]

Attachment: Attempted fix

Will land this on cedar to see if it helps.

Comment 9

[Jonathan Griffin (:jgriffin)]

https://tbpl.mozilla.org/?tree=Cedar&noignore=1&rev=a3c04df5d2b5

Comment 10

[Aki Sasaki (not active)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16395992&tree=Cedar&full=1

Comment 11

[Jonathan Griffin (:jgriffin)]

Attachment: Try to copy gecko using devicemanagerADB

Comment 12

[Jonathan Griffin (:jgriffin)]

Pushed another attempted fix to cedar: https://hg.mozilla.org/projects/cedar/rev/0705e84d547d

Comment 13

[Jonathan Griffin (:jgriffin)]

Attachment: Another attempt to fix the adb push while installing gecko

Comment 14

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/projects/cedar/rev/838c6d621e7b

Comment 15

[Jonathan Griffin (:jgriffin)]

Attachment: Work around adb deadlock when installing gecko in emulator,

This is a modified version of a patch which has been running successfully on cedar for about 5 days, with no occurrences of this problem.

The 'fix' (really workaround) is to first copy the files to the /data partition, then copy them from there to /system/b2g using 'dd'.  Additionally, the initial copy must be performed *before* b2g is shut down.  The reason is that 'adb push' is much slower while b2g is running, and this seems to help prevent the deadlock.

Comment 16

[Andrew Halberstadt [:ahal]]

Comment on attachment 676710 [details] [diff] [review]
Work around adb deadlock when installing gecko in emulator,

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

r+, keeping in mind that these changes will need to be upstreamed to the mozdevice emulator.py

::: testing/marionette/client/marionette/emulator.py
@@ +387,5 @@
> +        # partition.
> +        for root, dirs, files in os.walk(gecko_path):
> +            for filename in files:
> +                data_local_file = os.path.join('/data/local', filename)
> +                print 'pushing', data_local_file

Were these print statements left on purpose? Won't this generate a lot of redundant logs?

Comment 17

[Jonathan Griffin (:jgriffin)]

I left the print statements in so if it hangs on a TPBL job, we can at least see where it hangs (e.g., which copying stage and which file).

I've filed bug 807119 to port this (and other changes) to mozdevice's emulator classes.

Comment 18

[Jonathan Griffin (:jgriffin)]

Since this touches setup.py, I'm taking the precaution of running it through try:  https://tbpl.mozilla.org/?tree=Try&rev=a6be101c6d42&noignore=1

Comment 19

[Jonathan Griffin (:jgriffin)]

try run 100% green

Comment 20

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/mozilla-central/rev/baa695a1f5ca

Comment 21

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/projects/ash/rev/df4610f3be6f

Comment 23

[Andrew Halberstadt [:ahal]]

I saw this happen once again on Cedar with reftests:
https://tbpl.mozilla.org/php/getParsedLog.php?id=16759480&tree=Cedar

Comment 24

[Jonathan Griffin (:jgriffin)]

cc'ing sheriffs since it's possible this will occur in the wild before it's fixed.

The output in the log when this happens is something like:

11:53:55     INFO -  pushing /data/local/omni.ja
11:53:55     INFO -  Traceback (most recent call last):
11:53:55     INFO -    File "runreftestb2g.py", line 563, in <module>
11:53:55     INFO -      sys.exit(main())
11:53:55     INFO -    File "runreftestb2g.py", line 483, in main
11:53:55     INFO -      marionette = Marionette(**kwargs)
11:53:55     INFO -    File "/home/cltbld/talos-slave/test/build/venv/lib/python2.6/site-packages/marionette/marionette.py", line 148, in __init__
11:53:55     INFO -      self.emulator.install_gecko(self.gecko_path, self)
11:53:55     INFO -    File "/home/cltbld/talos-slave/test/build/venv/lib/python2.6/site-packages/marionette/emulator.py", line 392, in install_gecko
11:53:55     INFO -      self.dm.pushFile(os.path.join(root, filename), data_local_file)
11:53:55     INFO -    File "/home/cltbld/talos-slave/test/build/venv/lib/python2.6/site-packages/mozdevice/devicemanagerADB.py", line 180, in pushFile
11:53:55     INFO -      self._checkCmd(["push", os.path.realpath(localname), destname])
11:53:55     INFO -    File "/home/cltbld/talos-slave/test/build/venv/lib/python2.6/site-packages/mozdevice/devicemanagerADB.py", line 769, in _checkCmd
11:53:55     INFO -      raise DMError("Timeout exceeded for _checkCmd call")
11:53:55     INFO -  mozdevice.devicemanager.DMError: Timeout exceeded for _checkCmd call

Comment 25

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16765363&tree=Mozilla-Inbound

Comment 26

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16767581&tree=Mozilla-Inbound

Comment 27

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16769790&tree=Mozilla-Inbound

Comment 28

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16779751&tree=Mozilla-Inbound

Comment 29

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16780144&tree=Mozilla-Inbound

Comment 30

[Ed Morley [:emorley]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16783859&tree=Firefox

Comment 31

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16780111&tree=Fx-Team

Comment 32

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16787392&tree=Fx-Team

Comment 33

[Andrew Halberstadt [:ahal]]

I'll take a look at this, but I'm having trouble reproducing it locally. I may just have to implement a system that will retry the install-gecko step if it fails.

Comment 34

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16790672&tree=Firefox

Comment 35

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=16791454&tree=Fx-Team

Comment 36

[Andrew Halberstadt [:ahal]]

Pushed a fix to cedar: https://tbpl.mozilla.org/?tree=Cedar&rev=1bc7d82bebf2

I'll re-trigger a bunch of times to try and reproduce. I'm pretty sure this will get around the problem (though I can't say I'm super happy about it).

Comment 37

[Andrew Halberstadt [:ahal]]

Attachment: Patch 1.0 - Retry adb push if it times out when installing gecko

Comment 38

[Jonathan Griffin (:jgriffin)]

Comment on attachment 678858 [details] [diff] [review]
Patch 1.0 - Retry adb push if it times out when installing gecko

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

Thanks.  Third time's the charm!

Comment 39

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a09cb93f9d82

Comment 40

[(PTO June 19-July 7) Ryan VanderMeulen]

https://hg.mozilla.org/mozilla-central/rev/a09cb93f9d82

Comment 41

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/c1e430ff299e
https://hg.mozilla.org/releases/mozilla-aurora/rev/7e9e4acbf58b

Comment 42

[Justin Wood (:Callek)]

(In reply to Andrew Halberstadt [:ahal] from comment #36)
> Pushed a fix to cedar: https://tbpl.mozilla.org/?tree=Cedar&rev=1bc7d82bebf2
> 
> I'll re-trigger a bunch of times to try and reproduce. I'm pretty sure this
> will get around the problem (though I can't say I'm super happy about it).

So ahal, this on cedar somehow caused an additional "head" on "default" with hg.

Two options which I'd like to do one of for us:

(a) Merge this change to cedar's tip, along with a current m-c
(b) Backout this change, *then* merge the head down to tip [effectively doing a no-op -- I think, would verify]

So to summarize, "do we still want this changeset on cedar"?

This does block me asking IT to [make sure and] enable the single-head hook.

Comment 43

[Jonathan Griffin (:jgriffin)]

Yes, we still want this on cedar, so I think 1) is the way to go.

Comment 44

[Andrew Halberstadt [:ahal]]

(In reply to Justin Wood (:Callek) from comment #42)
> So to summarize, "do we still want this changeset on cedar"?

Yes, sorry about that

Comment 45

[Justin Wood (:Callek)]

Just to round back, we talked about this on IRC. the patch landed on cedar conflicts with what is currently on cedar's tip (which likely includes the patch that was pushed to m-c)

So we'll just merge this head away, and keep what is/was on m-c instead. I'll take care of that.

Comment 46

[Aki Sasaki (not active)]

hg heads
hg up -r 112389
hg commit --close-branch -m "rogue head"
hg up -r default
hg ident
hg pull http://hg.mozilla.org/mozilla-central
hg merge
hg commit
hg push

Rogue head closed.

Comment 47

[Ed Morley [:emorley]]

(In reply to Aki Sasaki [:aki] from comment #46)
> hg heads
> hg up -r 112389
> hg commit --close-branch -m "rogue head"
> hg up -r default
> hg ident
> hg pull http://hg.mozilla.org/mozilla-central
> hg merge
> hg commit
> hg push
> 
> Rogue head closed.

This extra head will need to be dummy merged rather than closed, if cedar ever needs to merge to mozilla-central (due to the single head hook). Or is cedar just a testing-ground and accepted changes going to be transplanted/cherry-picked to m-c?

Comment 48

[Jonathan Griffin (:jgriffin)]

For B2G we won't need to merge cedar to m-c; I can't say about other users.

Comment 49

[Aki Sasaki (not active)]

I've only got a single changed file for mozharness talos; pretty easy to cherry pick that one when I'm ready to merge.

Comment 50

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.