https://treeherder.mozilla.org/#/jobs?repo=mozilla-beta&revision=5fecfbec2e3c&filter-searchStr=autophone&exclusion_profile=false Android 4.4 illustrates a recurrent problem where Autophone goes orange when we fail to get a measurement due to an intermittent usb failure. Looking at the Autophone log we see: https://autophone.s3.amazonaws.com/pub/mozilla.org/mobile/tinderbox-builds/mozilla-beta-android-api-11/1434736603/autophone-s1s2-s1s2-nytimes-local.ini-1-nexus-5-kot49h-5-59d56242-9d2c-4af8-a40c-271b05a6e7d6-autophone.log 2015-06-19 15:33:20,659|619|MainThread|root|INFO|nexus-5-kot49h-5|20150619105643|local-nytimes|Running test (1/1) for 8 iterations 2015-06-19 15:33:21,769|619|MainThread|root|INFO|nexus-5-kot49h-5|Pinging phone attempt 1 2015-06-19 15:33:23,070|619|MainThread|root|INFO|nexus-5-kot49h-5|<2015-06-19T15:33:23> nexus-5-kot49h-5 (WORKING): Attempt 1/2 for Test 1/1, run 1, for url /storage/sdcard0/tests/autophone/s1s2test/nytimes.com/index.html 2015-06-19 15:33:57,088|619|MainThread|root|INFO|nexus-5-kot49h-5|Pinging phone attempt 1 2015-06-19 15:33:58,392|619|MainThread|root|INFO|nexus-5-kot49h-5|<2015-06-19T15:33:58> nexus-5-kot49h-5 (WORKING): Attempt 1/2 for Test 1/1, run 2, for url /storage/sdcard0/tests/autophone/s1s2test/nytimes.com/index.html 2015-06-19 15:35:57,168|619|MainThread|root|INFO|nexus-5-kot49h-5|20150619105643|local-nytimes|Unable to find Throbber stop and the corresponding location in logcat is https://autophone.s3.amazonaws.com/pub/mozilla.org/mobile/tinderbox-builds/mozilla-beta-android-api-11/1434736603/autophone-s1s2-s1s2-nytimes-local.ini-1-nexus-5-kot49h-5-59d56242-9d2c-4af8-a40c-271b05a6e7d6-logcat.log 06-19 15:35:56.927 E/UsbDebuggingManager( 777): Communication error: 06-19 15:35:56.927 E/UsbDebuggingManager( 777): java.io.IOException: Connection refused 06-19 15:35:56.927 E/UsbDebuggingManager( 777): at android.net.LocalSocketImpl.connectLocal(Native Method) 06-19 15:35:56.927 E/UsbDebuggingManager( 777): at android.net.LocalSocketImpl.connect(LocalSocketImpl.java:287) 06-19 15:35:56.927 E/UsbDebuggingManager( 777): at android.net.LocalSocket.connect(LocalSocket.java:130) 06-19 15:35:56.927 E/UsbDebuggingManager( 777): at com.android.server.usb.UsbDebuggingManager.listenToSocket(UsbDebuggingManager.java:75) 06-19 15:35:56.927 E/UsbDebuggingManager( 777): at com.android.server.usb.UsbDebuggingManager.run(UsbDebuggingManager.java:111) 06-19 15:35:56.927 E/UsbDebuggingManager( 777): at java.lang.Thread.run(Thread.java:841) 06-19 15:35:57.927 E/UsbDebuggingManager( 777): Communication error: 06-19 15:35:57.927 E/UsbDebuggingManager( 777): java.io.IOException: Connection refused 06-19 15:35:57.927 E/UsbDebuggingManager( 777): at android.net.LocalSocketImpl.connectLocal(Native Method) 06-19 15:35:57.927 E/UsbDebuggingManager( 777): at android.net.LocalSocketImpl.connect(LocalSocketImpl.java:287) 06-19 15:35:57.927 E/UsbDebuggingManager( 777): at android.net.LocalSocket.connect(LocalSocket.java:130) 06-19 15:35:57.927 E/UsbDebuggingManager( 777): at com.android.server.usb.UsbDebuggingManager.listenToSocket(UsbDebuggingManager.java:75) 06-19 15:35:57.927 E/UsbDebuggingManager( 777): at com.android.server.usb.UsbDebuggingManager.run(UsbDebuggingManager.java:111) 06-19 15:35:57.927 E/UsbDebuggingManager( 777): at java.lang.Thread.run(Thread.java:841) The remaining tests were able to collect the logcat and find the throbber indicators so the problem is an intermittent one. I can see two ways forward: 1. crappy - do not count individual measurement failures as failures which cause the test to go orange. 2. not so crappy - since the remaining tests appear to connect via usb and collect the throbbers, it should be possible to retry the logcat collection up to a limit to see if we can work around the usb failure.

Looking at #2, we already retry collecting logcat if it fails which means we are out of luck for the cases where the flood of E/UsbDebuggingManager messages appears and the Throbber message is missing. Therefore it appears that #1 might be the only approach we can use if the USB error is the cause of the missing measurement. It also appears that the USB error may be not be the root cause. For example, the Android 4.4 failing test in https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=9eff85753c97&filter-searchStr=autophone&exclusion_profile=false also fails to get a measurement but without the USB errors. It is terminated: appear to terminate due to 06-26 14:37:33.558 I/Gecko (13346): Can't find symbol 'GetActiveUniformName'. 06-26 14:40:14.048 I/WindowState( 811): WIN DEATH: Window{42d052e0 u0 org.mozilla.fennec/org.mozilla.fennec.App} 06-26 14:40:14.048 W/WindowManager( 811): Force-removing child win Window{42a486f8 u0 SurfaceView} from container Window{42d052e0 u0 org.mozilla.fennec/org.mozilla.fennec.App} 06-26 14:40:14.048 I/ActivityManager( 811): Process org.mozilla.fennec (pid 13346) has died. 06-26 14:40:14.048 W/ActivityManager( 811): Force removing ActivityRecord{42ab7490 u0 org.mozilla.fennec/.App t57}: app died, no saved state 06-26 14:40:14.048 W/WindowManager( 811): Failed looking up window 06-26 14:40:14.048 W/WindowManager( 811): java.lang.IllegalArgumentException: Requested window android.os.BinderProxy@42814700 does not exist 06-26 14:40:14.048 W/WindowManager( 811): at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:7923) 06-26 14:40:14.048 W/WindowManager( 811): at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:7914) 06-26 14:40:14.048 W/WindowManager( 811): at com.android.server.wm.WindowState$DeathRecipient.binderDied(WindowState.java:1047) 06-26 14:40:14.048 W/WindowManager( 811): at android.os.BinderProxy.sendDeathNotice(Binder.java:493) 06-26 14:40:14.048 W/WindowManager( 811): at dalvik.system.NativeStart.run(Native Method) 06-26 14:40:14.048 I/WindowState( 811): WIN DEATH: null 06-26 14:40:14.088 D/Zygote ( 177): Process 13346 terminated by signal (15) This is also the case with the original example in comment 0: 06-19 15:32:54.208 I/ActivityManager( 777): Process org.mozilla.firefox_beta (pid 22717) has died. 06-19 15:32:54.248 D/Zygote ( 182): Process 22717 terminated by signal (15) snorp: Do you have any idea with fennec is being terminated in these cases and is this a real fennec bug?

Bob, signal 15 is SIGTERM. It's unlikely this would be triggered from within Fennec, and I don't think Android uses it to kill stuff (it just uses SIGKILL). Is it possible autophone could be killing it? One thing that might help is to use the 'log' command to put something in logcat when you are going to kill it.

kill without a signal being specified sends SIGTERM. Much of Autophone issues kills without specifying the signal and thus does use SIGTERM. I *don't think* I'm issuing these, but I can answer that pretty quickly I think.

(In reply to Bob Clary [:bc:] from comment #0) I believe the connection refused message is unrelated and the previous comment was wrong. The message: failed to get measurements start_time: 06-19 15:34:17.127 shows the start_time occurred after the usb connection error and that the throbber stop was unrelated. --------- beginning of /dev/log/system 06-19 15:34:16.687 E/UsbDebuggingManager( 777): Communication error: 06-19 15:34:16.687 E/UsbDebuggingManager( 777): java.io.IOException: Connection refused 06-19 15:34:16.687 E/UsbDebuggingManager( 777): at android.net.LocalSocketImpl.connectLocal(Native Method) 06-19 15:34:16.687 E/UsbDebuggingManager( 777): at android.net.LocalSocketImpl.connect(LocalSocketImpl.java:287) 06-19 15:34:16.687 E/UsbDebuggingManager( 777): at android.net.LocalSocket.connect(LocalSocket.java:130) 06-19 15:34:16.687 E/UsbDebuggingManager( 777): at com.android.server.usb.UsbDebuggingManager.listenToSocket(UsbDebuggingManager.java:75) 06-19 15:34:16.687 E/UsbDebuggingManager( 777): at com.android.server.usb.UsbDebuggingManager.run(UsbDebuggingManager.java:111) 06-19 15:34:16.687 E/UsbDebuggingManager( 777): at java.lang.Thread.run(Thread.java:841) --------- beginning of /dev/log/main 06-19 15:34:16.937 D/AndroidRuntime(24061): 06-19 15:34:16.937 D/AndroidRuntime(24061): >>>>>> AndroidRuntime START com.android.internal.os.RuntimeInit <<<<<< 06-19 15:34:16.937 D/AndroidRuntime(24061): CheckJNI is OFF 06-19 15:34:16.957 D/dalvikvm(24061): Trying to load lib libjavacore.so 0x0 06-19 15:34:16.957 D/dalvikvm(24061): Added shared lib libjavacore.so 0x0 06-19 15:34:16.957 D/dalvikvm(24061): Trying to load lib libnativehelper.so 0x0 06-19 15:34:16.957 D/dalvikvm(24061): Added shared lib libnativehelper.so 0x0 06-19 15:34:16.957 D/dalvikvm(24061): No JNI_OnLoad found in libnativehelper.so 0x0, skipping init 06-19 15:34:16.977 D/dalvikvm(24061): Note: class Landroid/app/ActivityManagerNative; has 179 unimplemented (abstract) methods 06-19 15:34:17.107 D/AndroidRuntime(24061): Calling main entry com.android.commands.am.Am 06-19 15:34:17.117 I/ActivityManager( 777): START u0 {act=android.intent.action.VIEW dat=/storage/sdcard0/tests/autophone/s1s2test/nytimes.com/index.html flg=0x10000000 cmp=org.mozilla.firefox_beta/.App (has extras)} from pid 24061 06-19 15:34:17.127 I/ActivityManager( 777): Start proc org.mozilla.firefox_beta for activity org.mozilla.firefox_beta/.App: pid=24077 uid=10076 gids={50076, 3003, 1028, 1015} (In reply to Bob Clary [:bc:] from comment #1) I have investigated this and the sigterms are also unrelated. This entire issue appears to be an instance of the problems we have with the nytimes page. I'm going to dupe it to that bug and continue the investigation there.