Closed Bug 734715 Opened 12 years ago Closed 10 years ago

Intermittent Automation Error: Unable to copy profile to device.

Categories

(Testing :: General, defect)

Product:
Testing
Component:
General
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: philor, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [android_tier_∞])

Attachments

(1 file)

add socket error reporting to devicemanagerSUT
2.85 KB, patch
jmaher
: review+
Details | Diff | Splinter Review 
Personally, I'm just interested in remembering something that someday I'll be able to match to set RETRY on the job.

https://tbpl.mozilla.org/php/getParsedLog.php?id=9982839&tree=Mozilla-Inbound
Android Tegra 250 mozilla-inbound opt test robocop on 2012-03-10 20:19:47 PST for push 9c6e7924e791

7 INFO TEST-PASS | testOverscroll | Checking gecko didn't draw unnecessarily - false should equal false
INFO | automation.py | Application ran for: 0:00:58.426242
INFO | automation.py | Reading PID log: /tmp/tmp5tnbaJpidlog
getting files in '/mnt/sdcard/tests/profile/minidumps/'
WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!

INFO | runtests.py | Running tests: end.
removing file: /mnt/sdcard/tests/logs/mochitest.log
Warning: cleaning up pidfile '/builds/tegra-133/test/../runtestsremote.pid' was unsuccessful from the test harness
INFO | runtests.py | Installing extension at /builds/tegra-133/test/build/tests/mochitest/extensions/roboextender@mozilla.org to /tmp/tmpuKKWf8.
INFO | runtests.py | Installing extension at /builds/tegra-133/test/build/tests/mochitest/extensions/specialpowers to /tmp/tmpuKKWf8.
INFO | runtests.py | Installing extension at /builds/tegra-133/test/build/tests/mochitest/extensions/worker to /tmp/tmpuKKWf8.
INFO | runtests.py | Installing extension at /builds/tegra-133/test/build/tests/mochitest/extensions/workerbootstrap to /tmp/tmpuKKWf8.
pushing directory: /tmp/tmpuKKWf8 to /mnt/sdcard/tests/profile
Push File Failed to Validate!
removing file: /mnt/sdcard/tests/profile//extensions/staged/workerbootstrap-test@mozilla.org/bootstrap.js
failed making directory: /mnt
unable to make dirs: /mnt/sdcard/tests/profile//extensions/staged/workerbootstrap-test@mozilla.org/bootstrap.js
TEST-UNEXPECTED-FAIL | Unable to copy profile to device. | Exception caught while running robocop tests.
program finished with exit code 1
I love the whiteboard!

This is most likely a failure to connect to the device.  Why it would fail in the middle of copying the profile, I don't know.  Why it fails at all, I don't know.
I would like more explicit error messages when this sort of problem occurs. With this patch, we should get messages similar to:

pushing directory: /tmp/tmpiw8OTS to /mnt/sdcard/tests/profile
Error receiving data from socket. cmd=cd /mnt/sdcard/tests/profile/extensions/staged
; err=[Errno 104] Connection reset by peer
reconnecting socket
unable to connect socket: [Errno 111] Connection refused
reconnecting socket
unable to connect socket: [Errno 111] Connection refused
reconnecting socket
unable to connect socket: [Errno 111] Connection refused
reconnecting socket
unable to connect socket: [Errno 111] Connection refused
failed making directory: /mnt/sdcard/tests/profile/extensions/staged
unable to make dirs: /mnt/sdcard/tests/profile//extensions/staged/special-powers@mozilla.org/chrome/specialpowers/content/specialpowers.js
removing file: /mnt/sdcard/tests/profile//extensions/staged/special-powers@mozilla.org/chrome/specialpowers/content/specialpowers.js
failed making directory: /mnt
Attachment #611710 - Flags: review?(jmaher)
Attachment #611710 - Flags: review?(jmaher) → review+
Keywords: checkin-needed
Whiteboard: [orange][android_tier_∞] [orange][android_tier_∞] → [orange][android_tier_∞] [keep open after check-in] [orange][android_tier_∞] [keep open after check-in]
(In reply to TinderboxPushlog Robot from comment #25)
> philor
> https://tbpl.mozilla.org/php/getParsedLog.php?id=10679686&tree=Mozilla-
> Inbound
> Android Tegra 250 mozilla-inbound opt test robocop on 2012-04-05 16:13:56

I noticed this in the log:

4-05 16:19:26.384 E/AndroidRuntime( 1411): FATAL EXCEPTION: Thread-40
04-05 16:19:26.384 E/AndroidRuntime( 1411): java.lang.IllegalArgumentException: data.length=65548 offset=0 count=1073800792
04-05 16:19:26.384 E/AndroidRuntime( 1411): 	at org.apache.harmony.luni.platform.OSNetworkSystem.read(OSNetworkSystem.java:354)
04-05 16:19:26.384 E/AndroidRuntime( 1411): 	at java.io.FileInputStream.available(FileInputStream.java:148)
04-05 16:19:26.384 E/AndroidRuntime( 1411): 	at com.mozilla.SUTAgentAndroid.service.RedirOutputThread.run(RedirOutputThread.java:110)

...probably deserves some attention.
Whiteboard: [orange][android_tier_∞] [keep open after check-in] [orange][android_tier_∞] [keep open after check-in] → [orange][android_tier_∞] [orange][android_tier_∞]
(In reply to Geoff Brown [:gbrown] from comment #26)
> I noticed this in the log:
> 
> 4-05 16:19:26.384 E/AndroidRuntime( 1411): FATAL EXCEPTION: Thread-40
> 04-05 16:19:26.384 E/AndroidRuntime( 1411):
> java.lang.IllegalArgumentException: data.length=65548 offset=0
> count=1073800792

...spun off bug 743766.
Depends on: 743766
Now that I'm looking for it, I see that bug 743766 is implicated in about 50% of these failures.
(In reply to TinderboxPushlog Robot from comment #46)
> philor
> https://tbpl.mozilla.org/php/getParsedLog.php?id=10945538&tree=Mozilla-
> Inbound
> Android Tegra 250 mozilla-inbound opt test robocop on 2012-04-16 11:57:00
> 
> TEST-UNEXPECTED-FAIL | Unable to copy profile to device. | Exception caught
> while running robocop tests.

This one has a different stack trace:

04-16 12:05:55.779 E/AndroidRuntime( 1453): FATAL EXCEPTION: CmdWorkerThread
04-16 12:05:55.779 E/AndroidRuntime( 1453): java.lang.NullPointerException
04-16 12:05:55.779 E/AndroidRuntime( 1453): 	at com.mozilla.SUTAgentAndroid.service.DoCommand.GetProcessInfo(DoCommand.java:2527)
04-16 12:05:55.779 E/AndroidRuntime( 1453): 	at com.mozilla.SUTAgentAndroid.service.DoCommand.processCommand(DoCommand.java:332)
04-16 12:05:55.779 E/AndroidRuntime( 1453): 	at com.mozilla.SUTAgentAndroid.service.CmdWorkerThread.run(CmdWorkerThread.java:164)

...spun of bug 745889.
Depends on: 745889
(In reply to TinderboxPushlog Robot from comment #140)
> philor
> https://tbpl.mozilla.org/php/getParsedLog.php?id=12014074&tree=Mozilla-
> Inbound

This one is interesting, but I don't know what to make of it:

05-23 21:53:04.036 W/dalvikvm( 1206): Implementation of Lcom/android/inputmethod/latin/LatinIME;.swipeUp is not public
05-23 21:53:04.036 W/dalvikvm( 1206): Link of class 'Lcom/android/inputmethod/latin/LatinIME;' failed
05-23 21:53:04.036 W/dalvikvm( 1206): threadid=1: thread exiting with uncaught exception (group=0x4001d820)
05-23 21:53:04.086 E/AndroidRuntime( 1206): FATAL EXCEPTION: main
05-23 21:53:04.086 E/AndroidRuntime( 1206): java.lang.IllegalAccessError: interface implementation not public
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at dalvik.system.DexFile.defineClass(Native Method)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at dalvik.system.DexFile.loadClassBinaryName(DexFile.java:209)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at dalvik.system.PathClassLoader.findClass(PathClassLoader.java:203)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at java.lang.ClassLoader.loadClass(ClassLoader.java:573)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at java.lang.ClassLoader.loadClass(ClassLoader.java:532)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at android.app.ActivityThread.handleCreateService(ActivityThread.java:2940)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at android.app.ActivityThread.access$3300(ActivityThread.java:125)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2087)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at android.os.Handler.dispatchMessage(Handler.java:99)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at android.os.Looper.loop(Looper.java:123)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at android.app.ActivityThread.main(ActivityThread.java:4627)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at java.lang.reflect.Method.invokeNative(Native Method)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at java.lang.reflect.Method.invoke(Method.java:521)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
05-23 21:53:04.086 E/AndroidRuntime( 1206): 	at dalvik.system.NativeStart.main(Native Method)

(the push was unrelated to input methods and sut agent was trying to cd at the time).
(In reply to TinderboxPushlog Robot from comment #143)
> edmorley
> https://tbpl.mozilla.org/php/getParsedLog.php?id=12065451&tree=Mozilla-
> Inbound

05-25 06:05:06.376 W/dalvikvm( 1330): JNI WARNING: illegal start byte 0xff
05-25 06:05:06.376 W/dalvikvm( 1330):              string: '������al.db'
05-25 06:05:06.376 W/dalvikvm( 1330):              in Ljava/io/File;.listImpl ([B)[Ljava/lang/String; (NewStringUTF)
05-25 06:05:06.386 E/dalvikvm( 1330): VM aborting
05-25 06:05:12.006 W/dalvikvm( 1496): JNI WARNING: illegal start byte 0xff
05-25 06:05:12.006 W/dalvikvm( 1496):              string: '������al.db'
05-25 06:05:12.006 W/dalvikvm( 1496):              in Ljava/io/File;.listImpl ([B)[Ljava/lang/String; (NewStringUTF)
05-25 06:05:12.006 E/dalvikvm( 1496): VM aborting
05-25 06:05:15.697 W/ActivityManager( 1017): Activity idle timeout for HistoryRecord{44589040 com.mozilla.SUTAgentAndroid/.SUTAgentAndroid}
05-25 06:05:32.536 W/dalvikvm( 1539): JNI WARNING: illegal start byte 0xff
05-25 06:05:32.536 W/dalvikvm( 1539):              string: '������al.db'
05-25 06:05:32.536 W/dalvikvm( 1539):              in Ljava/io/File;.listImpl ([B)[Ljava/lang/String; (NewStringUTF)
05-25 06:05:32.536 E/dalvikvm( 1539): VM aborting
Summary: Intermittent TEST-UNEXPECTED-FAIL | Unable to copy profile to device. | Exception caught while running robocop tests → Intermittent TEST-UNEXPECTED-FAIL | Unable to copy profile to device. | Exception caught while running tests
Many of the "Unable to copy profile" errors are associated with error 54 in SUT communication, which often indicates a device reboot (logcats in recent logs often show device boot messages during the test time range). See bug 772531.
Whiteboard: [orange][android_tier_∞] → [android_tier_∞]
https://tbpl.mozilla.org/php/getParsedLog.php?id=19534111&tree=Mozilla-Inbound
Summary: Intermittent TEST-UNEXPECTED-FAIL | Unable to copy profile to device. | Exception caught while running tests → Intermittent Automation Error: Unable to copy profile to device., Automation Error: Exception caught while running tests
Last instance of the failure in comment 0 was 2013-10-14, the rest since have been false positives.
Cleaning up summary and closing this out.
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
Summary: Intermittent Automation Error: Unable to copy profile to device., Automation Error: Exception caught while running tests → Intermittent Automation Error: Unable to copy profile to device.
Component: New Frameworks → General
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: