1203535 - Autophone - robocop_autophone failing on some devices with No such file or directory: 'robocop.log'

Status: RESOLVED FIXED

(Testing Graveyard :: Autophone, defect)

Description

[Bob Clary [:bc] (inactive)]

https://autophone.s3.amazonaws.com/pub/mozilla.org/mobile/tinderbox-builds/mozilla-inbound-android-api-11/1441878151/robocoptest-autophone-robocoptests-autophone-settings.ini-1-nexus-4-jdq39-2-37eedf21-e285-420d-b90e-fd15ffb4f3c1.log

1 ERROR Automation Error: Exception caught while running tests
Traceback (most recent call last):
  File "mochitest/runrobocop.py", line 454, in runSingleTest
    log_result = self.parseLocalLog()
  File "mochitest/runrobocop.py", line 270, in parseLocalLog
    with open(self.localLog) as currentLog:
IOError: [Errno 2] No such file or directory: 'robocop.log'

This happens on mozilla-inbound with nexus-4-jdq39-2, b2g-inbound with nexus-4-jdq39-4. 

I do *not* see this error on fx-team with nexus-4-jdq39-3.

I don't have test runs with nexus-4-jdq39-1 on mozilla-central or nexus-7-jss15q-2 on mozilla-inbound.

Comment 1

[Bob Clary [:bc] (inactive)]

gbrown: Any thoughts?

Comment 2

[Geoff Brown [:gbrown]]

INFO | automation.py | Application ran for: 0:00:12.014575

That seems too short, like the browser isn't being started: No browser, no test, no log. But why no browser?

Comment 3

[Geoff Brown [:gbrown]]

Logcat from successful run (fx-team):

09-10 04:16:10.430 I/SUTAgentAndroid( 1691): 10.252.73.89 : exec "MOZ_CRASHREPORTER=1,R_LOG_VERBOSE=1,R_LOG_DESTINATION=stderr,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1,NSPR_LOG_FILE=/mnt/sdcard/tests/nspr/nspr-testAdobeFlash.log,R_LOG_LEVEL=6,MOZ_DISABLE_NONLOCAL_CONNECTIONS=1,MOZ_PROCESS_LOG=/var/folders/94/zbj0mcp54hx99z748npbknzm0000gn/T/tmpR0iPm4pidlog" am instrument --user 0 -w -e quit_and_finish 1 -e deviceroot /mnt/sdcard/tests -e class org.mozilla.gecko.tests.testAdobeFlash org.mozilla.roboexample.test/org.mozilla.gecko.FennecInstrumentationTestRunner
09-10 04:16:10.490 D/dalvikvm( 1691): GC_CONCURRENT freed 473K, 6% free 8876K/9404K, paused 5ms+8ms, total 50ms
09-10 04:16:10.540 D/AndroidRuntime( 7706):
09-10 04:16:10.540 D/AndroidRuntime( 7706): >>>>>> AndroidRuntime START com.android.internal.os.RuntimeInit <<<<<<
09-10 04:16:10.540 D/AndroidRuntime( 7706): CheckJNI is OFF
09-10 04:16:10.550 D/dalvikvm( 7706): Trying to load lib libjavacore.so 0x0
09-10 04:16:10.550 D/dalvikvm( 7706): Added shared lib libjavacore.so 0x0
09-10 04:16:10.560 D/dalvikvm( 7706): Trying to load lib libnativehelper.so 0x0
09-10 04:16:10.560 D/dalvikvm( 7706): Added shared lib libnativehelper.so 0x0
09-10 04:16:10.700 D/AndroidRuntime( 7706): Calling main entry com.android.commands.am.Am
09-10 04:16:10.700 D/dalvikvm( 7706): Note: class Landroid/app/ActivityManagerNative; has 157 unimplemented (abstract) methods
09-10 04:16:10.850 W/dalvikvm( 7721): VFY: unable to resolve static field 347 (GeckoRunning) in Lorg/mozilla/gecko/GeckoThread$LaunchState;
09-10 04:16:10.850 D/dalvikvm( 7721): VFY: replacing opcode 0x62 at 0x0008
09-10 04:16:10.870 I/dalvikvm( 7721): Could not find method android.app.Activity.finishAfterTransition, referenced from method android.support.v4.app.FragmentActivity.onBackPressed
09-10 04:16:10.870 W/dalvikvm( 7721): VFY: unable to resolve virtual method 36: Landroid/app/Activity;.finishAfterTransition ()V
09-10 04:16:10.870 D/dalvikvm( 7721): VFY: replacing opcode 0x6e at 0x000e
09-10 04:16:10.880 W/dalvikvm( 7721): method Landroid/test/InstrumentationTestRunner$StringResultPrinter;.print incorrectly overrides package-private method with same name in Ljunit/textui/ResultPrinter;
09-10 04:16:10.880 I/TestRunner( 7721): started: testLoad(org.mozilla.gecko.tests.testAdobeFlash)
09-10 04:16:10.911 I/Robocop ( 7721): {"action":"log","message":"SimpleTest START","time":1441883770904,"pid":null,"level":"info","source":"robocop","thread":null}
09-10 04:16:10.911 I/Robocop ( 7721): {"action":"test_start","time":1441883770921,"pid":null,"source":"robocop","test":"testAdobeFlash","thread":null}

vs failed run (mozilla-inbound):

09-10 09:49:49.571 I/SUTAgentAndroid( 1796): 10.252.73.89 : exec "MOZ_CRASHREPORTER=1,R_LOG_VERBOSE=1,R_LOG_DESTINATION=stderr,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1,NSPR_LOG_FILE=/mnt/sdcard/tests/nspr/nspr-testAdobeFlash.log,R_LOG_LEVEL=6,MOZ_DISABLE_NONLOCAL_CONNECTIONS=1,MOZ_PROCESS_LOG=/var/folders/94/zbj0mcp54hx99z748npbknzm0000gn/T/tmpJjnWoTpidlog" am instrument --user 0 -w -e quit_and_finish 1 -e deviceroot /mnt/sdcard/tests -e class org.mozilla.gecko.tests.testAdobeFlash org.mozilla.roboexample.test/org.mozilla.gecko.FennecInstrumentationTestRunner
09-10 09:49:49.661 D/AndroidRuntime( 7673): Calling main entry com.android.commands.am.Am
09-10 09:49:49.661 D/dalvikvm( 7673): Note: class Landroid/app/ActivityManagerNative; has 157 unimplemented (abstract) methods
09-10 09:49:49.671 D/AndroidRuntime( 7684):
09-10 09:49:49.671 D/AndroidRuntime( 7684): >>>>>> AndroidRuntime START com.android.internal.os.RuntimeInit <<<<<<
09-10 09:49:49.671 D/AndroidRuntime( 7684): CheckJNI is OFF
09-10 09:49:49.681 D/dalvikvm( 7684): Trying to load lib libjavacore.so 0x0
09-10 09:49:49.681 D/dalvikvm( 7684): Added shared lib libjavacore.so 0x0
09-10 09:49:49.691 D/dalvikvm( 7684): Trying to load lib libnativehelper.so 0x0
09-10 09:49:49.691 D/dalvikvm( 7684): Added shared lib libnativehelper.so 0x0
09-10 09:49:49.701 D/AndroidRuntime( 7673): Shutting down VM
09-10 09:49:49.701 D/dalvikvm( 7673): GC_CONCURRENT freed 92K, 17% free 499K/596K, paused 1ms+0ms, total 3ms
09-10 09:49:49.822 D/AndroidRuntime( 7684): Calling main entry com.android.commands.am.Am
09-10 09:49:49.822 D/dalvikvm( 7684): Note: class Landroid/app/ActivityManagerNative; has 157 unimplemented (abstract) methods
09-10 09:49:49.832 I/AndroidRuntime( 7684): VM exiting with result code 1.

Comment 4

[Geoff Brown [:gbrown]]

Theories:

 - robocop.apk (or maybe the fennec apk?) fails to install (could we "pm list packages" after installation?)
 - there's something wrong with "am instrument"
 - some sort of privilege / permissions issue???

Comment 5

[Bob Clary [:bc] (inactive)]

Attachment: bug-1203535-v1.patch

As we discussed on irc, this patch changes the transport from sut to adb for the unit tests. I am running a fairly extensive test at:

https://treeherder.allizom.org/#/jobs?repo=mozilla-inbound&revision=6227331e17ed&exclusion_profile=false&filter-searchStr=autophone

I'm a little concerned about some of the exceptions I am seeing. I'll attach a summary of the various exceptions I've seen so far.

Comment 6

[Bob Clary [:bc] (inactive)]

Attachment: exception summary

Comment 7

[Geoff Brown [:gbrown]]

Comment on attachment 8660036 [details] [diff] [review]
bug-1203535-v1.patch

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

I share your concern about the exceptions, and don't have much insight into them.

btw, testAdobeFlash is a no-op on pre-ICS -- no reason to run it on 2.3.

Comment 8

[Bob Clary [:bc] (inactive)]

re 2.3 - thanks and cool. The exceptions for the logcat are localized to the 2.3 devices. I wonder if bad / slow sdcards are an issue.

I'll land and deploy this this weekend and will adjust the manifests to keep testAdobeFlash from running on the nexus s devices. Since we are no longer contrained to run the unit tests on devices which have a working sutagent, I'll try to partition them better. I'll also remove the sutagent from all of the devices.

Comment 9

[Bob Clary [:bc] (inactive)]

https://github.com/mozilla/autophone/commit/aaa9252af597b9bb6de6cb435d8284972c2e3ab6