【Appium】appium中执行脚本log

[hicheng]

2016-11-26 07:00:34:983 - info: Welcome to Appium v1.4.16 (REV ae6877eff263066b26328d457bd285c0cc62430d) //欢迎语和Appium版本 2016-11-26 07:00:34:985 - info: Appium REST http interface listener started on 0.0.0.0:4723 //启动监听的端口 2016-11-26 07:00:34:989 - info: [debug] Non-default server args:
//含有非默认的服务器参数 appium --session-override --log c://log/log.txt {"sessionOverride":true,"log":"c://log/log1.txt"} 2016-11-26 07:00:34:990 - info: Console LogLevel: debug //控制器log的级别 2016-11-26 07:00:34:990 - info: File LogLevel: debug //log文档的log级别 2016-11-26 07:00:41:591 - info: --> POST /wd/hub/session {"requiredCapabilities":{},"desiredCapabilities": {"deviceName":"077a4602","unicodeKeyboard":"True","newCommandTimeout":120,"resetKeyboard":"True","platformVersion":"4.4.4","appPackage":"com.manboker.headportrait","platformName":"Android","appActivity":".activities.SplashActivity"}} //传入设置的设备信息 2016-11-26 07:00:41:594 - info: Client User-Agent string: Python-urllib/2.7 //用户代理 2016-11-26 07:00:41:595 - warn: Converting cap unicodeKeyboard from string to boolean. This might cause unexpected behavior. 2016-11-26 07:00:41:596 - warn: Converting cap resetKeyboard from string to boolean. This might cause unexpected behavior. 2016-11-26 07:00:41:598 - info: [debug] Didn't get app but did get Android package, will attempt to launch it on the device 2016-11-26 07:00:41:600 - info: [debug] Creating new appium session eaf118d0-de01-4eb1-a791-3856101e9e1d //创建session 2016-11-26 07:00:41:601 - info: Starting android appium 2016-11-26 07:00:41:604 - info: [debug] Getting Java version 2016-11-26 07:00:41:843 - info: Java version is: 1.8.0_101

2016-11-26 07:00:41:846 - info: [debug] Checking whether adb is present 2016-11-26 07:00:41:848 - info: [debug] Using adb from D:\Test\android-sdk-windows\platform-tools\adb.exe 2016-11-26 07:00:41:850 - warn: No app capability, can't parse package/activity 2016-11-26 07:00:41:851 - info: [debug] Using fast reset? true 2016-11-26 07:00:41:857 - info: [debug] Preparing device for session 2016-11-26 07:00:41:859 - info: [debug] Not checking whether app is present since we are assuming it's already on the device 2016-11-26 07:00:41:860 - info: Retrieving device 2016-11-26 07:00:41:862 - info: [debug] Trying to find a connected android device 2016-11-26 07:00:41:863 - info: [debug] Getting connected devices... 2016-11-26 07:00:41:867 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe devices 2016-11-26 07:00:42:047 - info: [debug] 1 device(s) connected 2016-11-26 07:00:42:049 - info: Found device 077a4602 2016-11-26 07:00:42:050 - info: [debug] Setting device id to 077a4602 2016-11-26 07:00:42:054 - info: [debug] Waiting for device to be ready and to respond to shell commands (timeout = 5) 2016-11-26 07:00:42:058 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 wait-for-device 2016-11-26 07:00:42:156 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "echo 'ready'" 2016-11-26 07:00:42:294 - info: [debug] Starting logcat capture 2016-11-26 07:00:42:336 - info: [debug] Getting device API level 2016-11-26 07:00:42:337 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "getprop ro.build.version.sdk" 2016-11-26 07:00:42:452 - info: [debug] Device is at API Level 19 2016-11-26 07:00:42:454 - info: Device API level is: 19 2016-11-26 07:00:42:456 - info: [debug] Extracting strings for language: default 2016-11-26 07:00:42:457 - info: [debug] Apk doesn't exist locally 2016-11-26 07:00:42:458 - info: [debug] Could not get strings, but it looks like we had an old strings file anyway, so ignoring 2016-11-26 07:00:42:459 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "rm -rf /data/local/tmp/strings.json" 2016-11-26 07:00:42:554 - info: [debug] Not uninstalling app since server not started with --full-reset 2016-11-26 07:00:42:555 - info: [debug] Skipping install since we launched with a package instead of an app path 2016-11-26 07:00:42:556 - info: [debug] Forwarding system:4724 to device:4724 2016-11-26 07:00:42:557 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 forward tcp:4724 tcp:4724 2016-11-26 07:00:42:641 - info: [debug] Pushing appium bootstrap to device... 2016-11-26 07:00:42:643 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 push "D:\Test\Appium\node_modules\appium\build\android_bootstrap\AppiumBootstrap.jar" /data/local/tmp/ 2016-11-26 07:00:42:823 - info: [debug] Enabling Unicode keyboard support 2016-11-26 07:00:42:824 - info: [debug] Pushing unicode ime to device... 2016-11-26 07:00:42:825 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 install "D:\Test\Appium\node_modules\appium\build\unicode_ime_apk\UnicodeIME-debug.apk" 2016-11-26 07:00:53:998 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "settings get secure default_input_method" 2016-11-26 07:00:54:863 - info: [debug] Unsetting IME 'io.appium.android.ime/.UnicodeIME' 2016-11-26 07:00:54:865 - info: [debug] Setting IME to 'io.appium.android.ime/.UnicodeIME' 2016-11-26 07:00:54:871 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "ime enable io.appium.android.ime/.UnicodeIME" 2016-11-26 07:00:55:894 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "ime set io.appium.android.ime/.UnicodeIME" 2016-11-26 07:00:56:688 - info: [debug] Pushing settings apk to device... 2016-11-26 07:00:56:692 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 install "D:\Test\Appium\node_modules\appium\build\settings_apk\settings_apk-debug.apk" 2016-11-26 07:01:07:894 - info: [debug] Pushing unlock helper app to device... 2016-11-26 07:01:07:898 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 install "D:\Test\Appium\node_modules\appium\build\unlock_apk\unlock_apk-debug.apk" 2016-11-26 07:01:19:067 - info: Starting App 2016-11-26 07:01:19:071 - info: [debug] Attempting to kill all 'uiautomator' processes 2016-11-26 07:01:19:075 - info: [debug] Getting all processes with 'uiautomator' 2016-11-26 07:01:19:078 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "ps 'uiautomator'" 2016-11-26 07:01:19:299 - info: [debug] No matching processes found 2016-11-26 07:01:19:301 - info: [debug] Running bootstrap 2016-11-26 07:01:19:304 - info: [debug] spawning: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell uiautomator runtest AppiumBootstrap.jar -c io.appium.android.bootstrap.Bootstrap -e pkg com.manboker.headportrait -e disableAndroidWatchers false 2016-11-26 07:01:19:957 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: numtests=1 2016-11-26 07:01:19:964 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: stream= 2016-11-26 07:01:19:974 - info: [debug] [UIAUTOMATOR STDOUT] io.appium.android.bootstrap.Bootstrap: 2016-11-26 07:01:19:978 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: id=UiAutomatorTestRunner 2016-11-26 07:01:19:982 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: test=testRunServer 2016-11-26 07:01:19:984 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: class=io.appium.android.bootstrap.Bootstrap 2016-11-26 07:01:19:991 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS: current=1 2016-11-26 07:01:19:993 - info: [debug] [UIAUTOMATOR STDOUT] INSTRUMENTATION_STATUS_CODE: 1 2016-11-26 07:01:19:995 - info: [debug] [BOOTSTRAP] [debug] Socket opened on port 4724 2016-11-26 07:01:19:996 - info: [debug] [BOOTSTRAP] [debug] Appium Socket Server Ready 2016-11-26 07:01:19:997 - info: [debug] [BOOTSTRAP] [debug] Loading json... 2016-11-26 07:01:19:999 - info: [debug] [BOOTSTRAP] [debug] Registered crash watchers. 2016-11-26 07:01:20:004 - info: [debug] Waking up device if it's not alive 2016-11-26 07:01:20:006 - info: [debug] Pushing command to appium work queue: ["wake",{}] 2016-11-26 07:01:20:010 - info: [debug] [BOOTSTRAP] [debug] Client connected 2016-11-26 07:01:20:012 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"wake","params":{}} 2016-11-26 07:01:20:013 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION 2016-11-26 07:01:20:014 - info: [debug] [BOOTSTRAP] [debug] Got command action: wake 2016-11-26 07:01:20:015 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "dumpsys window" 2016-11-26 07:01:20:050 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":true,"status":0} 2016-11-26 07:01:20:118 - info: [debug] Screen already unlocked, continuing. 2016-11-26 07:01:20:119 - info: [debug] Pushing command to appium work queue: ["getDataDir",{}] 2016-11-26 07:01:20:123 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"getDataDir","params":{}} 2016-11-26 07:01:20:124 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION 2016-11-26 07:01:20:125 - info: [debug] [BOOTSTRAP] [debug] Got command action: getDataDir 2016-11-26 07:01:20:125 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":"\/data\/local\/tmp","status":0} 2016-11-26 07:01:20:126 - info: [debug] dataDir set to: /data/local/tmp 2016-11-26 07:01:20:127 - info: [debug] Pushing command to appium work queue: ["compressedLayoutHierarchy",{"compressLayout":false}] 2016-11-26 07:01:20:130 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"compressedLayoutHierarchy","params":{"compressLayout":false}} 2016-11-26 07:01:20:131 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION 2016-11-26 07:01:20:131 - info: [debug] [BOOTSTRAP] [debug] Got command action: compressedLayoutHierarchy 2016-11-26 07:01:20:133 - info: [debug] Getting device API level 2016-11-26 07:01:20:133 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "getprop ro.build.version.sdk" 2016-11-26 07:01:20:166 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":false,"status":0} 2016-11-26 07:01:20:202 - info: [debug] Device is at API Level 19 2016-11-26 07:01:20:203 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "am start -S -a android.intent.action.MAIN -c android.intent.category.LAUNCHER -f 0x10200000 -n com.manboker.headportrait/.activities.SplashActivity" 2016-11-26 07:01:21:397 - info: [debug] Waiting for pkg "com.manboker.headportrait" and activity ".activities.SplashActivity" to be focused 2016-11-26 07:01:21:401 - info: [debug] Getting focused package and activity 2016-11-26 07:01:21:405 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "dumpsys window windows" 2016-11-26 07:01:21:566 - info: [debug] executing cmd: D:\Test\android-sdk-windows\platform-tools\adb.exe -s 077a4602 shell "getprop ro.build.version.release" 2016-11-26 07:01:21:638 - info: [debug] Device is at release version 4.4.4 2016-11-26 07:01:21:638 - info: [debug] Device launched! Ready for commands 2016-11-26 07:01:21:639 - info: [debug] Setting command timeout to 120 secs 2016-11-26 07:01:21:640 - info: [debug] Appium session started with sessionId eaf118d0-de01-4eb1-a791-3856101e9e1d 2016-11-26 07:01:21:647 - info: <-- POST /wd/hub/session 303 40056.211 ms - 74 2016-11-26 07:01:21:654 - info: --> GET /wd/hub/session/eaf118d0-de01-4eb1-a791-3856101e9e1d {} 2016-11-26 07:01:21:656 - info: [debug] Responding to client with success: {"status":0,"value":{"platform":"LINUX","browserName":"Android","platformVersion":"4.4.4","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"deviceName":"077a4602","unicodeKeyboard":true,"newCommandTimeout":120,"resetKeyboard":true,"platformVersion":"4.4.4","appPackage":"com.manboker.headportrait","platformName":"Android","appActivity":".activities.SplashActivity"},"deviceName":"077a4602","unicodeKeyboard":true,"newCommandTimeout":120,"resetKeyboard":true,"appPackage":"com.manboker.headportrait","platformName":"Android","appActivity":".activities.SplashActivity"},"sessionId":"eaf118d0-de01-4eb1-a791-3856101e9e1d"} 2016-11-26 07:01:21:661 - info: <-- GET /wd/hub/session/eaf118d0-de01-4eb1-a791-3856101e9e1d 200 7.588 ms - 757 {"status":0,"value":{"platform":"LINUX","browserName":"Android","platformVersion":"4.4.4","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"deviceName":"077a4602","unicodeKeyboard":true,"newCommandTimeout":120,"resetKeyboard":true,"platformVersion":"4.4.4","appPackage":"com.manboker.headportrait","platformName":"Android","appActivity":".activities.SplashActivity"},"deviceName":"077a4602","unicodeKeyboard":true,"newCommandTimeout":120,"resetKeyboard":true,"appPackage":"com.manboker.headportrait","platformName":"Android","appActivity":".activities.SplashActivity"},"sessionId":"eaf118d0-de01-4eb1-a791-3856101e9e1d"} 2016-11-26 07:01:21:666 - info: --> POST /wd/hub/session/eaf118d0-de01-4eb1-a791-3856101e9e1d/timeouts/implicit_wait {"sessionId":"eaf118d0-de01-4eb1-a791-3856101e9e1d","ms":30000

[hicheng]

测图脚本log， 含有隐式等待

[hicheng]

设置隐性等待的时间为30s，隐性等待获取不到元素的一个周期(大约是1.5s)

2016-11-26 07:01:21:681 - info: [debug] Pushing command to appium work queue: ["find",{"strategy":"id","selector":"com.manboker.headportrait:id/news_page_close","context":"","multiple":false}] 2016-11-26 07:01:21:688 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"find","params":{"strategy":"id","selector":"com.manboker.headportrait:id/news_page_close","context":"","multiple":false}} 2016-11-26 07:01:21:689 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION 2016-11-26 07:01:21:690 - info: [debug] [BOOTSTRAP] [debug] Got command action: find 2016-11-26 07:01:21:690 - info: [debug] [BOOTSTRAP] [debug] Finding com.manboker.headportrait:id/news_page_close using ID with the contextId: multiple: false 2016-11-26 07:01:21:691 - info: [debug] [BOOTSTRAP] [debug] Using: UiSelector[INSTANCE=0, RESOURCE_ID=com.manboker.headportrait:id/news_page_close] 2016-11-26 07:01:22:721 - info: [debug] [BOOTSTRAP] [debug] Failed to locate element. Clearing Accessibility cache and retrying. 2016-11-26 07:01:22:724 - info: [debug] [BOOTSTRAP] [debug] Finding com.manboker.headportrait:id/news_page_close using ID with the contextId: multiple: false 2016-11-26 07:01:22:727 - info: [debug] [BOOTSTRAP] [debug] Using: UiSelector[INSTANCE=0, RESOURCE_ID=com.manboker.headportrait:id/news_page_close] 2016-11-26 07:01:23:227 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":"No element found","status":7} 2016-11-26 07:01:23:230 - info: [debug] Waited for 1548ms so far

[hicheng]

找到元素时的log， 此时周期结束后才开始向返回json， 进行点击操作的时候因为元素已经获取就不进行等待{"cmd":"action","action":"element:click","params":{"elementId":"1"}}

2016-11-26 07:01:24:870 - info: [debug] Pushing command to appium work queue: ["find",{"strategy":"id","selector":"com.manboker.headportrait:id/news_page_close","context":"","multiple":false}] 2016-11-26 07:01:24:877 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"find","params":{"strategy":"id","selector":"com.manboker.headportrait:id/news_page_close","context":"","multiple":false}} 2016-11-26 07:01:24:880 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION 2016-11-26 07:01:24:883 - info: [debug] [BOOTSTRAP] [debug] Got command action: find 2016-11-26 07:01:24:886 - info: [debug] [BOOTSTRAP] [debug] Finding com.manboker.headportrait:id/news_page_close using ID with the contextId: multiple: false 2016-11-26 07:01:24:888 - info: [debug] [BOOTSTRAP] [debug] Using: UiSelector[INSTANCE=0, RESOURCE_ID=com.manboker.headportrait:id/news_page_close] 2016-11-26 07:01:26:137 - info: [debug] [BOOTSTRAP] [debug] Failed to locate element. Clearing Accessibility cache and retrying. 2016-11-26 07:01:26:140 - info: [debug] [BOOTSTRAP] [debug] Finding com.manboker.headportrait:id/news_page_close using ID with the contextId: multiple: false 2016-11-26 07:01:26:143 - info: [debug] [BOOTSTRAP] [debug] Using: UiSelector[INSTANCE=0, RESOURCE_ID=com.manboker.headportrait:id/news_page_close] 2016-11-26 07:01:26:159 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":{"ELEMENT":"1"},"status":0} 2016-11-26 07:01:26:162 - info: [debug] Responding to client with success: {"status":0,"value":{"ELEMENT":"1"},"sessionId":"eaf118d0-de01-4eb1-a791-3856101e9e1d"} 2016-11-26 07:01:26:174 - info: <-- POST /wd/hub/session/eaf118d0-de01-4eb1-a791-3856101e9e1d/element 200 4488.935 ms - 87 {"status":0,"value":{"ELEMENT":"1"},"sessionId":"eaf118d0-de01-4eb1-a791-3856101e9e1d"} 2016-11-26 07:01:26:191 - info: --> POST /wd/hub/session/eaf118d0-de01-4eb1-a791- 3856101e9e1d/element/1/click {"sessionId":"eaf118d0-de01-4eb1-a791-3856101e9e1d","id":"1"} 2016-11-26 07:01:26:193 - info: [debug] Pushing command to appium work queue: ["element:click",{"elementId":"1"}] 2016-11-26 07:01:26:198 - info: [debug] [BOOTSTRAP] [debug] Got data from client: {"cmd":"action","action":"element:click","params":{"elementId":"1"}} 2016-11-26 07:01:26:200 - info: [debug] [BOOTSTRAP] [debug] Got command of type ACTION 2016-11-26 07:01:26:202 - info: [debug] [BOOTSTRAP] [debug] Got command action: click 2016-11-26 07:01:29:322 - info: [debug] [BOOTSTRAP] [debug] Returning result: {"value":true,"status":0}