search

appium / appium

Cross-platform automation framework for all kinds of apps, built on top of the W3C WebDriver protocol
http://appium.io/
Apache License 2.0
18.63k stars 6.05k forks source link

set_network_connection command causes fatal race condition with multiple devices #4288

Closed yahman72 closed 2 years ago

yahman72 commented 9 years ago

Using set network connection (/wd/hub/session/.../network_connection) with two devices (=two appiums listening on different ports, using single adb instance = one port, see figure below) image

This causes a race condition between the appium instances. --> One of the instances looses all session data and starts responding with WebDriverException: Message: {"sessionId":null,"status":6,"value":""}

With a single device everything goes fine. Don't know how appium should behave but the following looks like a really weird in the logs: after every adb shell call the adb server is restarted with adb kill-server, is that correct? This eventually also leads to the race condition, because both appium instances keep killing and restarting the adb server....

Below are the logs from each appium instance.

Single Device Logs:

C:\tmptail -f app4724.log app4726.log
== app4724.log ==
2014-12-18 18:45:10:727 - info: Welcome to Appium v1.3.4 (REV c8c79a85fbd6870cd6fc3d66d038a115ebe22efe)
2014-12-18 18:45:10:727 - info: Appium REST http interface listener started on 0.0.0.0:4724
2014-12-18 18:45:10:727 - info: [debug] Non-default server args: {"port":4724,"bootstrapPort":4824,"sessionOverride":true,"log":"c:\\tmp\\app4724.log","logTimestamp":true,"localTimezone":true,"logNoColors":true,"androidDeviceReadyTimeout":"120","platformName":"Android","platformVersion":"19","automationName":"Appium","defaultCommandTimeout":1800}
2014-12-18 18:45:10:727 - info: Console LogLevel: debug
2014-12-18 18:45:10:727 - info: File LogLevel: debug

== app4726.log ==
2014-12-18 18:44:56:698 - info: Welcome to Appium v1.3.4 (REV c8c79a85fbd6870cd6fc3d66d038a115ebe22efe)
2014-12-18 18:44:56:698 - info: Appium REST http interface listener started on 0.0.0.0:4726
2014-12-18 18:44:56:698 - info: [debug] Non-default server args: {"port":4726,"bootstrapPort":4826,"sessionOverride":true,"log":"c:\\tmp\\app4726.log","logTimestamp":true,"localTimezone":true,"logNoColors":true,"androidDeviceReadyTimeout":"120","platformName":"Android","platformVersion":"19","automationName":"Appium","defaultCommandTimeout":1800}
2014-12-18 18:44:56:698 - info: Console LogLevel: debug
2014-12-18 18:44:56:698 - info: File LogLevel: debug
2014-12-18 18:45:26:521 - info: -- POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformName":"Android","appActivity":".DialerEntryActivity"}}
2014-12-18 18:45:26:521 - info: Client User-Agent string: Python-urllib/2.7
2014-12-18 18:45:26:537 - info: [debug] Didn't get app but did get Android package, will attempt to launch it on the device
2014-12-18 18:45:26:537 - info: [debug] Creating new appium session 12d10145-0938-4b23-8b21-b65d3e4fc311
2014-12-18 18:45:26:537 - info: Starting android appium
2014-12-18 18:45:26:537 - info: [debug] Getting Java version
2014-12-18 18:45:26:615 - info: Java version is: 1.7.0_45
2014-12-18 18:45:26:615 - info: [debug] Using fast reset? true
2014-12-18 18:45:26:615 - info: [debug] Preparing device for session
2014-12-18 18:45:26:615 - info: [debug] Not checking whether app is present since we are assuming it's already on the device
2014-12-18 18:45:26:615 - info: [debug] Checking whether adb is present
2014-12-18 18:45:26:615 - info: [debug] Using adb from C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe
2014-12-18 18:45:26:615 - info: Retrieving device
2014-12-18 18:45:26:615 - info: [debug] Trying to find a connected android device
2014-12-18 18:45:26:615 - info: [debug] Getting connected devices...
2014-12-18 18:45:26:615 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe devices
2014-12-18 18:45:26:662 - info: [debug] 3 device(s) connected
2014-12-18 18:45:26:662 - info: Found device CB5124VWNG
2014-12-18 18:45:26:662 - info: [debug] Setting device id to CB5124VWNG
2014-12-18 18:45:26:662 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:45:26:662 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG wait-for-device
2014-12-18 18:45:26:677 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "echo 'ready'"
2014-12-18 18:45:26:740 - info: [debug] Starting logcat capture
2014-12-18 18:45:26:802 - warn: No app capability, can't parse package/activity
2014-12-18 18:45:26:802 - info: [debug] Getting device API level
2014-12-18 18:45:26:802 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "getprop ro.build.version.sdk"
2014-12-18 18:45:26:896 - info: [debug] Device is at API Level 18
2014-12-18 18:45:26:896 - info: Device API level is: 18
2014-12-18 18:45:26:896 - info: [debug] Apk doesn't exist locally
2014-12-18 18:45:26:896 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "rm -rf /data/local/tmp/strings.json"
2014-12-18 18:45:26:974 - info: [debug] Not uninstalling app since server not started with --full-reset
2014-12-18 18:45:26:974 - info: [debug] Skipping install since we launched with a package instead of an app path
2014-12-18 18:45:26:974 - info: [debug] Forwarding system:4826 to device:4724
2014-12-18 18:45:26:974 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG forward tcp:4826 tcp:4724
2014-12-18 18:45:27:005 - info: [debug] Pushing appium bootstrap to device...
2014-12-18 18:45:27:005 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG push "C:\\tmp\\Appium-1.3.4.1\\node_modules\\appium\\build\\android_bootstrap\\AppiumBootstrap.jar" /data/local/tmp/
2014-12-18 18:45:27:036 - info: [debug] Pushing settings apk to device...
2014-12-18 18:45:27:036 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG install "C:\tmp\Appium-1.3.4.1\node_modules\appium\build\settings_apk\settings_apk-debug.apk"
2014-12-18 18:45:31:546 - info: [debug] Pushing unlock helper app to device...
2014-12-18 18:45:31:546 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG install "C:\tmp\Appium-1.3.4.1\node_modules\appium\build\unlock_apk\unlock_apk-debug.apk"
2014-12-18 18:45:32:919 - info: Starting App
2014-12-18 18:45:32:919 - info: [debug] Attempting to kill all 'uiautomator' processes
2014-12-18 18:45:32:919 - info: [debug] Getting all processes with 'uiautomator'
2014-12-18 18:45:32:919 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "ps 'uiautomator'"
2014-12-18 18:45:33:060 - info: [debug] No matching processes found
2014-12-18 18:45:33:060 - info: [debug] Running bootstrap
2014-12-18 18:45:33:060 - info: [debug] spawning: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap
2014-12-18 18:45:33:559 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:45:33:559 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:45:33:559 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:45:33:574 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:45:33:574 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap:
2014-12-18 18:45:33:574 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:45:33:574 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:45:33:574 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1
2014-12-18 18:45:33:590 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724
2014-12-18 18:45:33:590 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready
2014-12-18 18:45:33:590 - info: [debug] [BOOTSTRAP] [debug] Loading json...
2014-12-18 18:45:33:590 - info: [debug] Waking up device if it's not alive
2014-12-18 18:45:33:590 - info: [debug] Pushing command to appium work queue: ["wake",{}]
2014-12-18 18:45:33:590 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers.
2014-12-18 18:45:33:590 - info: [debug] [BOOTSTRAP] [debug] Client connected
2014-12-18 18:45:33:590 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"wake","params":{}}
2014-12-18 18:45:33:606 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:45:33:606 - info: [debug] [BOOTSTRAP] [debug] Got command action: wake
2014-12-18 18:45:33:606 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":true,"status":0}
2014-12-18 18:45:33:606 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "dumpsys window"
2014-12-18 18:45:33:715 - info: [debug] Screen already unlocked, continuing.
2014-12-18 18:45:33:715 - info: [debug] Pushing command to appium work queue: ["getDataDir",{}]
2014-12-18 18:45:33:715 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"getDataDir","params":{}}
2014-12-18 18:45:33:715 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:45:33:715 - info: [debug] [BOOTSTRAP] [debug] Got command action: getDataDir
2014-12-18 18:45:33:715 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":"\/data","status":0}
2014-12-18 18:45:33:715 - info: [debug] dataDir set to: /data
2014-12-18 18:45:33:715 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}]
2014-12-18 18:45:33:730 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}}
2014-12-18 18:45:33:730 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:45:33:730 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy
2014-12-18 18:45:33:730 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0}
2014-12-18 18:45:33:730 - info: [debug] Getting device API level
2014-12-18 18:45:33:730 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "getprop ro.build.version.sdk"
2014-12-18 18:45:33:777 - info: [debug] Device is at API Level 18
2014-12-18 18:45:33:777 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "am start -S -c android.intent.category.LAUNCHER -f 0x10200000 -n com.sonyericsson.android.socialphonebook/.DialerEntryActivity"
2014-12-18 18:45:34:916 - info: [debug] Waiting for pkg "com.sonyericsson.android.socialphonebook" and activity ".DialerEntryActivity" to be focused
2014-12-18 18:45:34:916 - info: [debug] Getting focused package and activity
2014-12-18 18:45:34:916 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "dumpsys window windows"
2014-12-18 18:45:35:103 - info: [debug] Device launched! Ready for commands
2014-12-18 18:45:35:103 - info: [debug] Setting command timeout to the default of 1800 secs
2014-12-18 18:45:35:103 - info: [debug] Appium session started with sessionId 12d10145-0938-4b23-8b21-b65d3e4fc311
2014-12-18 18:45:35:103 - info: -- POST /wd/hub/session 303 8577.343 ms - 9
2014-12-18 18:45:35:103 - info: -- GET /wd/hub/session/12d10145-0938-4b23-8b21-b65d3e4fc311 {}
2014-12-18 18:45:35:103 - info: [debug] Responding to client with success: {"status":0,"value":{"platform":"LINUX","browserName":"Android","platformVersion":"4.4","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook
","platformName":"Android","appActivity":".DialerEntryActivity"},"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformName":"Android","appActivity":".DialerEntryActivity"},"sessionId":"12d10145-0938-4b23-8b21-b65d3e4fc311"}
2014-12-18 18:45:35:119 - info: -- GET /wd/hub/session/12d10145-0938-4b23-8b21-b65d3e4fc311 200 4.367 ms - 757 {"status":0,"value":{"platform":"LINUX","browserName":"Android","platformVersion":"4.4","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com
.sonyericsson.android.socialphonebook","platformName":"Android","appActivity":".DialerEntryActivity"},"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformName":"Android","appActivity":".DialerEntryActivity"},"sessionId":"12d10145-0938-4b23-8b21-b65d3e4fc311"}
2014-12-18 18:45:35:134 - info: -- POST /wd/hub/session/12d10145-0938-4b23-8b21-b65d3e4fc311/network_connection {"sessionId":"12d10145-0938-4b23-8b21-b65d3e4fc311","parameters":{"type":0}}
2014-12-18 18:45:35:134 - info: Setting network connection
2014-12-18 18:45:35:134 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "settings put global airplane_mode_on 0"
2014-12-18 18:45:35:743 - info: [debug] Stopping logcat capture
2014-12-18 18:45:35:743 - info: [debug] Logcat terminated with code null, signal SIGTERM
2014-12-18 18:45:35:743 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG kill-server
2014-12-18 18:45:35:790 - error: Unhandled error: Error: read ECONNRESET
    at errnoException (net.js:904:11)
    at TCP.onread (net.js:558:19) context: [POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformNa]
2014-12-18 18:45:35:790 - info: [debug] UiAutomator exited
2014-12-18 18:45:35:790 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:45:35:790 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG wait-for-device
2014-12-18 18:45:39:846 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "echo 'ready'"
2014-12-18 18:45:39:908 - info: [debug] Starting logcat capture
2014-12-18 18:45:39:955 - info: [debug] Forwarding system:4826 to device:4724
2014-12-18 18:45:39:955 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG forward tcp:4826 tcp:4724
2014-12-18 18:45:39:986 - info: Starting App
2014-12-18 18:45:39:986 - info: [debug] Attempting to kill all 'uiautomator' processes
2014-12-18 18:45:39:986 - info: [debug] Getting all processes with 'uiautomator'
2014-12-18 18:45:39:986 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "ps 'uiautomator'"
2014-12-18 18:45:40:142 - info: [debug] No matching processes found
2014-12-18 18:45:40:142 - info: [debug] Running bootstrap
2014-12-18 18:45:40:142 - info: [debug] spawning: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap
2014-12-18 18:45:40:594 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:45:40:594 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:45:40:594 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:45:40:594 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:45:40:594 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap:
2014-12-18 18:45:40:594 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:45:40:594 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:45:40:594 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1
2014-12-18 18:45:40:626 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724
2014-12-18 18:45:40:626 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready
2014-12-18 18:45:40:626 - info: [debug] [BOOTSTRAP] [debug] Loading json...
2014-12-18 18:45:40:626 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}]
2014-12-18 18:45:40:626 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers.
2014-12-18 18:45:40:626 - info: [debug] [BOOTSTRAP] [debug] Client connected
2014-12-18 18:45:40:626 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}}
2014-12-18 18:45:40:641 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:45:40:641 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy
2014-12-18 18:45:40:641 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0}
2014-12-18 18:45:40:641 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "am broadcast -a android.intent.action.AIRPLANE_MODE --ez state false"
2014-12-18 18:45:41:390 - info: [debug] Stopping logcat capture
2014-12-18 18:45:41:406 - info: [debug] Logcat terminated with code null, signal SIGTERM
2014-12-18 18:45:41:406 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG kill-server
2014-12-18 18:45:41:437 - error: Unhandled error: Error: read ECONNRESET
    at errnoException (net.js:904:11)
    at TCP.onread (net.js:558:19) context: [POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformNa]
2014-12-18 18:45:41:437 - info: [debug] UiAutomator exited
2014-12-18 18:45:41:437 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:45:41:437 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG wait-for-device
2014-12-18 18:45:45:528 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "echo 'ready'"
2014-12-18 18:45:45:606 - info: [debug] Starting logcat capture
2014-12-18 18:45:45:653 - info: [debug] Forwarding system:4826 to device:4724
2014-12-18 18:45:45:653 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG forward tcp:4826 tcp:4724
2014-12-18 18:45:45:700 - info: Starting App
2014-12-18 18:45:45:700 - info: [debug] Attempting to kill all 'uiautomator' processes
2014-12-18 18:45:45:700 - info: [debug] Getting all processes with 'uiautomator'
2014-12-18 18:45:45:700 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "ps 'uiautomator'"
2014-12-18 18:45:45:809 - info: [debug] No matching processes found
2014-12-18 18:45:45:809 - info: [debug] Running bootstrap
2014-12-18 18:45:45:809 - info: [debug] spawning: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap
2014-12-18 18:45:46:277 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:45:46:277 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:45:46:277 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:45:46:277 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:45:46:277 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap:
2014-12-18 18:45:46:277 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:45:46:277 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:45:46:277 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1
2014-12-18 18:45:46:308 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724
2014-12-18 18:45:46:324 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready
2014-12-18 18:45:46:324 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}]
2014-12-18 18:45:46:324 - info: [debug] [BOOTSTRAP] [debug] Loading json...
2014-12-18 18:45:46:324 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers.
2014-12-18 18:45:46:324 - info: [debug] [BOOTSTRAP] [debug] Client connected
2014-12-18 18:45:46:324 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}}
2014-12-18 18:45:46:339 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:45:46:339 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy
2014-12-18 18:45:46:339 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0}
2014-12-18 18:45:46:339 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "am start -n io.appium.settings/.Settings -e wifi off -e data off"
2014-12-18 18:45:47:197 - info: [debug] Stopping logcat capture
2014-12-18 18:45:47:197 - info: [debug] Logcat terminated with code null, signal SIGTERM
2014-12-18 18:45:47:197 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG kill-server
2014-12-18 18:45:47:244 - error: Unhandled error: Error: read ECONNRESET
    at errnoException (net.js:904:11)
    at TCP.onread (net.js:558:19) context: [POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformNa]
2014-12-18 18:45:47:244 - info: [debug] UiAutomator exited
2014-12-18 18:45:47:244 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:45:47:244 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG wait-for-device
2014-12-18 18:45:51:333 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "echo 'ready'"
2014-12-18 18:45:51:411 - info: [debug] Starting logcat capture
2014-12-18 18:45:51:474 - info: [debug] Forwarding system:4826 to device:4724
2014-12-18 18:45:51:474 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG forward tcp:4826 tcp:4724
2014-12-18 18:45:51:520 - info: Starting App
2014-12-18 18:45:51:520 - info: [debug] Attempting to kill all 'uiautomator' processes
2014-12-18 18:45:51:520 - info: [debug] Getting all processes with 'uiautomator'
2014-12-18 18:45:51:520 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "ps 'uiautomator'"
2014-12-18 18:45:51:676 - info: [debug] No matching processes found
2014-12-18 18:45:51:676 - info: [debug] Running bootstrap
2014-12-18 18:45:51:676 - info: [debug] spawning: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap
2014-12-18 18:45:52:160 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:45:52:160 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:45:52:160 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:45:52:176 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:45:52:176 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap:
2014-12-18 18:45:52:176 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:45:52:176 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:45:52:176 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1
2014-12-18 18:45:52:207 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724
2014-12-18 18:45:52:207 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready
2014-12-18 18:45:52:207 - info: [debug] [BOOTSTRAP] [debug] Loading json...
2014-12-18 18:45:52:207 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}]
2014-12-18 18:45:52:207 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers.
2014-12-18 18:45:52:207 - info: [debug] [BOOTSTRAP] [debug] Client connected
2014-12-18 18:45:52:207 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}}
2014-12-18 18:45:52:207 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:45:52:207 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy
2014-12-18 18:45:52:207 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0}
2014-12-18 18:45:52:207 - info: Getting network connection
2014-12-18 18:45:52:207 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "settings get global airplane_mode_on"
2014-12-18 18:45:52:909 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "settings get global wifi_on"
2014-12-18 18:45:53:548 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "settings get global mobile_data"
2014-12-18 18:45:54:297 - info: [debug] Responding to client with success: {"status":0,"value":4,"sessionId":"12d10145-0938-4b23-8b21-b65d3e4fc311"}
2014-12-18 18:45:54:297 - info: -- POST /wd/hub/session/12d10145-0938-4b23-8b21-b65d3e4fc311/network_connection 200 19165.962 ms - 73 {"status":0,"value":4,"sessionId":"12d10145-0938-4b23-8b21-b65d3e4fc311"}
2014-12-18 18:45:54:313 - info: -- DELETE /wd/hub/session/12d10145-0938-4b23-8b21-b65d3e4fc311 {}
2014-12-18 18:45:54:313 - info: Shutting down appium session
2014-12-18 18:45:54:313 - info: [debug] Pressing the HOME button
2014-12-18 18:45:54:313 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "input keyevent 3"
2014-12-18 18:45:55:124 - info: [debug] Stopping logcat capture
2014-12-18 18:45:55:124 - info: [debug] Logcat terminated with code null, signal SIGTERM
2014-12-18 18:45:55:140 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"shutdown"}
2014-12-18 18:45:55:140 - info: [debug] [BOOTSTRAP] [debug] Got command of type SHUTDOWN
2014-12-18 18:45:55:140 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":"OK, shutting down","status":0}
2014-12-18 18:45:55:140 - info: [debug] [BOOTSTRAP] [debug] Closed client connection
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=.
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 0
2014-12-18 18:45:55:140 - info: [debug] Sent shutdown command, waiting for UiAutomator to stop...
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] Test results for WatcherResultPrinter=.
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] Time: 3.039
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] OK (1 test)
2014-12-18 18:45:55:140 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: -1
2014-12-18 18:45:55:140 - info: [debug] UiAutomator shut down normally
2014-12-18 18:45:55:140 - info: [debug] Cleaning up android objects
2014-12-18 18:45:55:140 - info: [debug] Cleaning up appium session
2014-12-18 18:45:55:140 - info: [debug] Responding to client with success: {"status":0,"value":null,"sessionId":"12d10145-0938-4b23-8b21-b65d3e4fc311"}
2014-12-18 18:45:55:140 - info: -- DELETE /wd/hub/session/12d10145-0938-4b23-8b21-b65d3e4fc311 200 841.744 ms - 76 {"status":0,"value":null,"sessionId":"12d10145-0938-4b23-8b21-b65d3e4fc311"}

Two Devices Logs:


C:\tmptail -f app4724.log app4726.log
== app4724.log ==
2014-12-18 18:46:30:548 - info: Welcome to Appium v1.3.4 (REV c8c79a85fbd6870cd6fc3d66d038a115ebe22efe)
2014-12-18 18:46:30:548 - info: Appium REST http interface listener started on 0.0.0.0:4724
2014-12-18 18:46:30:548 - info: [debug] Non-default server args: {"port":4724,"bootstrapPort":4824,"sessionOverride":true,"log":"c:\\tmp\\app4724.log","logTimestamp":true,"localTimezone":true,"logNoColors":true,"androidDeviceReadyTimeout":"120","platformName":"Android","platformVersion":"19","automationName":"Appium","defaultCommandTimeout":1800}
2014-12-18 18:46:30:548 - info: Console LogLevel: debug
2014-12-18 18:46:30:548 - info: File LogLevel: debug

== app4726.log ==
2014-12-18 18:46:31:765 - info: Welcome to Appium v1.3.4 (REV c8c79a85fbd6870cd6fc3d66d038a115ebe22efe)
2014-12-18 18:46:31:765 - info: Appium REST http interface listener started on 0.0.0.0:4726
2014-12-18 18:46:31:765 - info: [debug] Non-default server args: {"port":4726,"bootstrapPort":4826,"sessionOverride":true,"log":"c:\\tmp\\app4726.log","logTimestamp":true,"localTimezone":true,"logNoColors":true,"androidDeviceReadyTimeout":"120","platformName":"Android","platformVersion":"19","automationName":"Appium","defaultCommandTimeout":1800}
2014-12-18 18:46:31:765 - info: Console LogLevel: debug
2014-12-18 18:46:31:765 - info: File LogLevel: debug

== app4724.log ==
2014-12-18 18:46:50:745 - info: -- POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB1","udid":"d81e91ba","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.android.contacts","platformName":"Android","appActivity":".activities.DialtactsActivity"}}
2014-12-18 18:46:50:745 - info: Client User-Agent string: Python-urllib/2.7
2014-12-18 18:46:50:745 - info: [debug] Didn't get app but did get Android package, will attempt to launch it on the device
2014-12-18 18:46:50:745 - info: [debug] Creating new appium session 393f3fe2-253e-4704-8d47-cbe033b533e0
2014-12-18 18:46:50:745 - info: Starting android appium
2014-12-18 18:46:50:745 - info: [debug] Getting Java version
2014-12-18 18:46:50:807 - info: Java version is: 1.7.0_45
2014-12-18 18:46:50:807 - info: [debug] Using fast reset? true
2014-12-18 18:46:50:807 - info: [debug] Preparing device for session
2014-12-18 18:46:50:807 - info: [debug] Not checking whether app is present since we are assuming it's already on the device
2014-12-18 18:46:50:807 - info: [debug] Checking whether adb is present
2014-12-18 18:46:50:807 - info: [debug] Using adb from C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe
2014-12-18 18:46:50:807 - info: Retrieving device
2014-12-18 18:46:50:807 - info: [debug] Trying to find a connected android device
2014-12-18 18:46:50:807 - info: [debug] Getting connected devices...
2014-12-18 18:46:50:807 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe devices
2014-12-18 18:46:50:838 - info: [debug] 3 device(s) connected
2014-12-18 18:46:50:838 - info: Found device d81e91ba
2014-12-18 18:46:50:838 - info: [debug] Setting device id to d81e91ba
2014-12-18 18:46:50:838 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:46:50:838 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba wait-for-device
2014-12-18 18:46:50:854 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "echo 'ready'"
2014-12-18 18:46:50:932 - info: [debug] Starting logcat capture
2014-12-18 18:46:50:963 - warn: No app capability, can't parse package/activity
2014-12-18 18:46:50:963 - info: [debug] Getting device API level
2014-12-18 18:46:50:963 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "getprop ro.build.version.sdk"
2014-12-18 18:46:51:072 - info: [debug] Device is at API Level 18
2014-12-18 18:46:51:072 - info: Device API level is: 18
2014-12-18 18:46:51:072 - info: [debug] Apk doesn't exist locally
2014-12-18 18:46:51:072 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "rm -rf /data/local/tmp/strings.json"
2014-12-18 18:46:51:119 - info: [debug] Not uninstalling app since server not started with --full-reset
2014-12-18 18:46:51:119 - info: [debug] Skipping install since we launched with a package instead of an app path
2014-12-18 18:46:51:119 - info: [debug] Forwarding system:4824 to device:4724
2014-12-18 18:46:51:119 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba forward tcp:4824 tcp:4724
2014-12-18 18:46:51:150 - info: [debug] Pushing appium bootstrap to device...
2014-12-18 18:46:51:150 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba push "C:\\tmp\\Appium-1.3.4.1\\node_modules\\appium\\build\\android_bootstrap\\AppiumBootstrap.jar" /data/local/tmp/
2014-12-18 18:46:51:197 - info: [debug] Pushing settings apk to device...
2014-12-18 18:46:51:197 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba install "C:\tmp\Appium-1.3.4.1\node_modules\appium\build\settings_apk\settings_apk-debug.apk"
2014-12-18 18:46:53:569 - info: [debug] Pushing unlock helper app to device...
2014-12-18 18:46:53:585 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba install "C:\tmp\Appium-1.3.4.1\node_modules\appium\build\unlock_apk\unlock_apk-debug.apk"
2014-12-18 18:46:54:817 - info: Starting App
2014-12-18 18:46:54:817 - info: [debug] Attempting to kill all 'uiautomator' processes
2014-12-18 18:46:54:817 - info: [debug] Getting all processes with 'uiautomator'
2014-12-18 18:46:54:817 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "ps 'uiautomator'"
2014-12-18 18:46:54:958 - info: [debug] No matching processes found
2014-12-18 18:46:54:958 - info: [debug] Running bootstrap
2014-12-18 18:46:54:958 - info: [debug] spawning: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap
2014-12-18 18:46:55:831 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:46:55:847 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:46:55:847 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:46:55:847 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:46:55:847 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap:
2014-12-18 18:46:55:847 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:46:55:847 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:46:55:847 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1
2014-12-18 18:46:55:863 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724
2014-12-18 18:46:55:863 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready
2014-12-18 18:46:55:863 - info: [debug] [BOOTSTRAP] [debug] Loading json...
2014-12-18 18:46:55:863 - info: [debug] Waking up device if it's not alive
2014-12-18 18:46:55:863 - info: [debug] Pushing command to appium work queue: ["wake",{}]
2014-12-18 18:46:55:863 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers.
2014-12-18 18:46:55:863 - info: [debug] [BOOTSTRAP] [debug] Client connected
2014-12-18 18:46:55:863 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"wake","params":{}}
2014-12-18 18:46:55:878 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:46:55:878 - info: [debug] [BOOTSTRAP] [debug] Got command action: wake
2014-12-18 18:46:55:878 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":true,"status":0}
2014-12-18 18:46:55:878 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "dumpsys window"
2014-12-18 18:46:56:081 - info: [debug] Screen already unlocked, continuing.
2014-12-18 18:46:56:081 - info: [debug] Pushing command to appium work queue: ["getDataDir",{}]
2014-12-18 18:46:56:097 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"getDataDir","params":{}}
2014-12-18 18:46:56:097 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:46:56:097 - info: [debug] [BOOTSTRAP] [debug] Got command action: getDataDir
2014-12-18 18:46:56:097 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":"\/data\/local\/tmp","status":0}
2014-12-18 18:46:56:097 - info: [debug] dataDir set to: /data/local/tmp
2014-12-18 18:46:56:097 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}]
2014-12-18 18:46:56:097 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}}
2014-12-18 18:46:56:097 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:46:56:097 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy
2014-12-18 18:46:56:097 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0}
2014-12-18 18:46:56:097 - info: [debug] Getting device API level
2014-12-18 18:46:56:097 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "getprop ro.build.version.sdk"
2014-12-18 18:46:56:143 - info: [debug] Device is at API Level 18
2014-12-18 18:46:56:143 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "am start -S -c android.intent.category.LAUNCHER -f 0x10200000 -n com.android.contacts/.activities.DialtactsActivity"
2014-12-18 18:46:57:501 - info: [debug] Waiting for pkg "com.android.contacts" and activity ".activities.DialtactsActivity" to be focused
2014-12-18 18:46:57:501 - info: [debug] Getting focused package and activity
2014-12-18 18:46:57:501 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "dumpsys window windows"
2014-12-18 18:46:57:703 - info: [debug] Device launched! Ready for commands
2014-12-18 18:46:57:703 - info: [debug] Setting command timeout to the default of 1800 secs
2014-12-18 18:46:57:703 - info: [debug] Appium session started with sessionId 393f3fe2-253e-4704-8d47-cbe033b533e0
2014-12-18 18:46:57:703 - info: -- POST /wd/hub/session 303 6970.196 ms - 9
2014-12-18 18:46:57:719 - info: -- GET /wd/hub/session/393f3fe2-253e-4704-8d47-cbe033b533e0 {}
2014-12-18 18:46:57:719 - info: [debug] Responding to client with success: {"status":0,"value":{"platform":"LINUX","browserName":"Android","platformVersion":"4.4","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"deviceName":"MsB1","udid":"d81e91ba","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.android.contacts","platformName":"Andr
oid","appActivity":".activities.DialtactsActivity"},"deviceName":"MsB1","udid":"d81e91ba","appWaitActivity":false,"intentAction":false,"appPackage":"com.android.contacts","platformName":"Android","appActivity":".activities.DialtactsActivity"},"sessionId":"393f3fe2-253e-4704-8d47-cbe033b533e0"}
2014-12-18 18:46:57:719 - info: -- GET /wd/hub/session/393f3fe2-253e-4704-8d47-cbe033b533e0 200 4.119 ms - 731 {"status":0,"value":{"platform":"LINUX","browserName":"Android","platformVersion":"4.4","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"deviceName":"MsB1","udid":"d81e91ba","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.a
ndroid.contacts","platformName":"Android","appActivity":".activities.DialtactsActivity"},"deviceName":"MsB1","udid":"d81e91ba","appWaitActivity":false,"intentAction":false,"appPackage":"com.android.contacts","platformName":"Android","appActivity":".activities.DialtactsActivity"},"sessionId":"393f3fe2-253e-4704-8d47-cbe033b533e0"}

== app4726.log ==
2014-12-18 18:46:57:765 - info: -- POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformName":"Android","appActivity":".DialerEntryActivity"}}
2014-12-18 18:46:57:765 - info: Client User-Agent string: Python-urllib/2.7
2014-12-18 18:46:57:765 - info: [debug] Didn't get app but did get Android package, will attempt to launch it on the device
2014-12-18 18:46:57:765 - info: [debug] Creating new appium session ff1a24e4-9409-4400-9fbc-a5e8984f9211
2014-12-18 18:46:57:765 - info: Starting android appium
2014-12-18 18:46:57:765 - info: [debug] Getting Java version
2014-12-18 18:46:57:828 - info: Java version is: 1.7.0_45
2014-12-18 18:46:57:828 - info: [debug] Using fast reset? true
2014-12-18 18:46:57:828 - info: [debug] Preparing device for session
2014-12-18 18:46:57:828 - info: [debug] Not checking whether app is present since we are assuming it's already on the device
2014-12-18 18:46:57:828 - info: [debug] Checking whether adb is present
2014-12-18 18:46:57:828 - info: [debug] Using adb from C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe
2014-12-18 18:46:57:828 - info: Retrieving device
2014-12-18 18:46:57:828 - info: [debug] Trying to find a connected android device
2014-12-18 18:46:57:828 - info: [debug] Getting connected devices...
2014-12-18 18:46:57:843 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe devices
2014-12-18 18:46:57:859 - info: [debug] 3 device(s) connected
2014-12-18 18:46:57:859 - info: Found device CB5124VWNG
2014-12-18 18:46:57:859 - info: [debug] Setting device id to CB5124VWNG
2014-12-18 18:46:57:859 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:46:57:859 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG wait-for-device
2014-12-18 18:46:57:890 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "echo 'ready'"
2014-12-18 18:46:57:953 - info: [debug] Starting logcat capture
2014-12-18 18:46:57:999 - warn: No app capability, can't parse package/activity
2014-12-18 18:46:57:999 - info: [debug] Getting device API level
2014-12-18 18:46:57:999 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "getprop ro.build.version.sdk"
2014-12-18 18:46:58:077 - info: [debug] Device is at API Level 18
2014-12-18 18:46:58:077 - info: Device API level is: 18
2014-12-18 18:46:58:077 - info: [debug] Apk doesn't exist locally
2014-12-18 18:46:58:077 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "rm -rf /data/local/tmp/strings.json"
2014-12-18 18:46:58:109 - info: [debug] Not uninstalling app since server not started with --full-reset
2014-12-18 18:46:58:109 - info: [debug] Skipping install since we launched with a package instead of an app path
2014-12-18 18:46:58:109 - info: [debug] Forwarding system:4826 to device:4724
2014-12-18 18:46:58:109 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG forward tcp:4826 tcp:4724
2014-12-18 18:46:58:140 - info: [debug] Pushing appium bootstrap to device...
2014-12-18 18:46:58:140 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG push "C:\\tmp\\Appium-1.3.4.1\\node_modules\\appium\\build\\android_bootstrap\\AppiumBootstrap.jar" /data/local/tmp/
2014-12-18 18:46:58:171 - info: [debug] Pushing settings apk to device...
2014-12-18 18:46:58:171 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG install "C:\tmp\Appium-1.3.4.1\node_modules\appium\build\settings_apk\settings_apk-debug.apk"
2014-12-18 18:47:00:090 - info: [debug] Pushing unlock helper app to device...
2014-12-18 18:47:00:090 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG install "C:\tmp\Appium-1.3.4.1\node_modules\appium\build\unlock_apk\unlock_apk-debug.apk"
2014-12-18 18:47:01:541 - info: Starting App
2014-12-18 18:47:01:541 - info: [debug] Attempting to kill all 'uiautomator' processes
2014-12-18 18:47:01:556 - info: [debug] Getting all processes with 'uiautomator'
2014-12-18 18:47:01:556 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "ps 'uiautomator'"
2014-12-18 18:47:01:681 - info: [debug] No matching processes found
2014-12-18 18:47:01:681 - info: [debug] Running bootstrap
2014-12-18 18:47:01:681 - info: [debug] spawning: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap
2014-12-18 18:47:02:149 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:47:02:149 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:47:02:149 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:47:02:149 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:47:02:149 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap:
2014-12-18 18:47:02:149 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:47:02:149 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:47:02:149 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1
2014-12-18 18:47:02:165 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724
2014-12-18 18:47:02:165 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready
2014-12-18 18:47:02:165 - info: [debug] [BOOTSTRAP] [debug] Loading json...
2014-12-18 18:47:02:165 - info: [debug] Waking up device if it's not alive
2014-12-18 18:47:02:165 - info: [debug] Pushing command to appium work queue: ["wake",{}]
2014-12-18 18:47:02:165 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers.
2014-12-18 18:47:02:165 - info: [debug] [BOOTSTRAP] [debug] Client connected
2014-12-18 18:47:02:165 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"wake","params":{}}
2014-12-18 18:47:02:180 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:47:02:180 - info: [debug] [BOOTSTRAP] [debug] Got command action: wake
2014-12-18 18:47:02:180 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":true,"status":0}
2014-12-18 18:47:02:180 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "dumpsys window"
2014-12-18 18:47:02:274 - info: [debug] Screen already unlocked, continuing.
2014-12-18 18:47:02:274 - info: [debug] Pushing command to appium work queue: ["getDataDir",{}]
2014-12-18 18:47:02:289 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"getDataDir","params":{}}
2014-12-18 18:47:02:289 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:47:02:289 - info: [debug] [BOOTSTRAP] [debug] Got command action: getDataDir
2014-12-18 18:47:02:289 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":"\/data","status":0}
2014-12-18 18:47:02:289 - info: [debug] dataDir set to: /data
2014-12-18 18:47:02:289 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}]
2014-12-18 18:47:02:289 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}}
2014-12-18 18:47:02:289 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:47:02:289 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy
2014-12-18 18:47:02:289 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0}
2014-12-18 18:47:02:289 - info: [debug] Getting device API level
2014-12-18 18:47:02:289 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "getprop ro.build.version.sdk"
2014-12-18 18:47:02:352 - info: [debug] Device is at API Level 18
2014-12-18 18:47:02:352 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "am start -S -c android.intent.category.LAUNCHER -f 0x10200000 -n com.sonyericsson.android.socialphonebook/.DialerEntryActivity"
2014-12-18 18:47:03:506 - info: [debug] Waiting for pkg "com.sonyericsson.android.socialphonebook" and activity ".DialerEntryActivity" to be focused
2014-12-18 18:47:03:506 - info: [debug] Getting focused package and activity
2014-12-18 18:47:03:506 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "dumpsys window windows"
2014-12-18 18:47:03:678 - info: [debug] Device launched! Ready for commands
2014-12-18 18:47:03:693 - info: [debug] Setting command timeout to the default of 1800 secs
2014-12-18 18:47:03:693 - info: [debug] Appium session started with sessionId ff1a24e4-9409-4400-9fbc-a5e8984f9211
2014-12-18 18:47:03:693 - info: -- POST /wd/hub/session 303 5926.272 ms - 9
2014-12-18 18:47:03:693 - info: -- GET /wd/hub/session/ff1a24e4-9409-4400-9fbc-a5e8984f9211 {}
2014-12-18 18:47:03:693 - info: [debug] Responding to client with success: {"status":0,"value":{"platform":"LINUX","browserName":"Android","platformVersion":"4.4","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook
","platformName":"Android","appActivity":".DialerEntryActivity"},"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformName":"Android","appActivity":".DialerEntryActivity"},"sessionId":"ff1a24e4-9409-4400-9fbc-a5e8984f9211"}
2014-12-18 18:47:03:693 - info: -- GET /wd/hub/session/ff1a24e4-9409-4400-9fbc-a5e8984f9211 200 4.285 ms - 757 {"status":0,"value":{"platform":"LINUX","browserName":"Android","platformVersion":"4.4","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com
.sonyericsson.android.socialphonebook","platformName":"Android","appActivity":".DialerEntryActivity"},"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformName":"Android","appActivity":".DialerEntryActivity"},"sessionId":"ff1a24e4-9409-4400-9fbc-a5e8984f9211"}

== app4724.log ==
2014-12-18 18:47:03:725 - info: -- POST /wd/hub/session/393f3fe2-253e-4704-8d47-cbe033b533e0/network_connection {"sessionId":"393f3fe2-253e-4704-8d47-cbe033b533e0","parameters":{"type":0}}
2014-12-18 18:47:03:725 - info: Setting network connection
2014-12-18 18:47:03:725 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "settings put global airplane_mode_on 0"
2014-12-18 18:47:04:663 - info: [debug] Stopping logcat capture
2014-12-18 18:47:04:663 - info: [debug] Logcat terminated with code null, signal SIGTERM
2014-12-18 18:47:04:663 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba kill-server
2014-12-18 18:47:04:694 - error: Unhandled error: Error: read ECONNRESET
    at errnoException (net.js:904:11)
    at TCP.onread (net.js:558:19) context: [POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB1","udid":"d81e91ba","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.android.contacts","platformName":"Android","appActi]
2014-12-18 18:47:04:694 - info: [debug] UiAutomator exited
2014-12-18 18:47:04:710 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:47:04:710 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba wait-for-device

== app4726.log ==
2014-12-18 18:47:04:694 - error: Unhandled error: Error: read ECONNRESET
    at errnoException (net.js:904:11)
    at TCP.onread (net.js:558:19) context: [POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB3","udid":"CB5124VWNG","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.sonyericsson.android.socialphonebook","platformNa]
2014-12-18 18:47:04:694 - info: [debug] Logcat terminated with code 0, signal null
2014-12-18 18:47:04:694 - info: [debug] UiAutomator exited
2014-12-18 18:47:04:694 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "echo 'ping'"
2014-12-18 18:47:05:770 - info: [debug] Error: spawn OK
2014-12-18 18:47:05:770 - info: [debug] Stopping logcat capture
2014-12-18 18:47:05:770 - info: [debug] Logcat already stopped
2014-12-18 18:47:05:770 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG kill-server
2014-12-18 18:47:05:833 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:47:05:833 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG wait-for-device

== app4724.log ==
2014-12-18 18:47:08:766 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "echo 'ready'"
2014-12-18 18:47:08:828 - info: [debug] Starting logcat capture
2014-12-18 18:47:08:859 - info: [debug] Forwarding system:4824 to device:4724
2014-12-18 18:47:08:859 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba forward tcp:4824 tcp:4724
2014-12-18 18:47:08:891 - info: Starting App
2014-12-18 18:47:08:906 - info: [debug] Attempting to kill all 'uiautomator' processes
2014-12-18 18:47:08:906 - info: [debug] Getting all processes with 'uiautomator'
2014-12-18 18:47:08:906 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "ps 'uiautomator'"
2014-12-18 18:47:09:078 - info: [debug] No matching processes found
2014-12-18 18:47:09:078 - info: [debug] Running bootstrap
2014-12-18 18:47:09:078 - info: [debug] spawning: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap
2014-12-18 18:47:09:842 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:47:09:842 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:47:09:842 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:47:09:842 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:47:09:842 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap:
2014-12-18 18:47:09:842 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:47:09:842 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:47:09:842 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1
2014-12-18 18:47:09:873 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724
2014-12-18 18:47:09:873 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready
2014-12-18 18:47:09:873 - info: [debug] [BOOTSTRAP] [debug] Loading json...
2014-12-18 18:47:09:873 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}]
2014-12-18 18:47:09:873 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers.
2014-12-18 18:47:09:873 - info: [debug] [BOOTSTRAP] [debug] Client connected
2014-12-18 18:47:09:873 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}}
2014-12-18 18:47:09:873 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:47:09:873 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy
2014-12-18 18:47:09:873 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0}
2014-12-18 18:47:09:873 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "am broadcast -a android.intent.action.AIRPLANE_MODE --ez state false"

== app4726.log ==
2014-12-18 18:47:09:920 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s CB5124VWNG shell "echo 'ready'"
2014-12-18 18:47:09:982 - info: [debug] Starting logcat capture
2014-12-18 18:47:10:045 - info: [debug] Attempting to uninstall app
2014-12-18 18:47:10:045 - info: [debug] Not uninstalling app since server not started with --full-reset
2014-12-18 18:47:10:045 - info: [debug] Cleaning up android objects
2014-12-18 18:47:10:045 - info: [debug] Cleaning up appium session

== app4724.log ==
2014-12-18 18:47:11:761 - info: [debug] Stopping logcat capture
2014-12-18 18:47:11:761 - info: [debug] Logcat terminated with code null, signal SIGTERM
2014-12-18 18:47:11:761 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba kill-server
2014-12-18 18:47:11:808 - error: Unhandled error: Error: read ECONNRESET
    at errnoException (net.js:904:11)
    at TCP.onread (net.js:558:19) context: [POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB1","udid":"d81e91ba","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.android.contacts","platformName":"Android","appActi]
2014-12-18 18:47:11:808 - info: [debug] UiAutomator exited
2014-12-18 18:47:11:808 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:47:11:808 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba wait-for-device

== app4726.log ==
2014-12-18 18:47:11:807 - info: [debug] Logcat terminated with code 0, signal null

== app4724.log ==
2014-12-18 18:47:15:895 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "echo 'ready'"
2014-12-18 18:47:15:942 - info: [debug] Starting logcat capture
2014-12-18 18:47:15:957 - info: [debug] Forwarding system:4824 to device:4724
2014-12-18 18:47:15:957 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba forward tcp:4824 tcp:4724
2014-12-18 18:47:15:973 - info: Starting App
2014-12-18 18:47:15:973 - info: [debug] Attempting to kill all 'uiautomator' processes
2014-12-18 18:47:15:973 - info: [debug] Getting all processes with 'uiautomator'
2014-12-18 18:47:15:973 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "ps 'uiautomator'"
2014-12-18 18:47:16:098 - info: [debug] No matching processes found
2014-12-18 18:47:16:098 - info: [debug] Running bootstrap
2014-12-18 18:47:16:098 - info: [debug] spawning: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap
2014-12-18 18:47:16:833 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:47:16:833 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:47:16:833 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:47:16:833 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:47:16:833 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap:
2014-12-18 18:47:16:833 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:47:16:833 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:47:16:833 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1
2014-12-18 18:47:16:849 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724
2014-12-18 18:47:16:849 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready
2014-12-18 18:47:16:849 - info: [debug] [BOOTSTRAP] [debug] Loading json...
2014-12-18 18:47:16:849 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}]
2014-12-18 18:47:16:849 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers.
2014-12-18 18:47:16:864 - info: [debug] [BOOTSTRAP] [debug] Client connected
2014-12-18 18:47:16:864 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}}
2014-12-18 18:47:16:864 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:47:16:864 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy
2014-12-18 18:47:16:864 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0}
2014-12-18 18:47:16:864 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "am start -n io.appium.settings/.Settings -e wifi off -e data off"
2014-12-18 18:47:17:865 - info: [debug] Stopping logcat capture
2014-12-18 18:47:17:865 - info: [debug] Logcat terminated with code null, signal SIGTERM
2014-12-18 18:47:17:865 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba kill-server
2014-12-18 18:47:17:896 - error: Unhandled error: Error: read ECONNRESET
    at errnoException (net.js:904:11)
    at TCP.onread (net.js:558:19) context: [POST /wd/hub/session {"desiredCapabilities":{"deviceName":"MsB1","udid":"d81e91ba","appWaitActivity":false,"platformVersion":"4.4","intentAction":false,"appPackage":"com.android.contacts","platformName":"Android","appActi]
2014-12-18 18:47:17:896 - info: [debug] UiAutomator exited
2014-12-18 18:47:17:896 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 120)
2014-12-18 18:47:17:896 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba wait-for-device
2014-12-18 18:47:21:987 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "echo 'ready'"
2014-12-18 18:47:22:034 - info: [debug] Starting logcat capture
2014-12-18 18:47:22:065 - info: [debug] Forwarding system:4824 to device:4724
2014-12-18 18:47:22:065 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba forward tcp:4824 tcp:4724
2014-12-18 18:47:22:081 - info: Starting App
2014-12-18 18:47:22:081 - info: [debug] Attempting to kill all 'uiautomator' processes
2014-12-18 18:47:22:081 - info: [debug] Getting all processes with 'uiautomator'
2014-12-18 18:47:22:081 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "ps 'uiautomator'"
2014-12-18 18:47:22:159 - info: [debug] No matching processes found
2014-12-18 18:47:22:159 - info: [debug] Running bootstrap
2014-12-18 18:47:22:159 - info: [debug] spawning: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap
2014-12-18 18:47:23:422 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:47:23:422 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:47:23:422 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:47:23:422 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:47:23:422 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap:
2014-12-18 18:47:23:422 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:47:23:422 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:47:23:422 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1
2014-12-18 18:47:23:453 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724
2014-12-18 18:47:23:453 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready
2014-12-18 18:47:23:453 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}]
2014-12-18 18:47:23:453 - info: [debug] [BOOTSTRAP] [debug] Loading json...
2014-12-18 18:47:23:453 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers.
2014-12-18 18:47:23:453 - info: [debug] [BOOTSTRAP] [debug] Client connected
2014-12-18 18:47:23:453 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}}
2014-12-18 18:47:23:453 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION
2014-12-18 18:47:23:453 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy
2014-12-18 18:47:23:453 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0}
2014-12-18 18:47:23:453 - info: Getting network connection
2014-12-18 18:47:23:453 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "settings get global airplane_mode_on"
2014-12-18 18:47:24:608 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "settings get global wifi_on"
2014-12-18 18:47:25:606 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "settings get global mobile_data"
2014-12-18 18:47:26:558 - info: [debug] Responding to client with success: {"status":0,"value":4,"sessionId":"393f3fe2-253e-4704-8d47-cbe033b533e0"}
2014-12-18 18:47:26:558 - info: -- POST /wd/hub/session/393f3fe2-253e-4704-8d47-cbe033b533e0/network_connection 200 22838.623 ms - 73 {"status":0,"value":4,"sessionId":"393f3fe2-253e-4704-8d47-cbe033b533e0"}

== app4726.log ==
2014-12-18 18:47:26:589 - info: -- POST /wd/hub/session/ff1a24e4-9409-4400-9fbc-a5e8984f9211/network_connection {"sessionId":"ff1a24e4-9409-4400-9fbc-a5e8984f9211","parameters":{"type":0}}
2014-12-18 18:47:26:604 - info: -- POST /wd/hub/session/ff1a24e4-9409-4400-9fbc-a5e8984f9211/network_connection 404 2.323 ms - 40

== app4724.log ==
2014-12-18 18:47:26:636 - info: -- DELETE /wd/hub/session/393f3fe2-253e-4704-8d47-cbe033b533e0 {}
2014-12-18 18:47:26:651 - info: Shutting down appium session
2014-12-18 18:47:26:651 - info: [debug] Pressing the HOME button
2014-12-18 18:47:26:651 - info: [debug] executing cmd: C:\Users\occ\AppData\Local\Android\android-sdk\platform-tools\adb.exe -s d81e91ba shell "input keyevent 3"
2014-12-18 18:47:27:574 - info: [debug] Stopping logcat capture
2014-12-18 18:47:27:574 - info: [debug] Logcat terminated with code null, signal SIGTERM
2014-12-18 18:47:27:589 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"shutdown"}
2014-12-18 18:47:27:589 - info: [debug] [BOOTSTRAP] [debug] Got command of type SHUTDOWN
2014-12-18 18:47:27:589 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":"OK, shutting down","status":0}
2014-12-18 18:47:27:589 - info: [debug] [BOOTSTRAP] [debug] Closed client connection
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=.
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 0
2014-12-18 18:47:27:589 - info: [debug] Sent shutdown command, waiting for UiAutomator to stop...
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream=
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] Test results for WatcherResultPrinter=.
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] Time: 4.256
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] OK (1 test)
2014-12-18 18:47:27:589 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: -1
2014-12-18 18:47:27:605 - info: [debug] UiAutomator shut down normally
2014-12-18 18:47:27:605 - info: [debug] Cleaning up android objects
2014-12-18 18:47:27:605 - info: [debug] Cleaning up appium session
2014-12-18 18:47:27:605 - info: [debug] Responding to client with success: {"status":0,"value":null,"sessionId":"393f3fe2-253e-4704-8d47-cbe033b533e0"}
2014-12-18 18:47:27:605 - info: -- DELETE /wd/hub/session/393f3fe2-253e-4704-8d47-cbe033b533e0 200 966.283 ms - 76 {"status":0,"value":null,"sessionId":"393f3fe2-253e-4704-8d47-cbe033b533e0"}

== app4726.log ==
2014-12-18 18:47:27:605 - info: -- DELETE /wd/hub/session/ff1a24e4-9409-4400-9fbc-a5e8984f9211 {}
2014-12-18 18:47:27:620 - info: -- DELETE /wd/hub/session/ff1a24e4-9409-4400-9fbc-a5e8984f9211 404 1.875 ms - 40
yahman72 commented 9 years ago

Some additional info: I tried this with 3 different devices (Sony Xperia/Android4.3, Samsung Galaxy S4Android4.4, Huawei Y530/Android4.3) - same results = appium restarts ADB server after every adb shell command...

tobytang1987 commented 9 years ago

it seems i met the same issue when i tried to perform testing on two different port appium server and android simulator..Check the log below,

36minfo: [debug] executing: "/Users/tobytang/DevTools/android/sdk/platform-tools/adb" -s 192.168.56.101:5555 forward tcp:4724 tcp:4724 info: [debug] Pushing appium bootstrap to device... info: [debug] executing: "/Users/tobytang/DevTools/android/sdk/platform-tools/adb" -s 192.168.56.101:5555 push "/Applications/Appium.app/Contents/Resources/node_modules/appium/build/android_bootstrap/AppiumBootstrap.jar" /data/local/tmp/ info: [debug] Pushing settings apk to device... info: [debug] executing: "/Users/tobytang/DevTools/android/sdk/platform-tools/adb" -s 192.168.56.101:5555 install "/Applications/Appium.app/Contents/Resources/node_modules/appium/build/settings_apk/settings_apk-debug.apk" info: [debug] Pushing unlock helper app to device... info: [debug] executing: "/Users/tobytang/DevTools/android/sdk/platform-tools/adb" -s 192.168.56.101:5555 install "/Applications/Appium.app/Contents/Resources/node_modules/appium/build/unlock_apk/unlock_apk-debug.apk" info: Starting App info: [debug] Attempting to kill all 'uiautomator' processes info: [debug] Getting all processes with 'uiautomator' info: [debug] executing: "/Users/tobytang/DevTools/android/sdk/platform-tools/adb" -s 192.168.56.101:5555 shell "ps 'uiautomator'" info: [debug] No matching processes found info: [debug] Running bootstrap info: [debug] spawning: /Users/tobytang/DevTools/android/sdk/platform-tools/adb -s 192.168.56.101:5555 shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1 info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream= info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap: info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1 info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1 info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724 info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready info: [debug] [BOOTSTRAP] [debug] Loading json... info: [debug] [BOOTSTRAP] [debug] json loading complete. info: [debug] [BOOTSTRAP] [debug] Registered crash watchers. info: [debug] Waking up device if it's not alive info: [debug] Pushing command to appium work queue: ["wake",{}] error: Unhandled error: Error: read ECONNRESET at errnoException (net.js:904:11) at TCP.onread (net.js:558:19) context: [POST /wd/hub/session {"desiredCapabilities":

imurchie commented 9 years ago

Appium restarts abd in this process because abd generally stops working at this point. I will look into getting around the race condition.

mykola-mokhnach commented 2 years ago

Closed as obsolete