问答 wsl 环境 appium 报错，github、官网搜索未果，恳请社区大佬帮忙解决~

黄翔 · 2022年04月27日 · 最后由陈恒捷回复于 2022年04月29日 · 7587 次阅读

appium 日志报错 Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}

汇总： Original error: The instrumentation process cannot be initialized within 30000ms timeout. Make sure the application under test does not crash and investigate the logcat output.

附 appium 日志：
2022-04-27 03:16:31:620 [Appium] Welcome to Appium v1.17.1
2022-04-27 03:16:31:621 [Appium] Non-default server args:
2022-04-27 03:16:31:622 [Appium] logFile: /mnt/c/Users/016456282/Desktop/hx.log
2022-04-27 03:16:31:641 [Appium] Appium REST http interface listener started on 0.0.0.0:4723
2022-04-27 03:17:48:006 [HTTP] --> POST /wd/hub/session
2022-04-27 03:17:48:007 [HTTP] {"capabilities":{"firstMatch":[{"platformName":"Android","appium:platformVersion":"7.0","appium:deviceName":"Android","appium:appPackage":"com.mmbox.xbrowser","appium:appWaitPackage":"com.mmbox.xbrowser","appium:app":"/mnt/c/Users/016456282/Desktop/MBT/application/browser.apk","appium:appActivity":"com.mmbox.xbrowser.BrowserActivity","appium:noReset":true,"appium:automationName":"uiautomator2"}]},"desiredCapabilities":{"platformName":"Android","platformVersion":"7.0","deviceName":"Android","appPackage":"com.mmbox.xbrowser","appWaitPackage":"com.mmbox.xbrowser","app":"/mnt/c/Users/016456282/Desktop/MBT/application/browser.apk","appActivity":"com.mmbox.xbrowser.BrowserActivity","noReset":true,"automationName":"uiautomator2"}}
2022-04-27 03:17:48:009 [W3C] Calling AppiumDriver.createSession() with args: [{"platformName":"Android","platformVersion":"7.0","deviceName":"Android","appPackage":"com.mmbox.xbrowser","appWaitPackage":"com.mmbox.xbrowser","app":"/mnt/c/Users/016456282/Desktop/MBT/application/browser.apk","appActivity":"com.mmbox.xbrowser.BrowserActivity","noReset":true,"automationName":"uiautomator2"},null,{"firstMatch":[{"platformName":"Android","appium:platformVersion":"7.0","appium:deviceName":"Android","appium:appPackage":"com.mmbox.xbrowser","appium:appWaitPackage":"com.mmbox.xbrowser","appium:app":"/mnt/c/Users/016456282/Desktop/MBT/application/browser.apk","appium:appActivity":"com.mmbox.xbrowser.BrowserActivity","appium:noReset":true,"appium:automationName":"uiautomator2"}]}]
2022-04-27 03:17:48:010 [BaseDriver] Event 'newSessionRequested' logged at 1651029468010 (11:17:48 GMT+0800 (China Standard Time))
2022-04-27 03:17:48:145 [Appium] Appium v1.17.1 creating new AndroidUiautomator2Driver (v1.44.2) session
2022-04-27 03:17:48:149 [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
2022-04-27 03:17:48:150 [BaseDriver] Creating session with W3C capabilities: {
2022-04-27 03:17:48:150 [BaseDriver] "alwaysMatch": {
2022-04-27 03:17:48:151 [BaseDriver] "platformName": "Android",
2022-04-27 03:17:48:151 [BaseDriver] "appium:platformVersion": "7.0",
2022-04-27 03:17:48:152 [BaseDriver] "appium:deviceName": "Android",
2022-04-27 03:17:48:152 [BaseDriver] "appium:appPackage": "com.mmbox.xbrowser",
2022-04-27 03:17:48:152 [BaseDriver] "appium:appWaitPackage": "com.mmbox.xbrowser",
2022-04-27 03:17:48:153 [BaseDriver] "appium:app": "/mnt/c/Users/016456282/Desktop/MBT/application/browser.apk",
2022-04-27 03:17:48:153 [BaseDriver] "appium:appActivity": "com.mmbox.xbrowser.BrowserActivity",
2022-04-27 03:17:48:153 [BaseDriver] "appium:noReset": true,
2022-04-27 03:17:48:154 [BaseDriver] "appium:automationName": "uiautomator2"
2022-04-27 03:17:48:154 [BaseDriver] },
2022-04-27 03:17:48:154 [BaseDriver] "firstMatch": [
2022-04-27 03:17:48:154 [BaseDriver] {}
2022-04-27 03:17:48:155 [BaseDriver] ]
2022-04-27 03:17:48:155 [BaseDriver] }
2022-04-27 03:17:48:165 [BaseDriver] Session created with session id: 7b5b4e0f-6fbf-45ad-9de9-44b4da8377fb
2022-04-27 03:17:48:172 [BaseDriver] Using local app '/mnt/c/Users/016456282/Desktop/MBT/application/browser.apk'
2022-04-27 03:17:48:173 [UiAutomator2] Checking whether app is actually present
2022-04-27 03:17:48:182 [ADB] Found 1 'build-tools' folders under '/lib/android-sdk' (newest first):
2022-04-27 03:17:48:182 [ADB] /lib/android-sdk/build-tools/debian
2022-04-27 03:17:48:183 [ADB] Using 'adb' from '/lib/android-sdk/platform-tools/adb'
2022-04-27 03:17:48:184 [AndroidDriver] Retrieving device list
2022-04-27 03:17:48:184 [ADB] Trying to find a connected android device
2022-04-27 03:17:48:185 [ADB] Getting connected devices...
2022-04-27 03:17:48:358 [ADB] Connected devices: [{"udid":"emulator-5554","state":"device"}]
2022-04-27 03:17:48:359 [AndroidDriver] Looking for a device with Android '7.0.0'
2022-04-27 03:17:48:361 [ADB] Setting device id to emulator-5554
2022-04-27 03:17:48:362 [ADB] Getting device platform version
2022-04-27 03:17:48:363 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell getprop ro.build.version.release'
2022-04-27 03:17:48:558 [ADB] Current device property 'ro.build.version.release': 7.0
2022-04-27 03:17:48:559 [AndroidDriver] Using device: emulator-5554
2022-04-27 03:17:48:562 [ADB] Using 'adb' from '/lib/android-sdk/platform-tools/adb'
2022-04-27 03:17:48:562 [ADB] Setting device id to emulator-5554
2022-04-27 03:17:48:563 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell getprop ro.build.version.sdk'
2022-04-27 03:17:48:753 [ADB] Current device property 'ro.build.version.sdk': 24
2022-04-27 03:17:48:754 [ADB] Device API level: 24
2022-04-27 03:17:48:755 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 wait-for-device'
2022-04-27 03:17:48:968 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell echo ping'
2022-04-27 03:17:49:138 [AndroidDriver] Pushing settings apk to device...
2022-04-27 03:17:49:139 [ADB] Getting install status for io.appium.settings
2022-04-27 03:17:49:140 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell dumpsys package io.appium.settings'
2022-04-27 03:17:49:324 [ADB] 'io.appium.settings' is installed
2022-04-27 03:17:49:325 [ADB] Getting package info for 'io.appium.settings'
2022-04-27 03:17:49:325 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell dumpsys package io.appium.settings'
2022-04-27 03:17:49:540 [ADB] The version name of the installed 'io.appium.settings' is greater or equal to the application version name ('3.1.0' >= '3.1.0')
2022-04-27 03:17:49:541 [ADB] There is no need to install/upgrade '/usr/local/lib/node_modules/appium/node_modules/io.appium.settings/apks/settings_apk-debug.apk'
2022-04-27 03:17:49:543 [ADB] Getting IDs of all 'io.appium.settings' processes
2022-04-27 03:17:49:544 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell 'pgrep --help; echo $?''
2022-04-27 03:17:49:745 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell 'pgrep ^{appium\.settings$} || pgrep ^{io\.appium\.setti$''}
2022-04-27 03:17:49:928 [AndroidDriver] io.appium.settings is already running. There is no need to reset its permissions.
2022-04-27 03:17:49:929 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell appops set io.appium.settings android:mock_location allow'
2022-04-27 03:17:50:130 [Logcat] Starting logcat capture
2022-04-27 03:17:50:329 [UiAutomator2] Forwarding UiAutomator2 Server port 6790 to 8200
2022-04-27 03:17:50:330 [ADB] Forwarding system: 8200 to device: 6790
2022-04-27 03:17:50:330 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 forward tcp:8200 tcp:6790'
2022-04-27 03:17:50:377 [ADB] Getting install status for io.appium.uiautomator2.server
2022-04-27 03:17:50:379 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell dumpsys package io.appium.uiautomator2.server'
2022-04-27 03:17:50:473 [ADB] 'io.appium.uiautomator2.server' is installed
2022-04-27 03:17:50:473 [ADB] Getting package info for 'io.appium.uiautomator2.server'
2022-04-27 03:17:50:474 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell dumpsys package io.appium.uiautomator2.server'
2022-04-27 03:17:50:550 [ADB] The version name of the installed 'io.appium.uiautomator2.server' is greater or equal to the application version name ('4.5.5' >= '4.5.5')
2022-04-27 03:17:50:551 [UiAutomator2] io.appium.uiautomator2.server installation state: sameVersionInstalled
2022-04-27 03:17:50:552 [ADB] Checking app cert for /usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-v4.5.5.apk
2022-04-27 03:17:50:554 [ADB] Using 'apksigner.jar' from '/lib/android-sdk/build-tools/debian/apksigner.jar'
2022-04-27 03:17:50:555 [ADB] Starting apksigner: /usr/lib/jvm/java-8-openjdk-amd64/bin/java -Xmx1024M -Xss1m -jar /lib/android-sdk/build-tools/debian/apksigner.jar verify --print-certs /usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-v4.5.5.apk
2022-04-27 03:17:51:002 [ADB] apksigner stdout: Signer #1 certificate DN: EMAILADDRESS=android@android.com, CN=Android, OU=Android, O=Android, L=Mountain View, ST=California, C=US
2022-04-27 03:17:51:003 [ADB] Signer #1 certificate SHA-256 digest: a40da80a59d170caa950cf15c18c454d47a39b26989d8b640ecd745ba71bf5dc
2022-04-27 03:17:51:003 [ADB] Signer #1 certificate SHA-1 digest: 61ed377e85d386a8dfee6b864bd85b0bfaa5af81
2022-04-27 03:17:51:003 [ADB] Signer #1 certificate MD5 digest: e89b158e4bcf988ebd09eb83f5378e87
2022-04-27 03:17:51:003 [ADB]
2022-04-27 03:17:51:003 [ADB] '/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-v4.5.5.apk' is signed with the default certificate
2022-04-27 03:17:51:004 [ADB] Getting install status for io.appium.uiautomator2.server.test
2022-04-27 03:17:51:004 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell dumpsys package io.appium.uiautomator2.server.test'
2022-04-27 03:17:51:062 [ADB] 'io.appium.uiautomator2.server.test' is installed
2022-04-27 03:17:51:063 [ADB] Checking app cert for /usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-debug-androidTest.apk
2022-04-27 03:17:51:063 [ADB] Starting apksigner: /usr/lib/jvm/java-8-openjdk-amd64/bin/java -Xmx1024M -Xss1m -jar /lib/android-sdk/build-tools/debian/apksigner.jar verify --print-certs /usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-debug-androidTest.apk
2022-04-27 03:17:51:401 [ADB] apksigner stdout: Signer #1 certificate DN: EMAILADDRESS=android@android.com, CN=Android, OU=Android, O=Android, L=Mountain View, ST=California, C=US
2022-04-27 03:17:51:401 [ADB] Signer #1 certificate SHA-256 digest: a40da80a59d170caa950cf15c18c454d47a39b26989d8b640ecd745ba71bf5dc
2022-04-27 03:17:51:402 [ADB] Signer #1 certificate SHA-1 digest: 61ed377e85d386a8dfee6b864bd85b0bfaa5af81
2022-04-27 03:17:51:402 [ADB] Signer #1 certificate MD5 digest: e89b158e4bcf988ebd09eb83f5378e87
2022-04-27 03:17:51:402 [ADB]
2022-04-27 03:17:51:403 [ADB] '/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-debug-androidTest.apk' is signed with the default certificate
2022-04-27 03:17:51:403 [UiAutomator2] Server packages are not going to be (re) installed
2022-04-27 03:17:51:406 [UiAutomator2] Waiting up to 30000ms for services to be available
2022-04-27 03:17:51:407 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell pm list instrumentation'
2022-04-27 03:17:51:680 [UiAutomator2] Instrumentation target 'io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner' is available
2022-04-27 03:17:51:680 [ADB] Checking app cert for /mnt/c/Users/016456282/Desktop/MBT/application/browser.apk
2022-04-27 03:17:51:683 [ADB] Starting apksigner: /usr/lib/jvm/java-8-openjdk-amd64/bin/java -Xmx1024M -Xss1m -jar /lib/android-sdk/build-tools/debian/apksigner.jar verify --print-certs /mnt/c/Users/016456282/Desktop/MBT/application/browser.apk
2022-04-27 03:17:52:105 [ADB] apksigner stdout: Signer #1 certificate DN: EMAILADDRESS=android@android.com, CN=Android, OU=Android, O=Android, L=Mountain View, ST=California, C=US
2022-04-27 03:17:52:105 [ADB] Signer #1 certificate SHA-256 digest: a40da80a59d170caa950cf15c18c454d47a39b26989d8b640ecd745ba71bf5dc
2022-04-27 03:17:52:105 [ADB] Signer #1 certificate SHA-1 digest: 61ed377e85d386a8dfee6b864bd85b0bfaa5af81
2022-04-27 03:17:52:105 [ADB] Signer #1 certificate MD5 digest: e89b158e4bcf988ebd09eb83f5378e87
2022-04-27 03:17:52:105 [ADB]
2022-04-27 03:17:52:106 [ADB] '/mnt/c/Users/016456282/Desktop/MBT/application/browser.apk' is signed with the default certificate
2022-04-27 03:17:52:106 [ADB] Getting install status for com.mmbox.xbrowser
2022-04-27 03:17:52:107 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell dumpsys package com.mmbox.xbrowser'
2022-04-27 03:17:52:165 [ADB] 'com.mmbox.xbrowser' is installed
2022-04-27 03:17:52:165 [ADB] Getting package info for 'com.mmbox.xbrowser'
2022-04-27 03:17:52:165 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell dumpsys package com.mmbox.xbrowser'
2022-04-27 03:17:52:237 [ADB] The version name of the installed 'com.mmbox.xbrowser' is greater or equal to the application version name ('2.9.0' >= '2.9.0')
2022-04-27 03:17:52:237 [ADB] There is no need to install/upgrade '/mnt/c/Users/016456282/Desktop/MBT/application/browser.apk'
2022-04-27 03:17:52:238 [UiAutomator2] Performing shallow cleanup of automation leftovers
2022-04-27 03:17:52:251 [UiAutomator2] No obsolete sessions have been detected (Error: connect ECONNREFUSED 127.0.0.1:8200)
2022-04-27 03:17:52:252 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell am force-stop io.appium.uiautomator2.server.test'
2022-04-27 03:17:52:536 [UiAutomator2] Starting UIAutomator2 server 4.5.5
2022-04-27 03:17:52:537 [UiAutomator2] Using UIAutomator2 server from '/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-v4.5.5.apk' and test from '/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-debug-androidTest.apk'
2022-04-27 03:17:52:537 [UiAutomator2] Waiting up to 30000ms for UiAutomator2 to be online...
2022-04-27 03:17:52:538 [ADB] Creating ADB subprocess with args: ["-P",5037,"-s","emulator-5554","shell","am","instrument","-w","io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner"]
2022-04-27 03:17:52:966 [Instrumentation] io.appium.uiautomator2.server.test.AppiumUiAutomator2Server:
2022-04-27 03:17:53:549 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:17:53:554 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:17:53:569 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:17:54:575 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:17:54:578 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:17:54:587 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:17:55:591 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:17:55:594 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:17:55:602 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:17:56:606 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:17:56:607 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:17:56:615 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:17:57:619 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:17:57:620 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:17:57:627 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:17:58:631 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:17:58:632 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:17:58:640 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:17:59:644 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:17:59:645 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:17:59:654 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:00:657 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:00:658 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:00:669 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:01:675 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:01:676 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:01:686 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:02:691 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:02:692 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:02:702 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:03:706 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:03:707 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:03:715 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:04:719 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:04:720 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:04:729 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:05:732 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:05:734 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:05:742 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:06:746 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:06:747 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:06:761 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:07:764 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:07:765 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:07:775 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:08:779 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:08:780 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:08:787 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:09:790 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:09:792 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:09:798 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:10:803 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:10:804 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:10:814 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:11:818 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:11:819 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:11:827 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:12:831 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:12:833 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:12:847 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:13:851 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:13:852 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:13:858 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:14:863 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:14:864 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:14:872 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:15:877 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:15:878 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:15:885 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:16:893 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:16:894 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:16:909 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:17:913 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:17:914 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:17:920 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:18:924 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:18:929 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:18:937 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:19:945 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:19:947 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:19:955 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:20:958 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:20:960 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:20:966 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:21:970 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:21:971 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:21:977 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:22:981 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:22:982 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:22:994 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:23:998 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:23:999 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:24:006 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}
2022-04-27 03:18:24:008 [UiAutomator2] The instrumentation process cannot be initialized within 30000ms timeout. Make sure the application under test does not crash and investigate the logcat output. You could also try to increase the value of 'uiautomator2ServerLaunchTimeout' capability.
2022-04-27 03:18:24:010 [UiAutomator2] Deleting UiAutomator2 session
2022-04-27 03:18:24:013 [UiAutomator2] Deleting UiAutomator2 server session
2022-04-27 03:18:24:015 [WD Proxy] Matched '/' to command name 'deleteSession'
2022-04-27 03:18:24:018 [UiAutomator2] Did not get confirmation UiAutomator2 deleteSession worked; Error was: UnknownError: An unknown server-side error occurred while processing the command. Original error: Trying to proxy a session command without session id
2022-04-27 03:18:24:019 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell am force-stop com.mmbox.xbrowser'
2022-04-27 03:18:24:284 [Logcat] Stopping logcat capture
2022-04-27 03:18:24:286 [ADB] Removing forwarded port socket connection: 8200
2022-04-27 03:18:24:286 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 forward --remove tcp:8200'
2022-04-27 03:18:24:329 [BaseDriver] Event 'newSessionStarted' logged at 1651029504329 (11:18:24 GMT+0800 (China Standard Time))
2022-04-27 03:18:24:400 [W3C] Encountered internal error running command: Error: The instrumentation process cannot be initialized within 30000ms timeout. Make sure the application under test does not crash and investigate the logcat output. You could also try to increase the value of 'uiautomator2ServerLaunchTimeout' capability.
2022-04-27 03:18:24:400 [W3C] at Object.errorAndThrow (/usr/local/lib/node_modules/appium/node_modules/appium-support/lib/logging.js:87:35)
2022-04-27 03:18:24:400 [W3C] at UiAutomator2Server.startSession (/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-driver/lib/uiautomator2.js:220:15)
2022-04-27 03:18:24:401 [W3C] at AndroidUiautomator2Driver.startUiAutomator2Session (/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-driver/lib/driver.js:366:5)
2022-04-27 03:18:24:401 [W3C] at AndroidUiautomator2Driver.createSession (/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-driver/lib/driver.js:212:7)
2022-04-27 03:18:24:401 [W3C] at AppiumDriver.createSession (/usr/local/lib/node_modules/appium/lib/appium.js:358:35)
2022-04-27 03:18:24:416 [W3C] Destroying socket connection
2022-04-27 03:18:24:418 [HTTP] <-- POST /wd/hub/session 500 36410 ms - 999
2022-04-27 03:18:24:418 [HTTP]

logcat 日志：
--------- beginning of system
04-27 03:16:07.120 1698 3795 W WindowManager: Attempted to remove non-existing token: android.os.Binder@605b6df
--------- beginning of main
04-27 03:16:13.135 2199 4034 I GCM-GMS : Registering GMS 745476177629
04-27 03:16:13.146 1855 2712 E GCM : Missing checkin config file
04-27 03:16:13.147 1855 2712 W GCM : GCM FAILED TO INITIALIZE - missing checkin
04-27 03:16:13.149 2199 4034 W GCM-GMS : Failed to get registration: java.io.IOException: AUTHENTICATION_FAILED
04-27 03:16:54.305 3117 3130 V NativeCrypto: SSL handshake aborted: ssl=0xa66926c8: I/O error during system call, Connection reset by peer
04-27 03:16:54.344 3117 3130 V NativeCrypto: SSL handshake aborted: ssl=0xa66926c8: I/O error during system call, Connection reset by peer
04-27 03:16:54.386 3117 3130 V NativeCrypto: SSL handshake aborted: ssl=0xa66926c8: I/O error during system call, Connection reset by peer
04-27 03:17:49.006 4993 4993 W pgrep : type=1400 audit(0.0:18): avc: denied { getattr } for path="/proc/sysrq-trigger" dev="proc" ino=4026532069 scontext=ushell:s0 tcontext=u:object_r:proc_sysrq:s0 tclass=file permissive=0
04-27 03:17:49.006 4993 4993 W pgrep : type=1400 audit(0.0:19): avc: denied { getattr } for path="/proc/iomem" dev="proc" ino=4026532007 scontext=ushell:s0 tcontext=u:object_r:proc_iomem:s0 tclass=file permissive=0
04-27 03:17:50.719 5013 5013 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
04-27 03:17:50.720 5013 5013 D AndroidRuntime: CheckJNI is OFF
04-27 03:17:50.740 5013 5013 W art : Unexpected CPU variant for X86 using defaults: x86
04-27 03:17:50.743 5013 5013 D ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
04-27 03:17:50.758 5013 5013 E memtrack: Couldn't load memtrack module (No such file or directory)
04-27 03:17:50.758 5013 5013 E android.os.Debug: failed to load memtrack module: -2
04-27 03:17:50.758 5013 5013 I Radio-JNI: register_android_hardware_Radio DONE
04-27 03:17:50.763 5013 5013 D AndroidRuntime: Calling main entry com.android.commands.pm.Pm
04-27 03:17:50.770 5013 5021 W MessageQueue: Handler (android.os.Handler) {5241708} sending message to a Handler on a dead thread
04-27 03:17:50.770 5013 5021 W MessageQueue: java.lang.IllegalStateException: Handler (android.os.Handler) {5241708} sending message to a Handler on a dead thread
04-27 03:17:50.770 5013 5021 W MessageQueue: at android.os.MessageQueue.enqueueMessage(MessageQueue.java:543)
04-27 03:17:50.770 5013 5021 W MessageQueue: at android.os.Handler.enqueueMessage(Handler.java:643)
04-27 03:17:50.770 5013 5021 W MessageQueue: at android.os.Handler.sendMessageAtTime(Handler.java:612)
04-27 03:17:50.770 5013 5021 W MessageQueue: at android.os.Handler.sendMessageDelayed(Handler.java:582)
04-27 03:17:50.770 5013 5021 W MessageQueue: at android.os.Handler.post(Handler.java:338)
04-27 03:17:50.770 5013 5021 W MessageQueue: at android.os.ResultReceiver$MyResultReceiver.send(ResultReceiver.java:57)
04-27 03:17:50.770 5013 5021 W MessageQueue: at com.android.internal.os.IResultReceiver$Stub.onTransact(IResultReceiver.java:58)
04-27 03:17:50.770 5013 5021 W MessageQueue: at android.os.Binder.execTransact(Binder.java:565)
04-27 03:17:50.772 5013 5013 I art : System.exit called, status: 0
04-27 03:17:50.772 5013 5013 I AndroidRuntime: VM exiting with result code 0.
04-27 03:17:51.572 5032 5032 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
04-27 03:17:51.573 5032 5032 D AndroidRuntime: CheckJNI is OFF
04-27 03:17:51.592 5032 5032 W art : Unexpected CPU variant for X86 using defaults: x86
04-27 03:17:51.596 5032 5032 D ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
04-27 03:17:51.610 5032 5032 E memtrack: Couldn't load memtrack module (No such file or directory)
04-27 03:17:51.610 5032 5032 E android.os.Debug: failed to load memtrack module: -2
04-27 03:17:51.610 5032 5032 I Radio-JNI: register_android_hardware_Radio DONE
04-27 03:17:51.615 5032 5032 D AndroidRuntime: Calling main entry com.android.commands.am.Am
04-27 03:17:51.619 1698 1709 I ActivityManager: Force stopping io.appium.uiautomator2.server.test appid=10082 user=0: from pid 5032
04-27 03:17:51.621 5032 5032 D AndroidRuntime: Shutting down VM
04-27 03:17:51.626 1984 1984 D CarrierSvcBindHelper: No carrier app for: 0
04-27 03:17:51.869 5042 5042 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
04-27 03:17:51.870 5042 5042 D AndroidRuntime: CheckJNI is OFF
04-27 03:17:51.890 5042 5042 W art : Unexpected CPU variant for X86 using defaults: x86
04-27 03:17:51.893 5042 5042 D ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
04-27 03:17:51.904 5042 5042 E memtrack: Couldn't load memtrack module (No such file or directory)
04-27 03:17:51.904 5042 5042 E android.os.Debug: failed to load memtrack module: -2
04-27 03:17:51.905 5042 5042 I Radio-JNI: register_android_hardware_Radio DONE
04-27 03:17:51.911 5042 5042 D AndroidRuntime: Calling main entry com.android.commands.am.Am
04-27 03:17:51.916 1698 1710 I ActivityManager: Force stopping io.appium.uiautomator2.server appid=10081 user=0: start instr
04-27 03:17:51.916 1698 1710 I ActivityManager: Killing 4751:io.appium.uiautomator2.server/u0a81 (adj 0): stop io.appium.uiautomator2.server
04-27 03:17:51.917 1698 1710 D ActivityManager: cleanUpApplicationRecord -- 4751
04-27 03:17:51.917 1698 1710 W ActivityManager: Crash of app io.appium.uiautomator2.server running instrumentation ComponentInfo{io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner}
04-27 03:17:51.927 1698 1710 I ActivityManager: Force stopping io.appium.uiautomator2.server appid=10081 user=0: finished inst
04-27 03:17:51.931 1698 5052 I ActivityManager: Failure reporting to instrumentation watcher: comp=ComponentInfo{io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner} results=Bundle[{shortMsg=Process crashed.}]
04-27 03:17:51.933 5053 5053 I art : Late-enabling -Xcheck:jni
04-27 03:17:51.934 5053 5053 W art : Unexpected CPU variant for X86 using defaults: x86
04-27 03:17:51.936 1698 1710 I ActivityManager: Start proc 5053:io.appium.uiautomator2.server/u0a81 for added application io.appium.uiautomator2.server
04-27 03:17:51.936 1698 1714 W ActivityManager: Error shutting down UiAutomationConnection
04-27 03:17:51.952 5053 5060 E art : Failed sending reply to debugger: Broken pipe
04-27 03:17:51.953 5053 5060 I art : Debugger is no longer active
04-27 03:17:51.953 5053 5060 I art : Starting a blocking GC Instrumentation
04-27 03:17:51.958 5053 5053 W System : ClassLoader referenced unknown path: /data/app/io.appium.uiautomator2.server.test-1/lib/x86
04-27 03:17:51.958 5053 5053 W System : ClassLoader referenced unknown path: /data/app/io.appium.uiautomator2.server-1/lib/x86
04-27 03:17:51.961 5053 5053 W System : ClassLoader referenced unknown path:
04-27 03:17:51.971 5053 5053 I MonitoringInstr: Instrumentation started!
04-27 03:17:51.971 5053 5053 I MonitoringInstr: Setting context classloader to 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/data/app/io.appium.uiautomator2.server.test-1/base.apk", zip file "/data/app/io.appium.uiautomator2.server-1/base.apk"],nativeLibraryDirectories=[/data/app/io.appium.uiautomator2.server.test-1/lib/x86, /data/app/io.appium.uiautomator2.server-1/lib/x86, /system/lib, /vendor/lib]]]', Original: 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/data/app/io.appium.uiautomator2.server.test-1/base.apk", zip file "/data/app/io.appium.uiautomator2.server-1/base.apk"],nativeLibraryDirectories=[/data/app/io.appium.uiautomator2.server.test-1/lib/x86, /data/app/io.appium.uiautomator2.server-1/lib/x86, /system/lib, /vendor/lib]]]'
04-27 03:17:51.973 5053 5053 I MonitoringInstr: No JSBridge.
04-27 03:17:51.975 5053 5068 I MonitoringInstr: Setting context classloader to 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/data/app/io.appium.uiautomator2.server.test-1/base.apk", zip file "/data/app/io.appium.uiautomator2.server-1/base.apk"],nativeLibraryDirectories=[/data/app/io.appium.uiautomator2.server.test-1/lib/x86, /data/app/io.appium.uiautomator2.server-1/lib/x86, /system/lib, /vendor/lib]]]', Original: 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/data/app/io.appium.uiautomator2.server.test-1/base.apk", zip file "/data/app/io.appium.uiautomator2.server-1/base.apk"],nativeLibraryDirectories=[/data/app/io.appium.uiautomator2.server.test-1/lib/x86, /data/app/io.appium.uiautomator2.server-1/lib/x86, /system/lib, /vendor/lib]]]'
04-27 03:17:51.979 5053 5068 I UsageTrackerFacilitator: Usage tracking enabled
04-27 03:17:51.979 5053 5068 I TestRequestBuilder: Scanning classpath to find tests in paths [/data/app/io.appium.uiautomator2.server.test-1/base.apk]
04-27 03:17:52.060 5053 5068 D TestExecutor: Adding listener androidx.test.internal.runner.listener.LogRunListener
04-27 03:17:52.060 5053 5068 D TestExecutor: Adding listener androidx.test.internal.runner.listener.InstrumentationResultPrinter
04-27 03:17:52.060 5053 5068 D TestExecutor: Adding listener androidx.test.internal.runner.listener.ActivityFinisherRunListener
04-27 03:17:52.061 5053 5068 I TestRunner: run started: 1 tests
04-27 03:17:52.063 5053 5068 I TestRunner: started: startServer(io.appium.uiautomator2.server.test.AppiumUiAutomator2Server)
04-27 03:17:52.065 5053 5053 I MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
04-27 03:17:52.067 5053 5068 I appium : [AppiumUiAutomator2Server] Starting Server
04-27 03:17:53.072 5053 5068 I appium : AndroidServer created on port 6790
04-27 03:17:53.073 5053 5068 I appium : io.appium.uiautomator2.server started:
04-27 03:17:53.084 5053 5070 I appium : Started UiAutomator2 io.appium.uiautomator2.http io.appium.uiautomator2.server on port 6790
04-27 03:17:58.011 1698 1713 I UsageStatsService: User[0] Flushing usage stats to disk
04-27 03:18:02.413 1698 1811 I WifiConnectivityManager: start a single scan from watchdogHandler
04-27 03:18:02.413 1698 1811 I WifiConnectivityManager: scheduleWatchdogTimer
04-27 03:18:23.317 5077 5077 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
04-27 03:18:23.318 5077 5077 D AndroidRuntime: CheckJNI is OFF
04-27 03:18:23.337 5077 5077 W art : Unexpected CPU variant for X86 using defaults: x86
04-27 03:18:23.340 5077 5077 D ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
04-27 03:18:23.354 5077 5077 E memtrack: Couldn't load memtrack module (No such file or directory)
04-27 03:18:23.354 5077 5077 E android.os.Debug: failed to load memtrack module: -2
04-27 03:18:23.354 5077 5077 I Radio-JNI: register_android_hardware_Radio DONE
04-27 03:18:23.360 5077 5077 D AndroidRuntime: Calling main entry com.android.commands.am.Am
04-27 03:18:23.366 1698 2908 I ActivityManager: Force stopping com.mmbox.xbrowser appid=10083 user=0: from pid 5077
04-27 03:18:23.367 5077 5077 D AndroidRuntime: Shutting down VM
04-27 03:18:23.371 1984 1984 D CarrierSvcBindHelper: No carrier app for: 0
04-27 03:18:23.725 1347 1367 E SurfaceFlinger: ro.sf.lcd_density must be defined as a build property
04-27 03:18:23.727 1347 2220 D gralloc_ranchu: gralloc_alloc: Creating ashmem region of size 14745600
04-27 03:18:23.739 5089 5089 D : HostConnection::get() New Host Connection established 0xaa41b2c0, tid 5089
04-27 03:18:23.745 1347 1347 E EGL_emulation: tid 1347: eglCreateSyncKHR(1989): error 0x3004 (EGL_BAD_ATTRIBUTE)
04-27 03:18:24.288 5094 5094 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
04-27 03:18:24.289 5094 5094 D AndroidRuntime: CheckJNI is OFF
04-27 03:18:24.306 5094 5094 W art : Unexpected CPU variant for X86 using defaults: x86
04-27 03:18:24.309 5094 5094 D ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
04-27 03:18:24.321 5094 5094 E memtrack: Couldn't load memtrack module (No such file or directory)
04-27 03:18:24.321 5094 5094 E android.os.Debug: failed to load memtrack module: -2
04-27 03:18:24.322 5094 5094 I Radio-JNI: register_android_hardware_Radio DONE
04-27 03:18:24.327 5094 5094 D AndroidRuntime: Calling main entry com.android.commands.am.Am
04-27 03:18:24.334 2990 2990 D MediaScannerReceiver: action: android.intent.action.MEDIA_SCANNER_SCAN_FILE path: /storage/emulated/0/screen.png
04-27 03:18:24.337 5094 5094 D AndroidRuntime: Shutting down VM
04-27 03:18:32.605 2199 2778 I Checkin : [EventLogChimeraService] Opted in for usage reporting: false
04-27 03:18:32.605 2199 2778 I Checkin : [EventLogChimeraService] Aggregate from 1651028841219 (log), 0 (data)

共收到 6 条回复时间点赞

马儿不会飞 #1 · 2022年04月27日

1.看起来你这是 [WD Proxy] 报错，
2.正常的日志应该这样的：
[debug] [WD Proxy] Got response with status 200: {"value":{"message":"WebDriverAgent is ready to accept commands","state":"success","os":{"testmanagerdVersion":28,"name":"iOS","sdkVersion":"13.0","version":"13.1.1"},"ios":{"ip":"172.16.132.205"},"ready":true,"build":{"time":"Aug 11 2020 18:19:39","productBundleIdentifier":"com.facebook.WebDriverAgentRunner"}},"sessionId":"6ACDECDD-835C-4801-8893-5F1C472B80A6"}
3.我猜应该是 WebDriverAgent 初始化失败了，你的安卓 SDK 版本应该有问题；
4.你试试重新装一个；

陈恒捷 #2 · 2022年04月27日 1 个赞

日志挺齐全，先赞一个

先分享下解析日志的思路，便于你看懂下面说的东西：

1、首先，得先大概了解 appium 这个场景下的大致架构原理。以下这个是 appium 在使用 uiautomator2 模式下的最新架构图（出自官方 https://github.com/appium/appium-uiautomator2-server/wiki ，百度搜关键字 appium uiautomator2 ，也能找到相关文章说明）：

2、了解架构后，从 appium 日志开始出错的位置开始分析，了解出错的直接原因

3、从直接原因的日志继续往前看，看前面做了什么，和架构图里的这些组件模块的关系是什么。辅助看 logcat 日志找到一些 appium log 里找不到的安卓系统内部错误信息

然后我从第二步开始详细说下怎么分析：

日志出错位置

2022-04-27 03:18:24:008 [UiAutomator2] The instrumentation process cannot be initialized within 30000ms timeout. Make sure the application under test does not crash and investigate the logcat output. You could also try to increase the value of 'uiautomator2ServerLaunchTimeout' capability.

直接原因翻译过来就是：instrumentation 进程在 30 秒超时时限内未能完成初始化。请确认被测应用没有崩溃（这里有点误导，应该看 instrumentation 进程有没有崩溃）并查看 logcat 输出。你也可以通过 uiautomator2ServerLaunchTimeout 调大超时时间

往前看，看前面在做什么

2022-04-27 03:17:53:549 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:17:53:554 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
...
2022-04-27 03:18:23:998 [WD Proxy] Matched '/status' to command name 'getStatus'
2022-04-27 03:18:23:999 [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:8200/wd/hub/status] with no body
2022-04-27 03:18:24:006 [WD Proxy] Got response with unknown status: {"errno":-111,"code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8200}

这段是在不断重试连接 http://127.0.0.1:8200/wd/hub/status 这个地址，为啥要连接这个地址呢？从架构图可以看到，有个 netty server ，实际就是在尝试连接这个 server 。因为只有这个 server 能连上，才有办法从 appium 服务端通过发信息给这个 server ，操作手机里的 app 。

2022-04-27 03:17:52:536 [UiAutomator2] Starting UIAutomator2 server 4.5.5
2022-04-27 03:17:52:537 [UiAutomator2] Using UIAutomator2 server from '/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-v4.5.5.apk' and test from '/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-server/apks/appium-uiautomator2-server-debug-androidTest.apk'
2022-04-27 03:17:52:537 [UiAutomator2] Waiting up to 30000ms for UiAutomator2 to be online...
2022-04-27 03:17:52:538 [ADB] Creating ADB subprocess with args: ["-P",5037,"-s","emulator-5554","shell","am","instrument","-w","io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner"]
2022-04-27 03:17:52:966 [Instrumentation] io.appium.uiautomator2.server.test.AppiumUiAutomator2Server:

这段挺清晰了，在启动 UIAutomator2 server ，并在启动完后等待 30 秒直到它在线。和上一段持续尝试连接能对上了。然后启动用的 adb 命令参数是 "-P",5037,"-s","emulator-5554","shell","am","instrument","-w","io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner"

2022-04-27 03:17:52:238 [UiAutomator2] Performing shallow cleanup of automation leftovers
2022-04-27 03:17:52:251 [UiAutomator2] No obsolete sessions have been detected (Error: connect ECONNREFUSED 127.0.0.1:8200)
2022-04-27 03:17:52:252 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell am force-stop io.appium.uiautomator2.server.test'

这段的关键语句是第一行的 Performing shallow cleanup of automation leftovers ，翻译过来就是 清理上一次自动化测试可能存在的遗留内容（有可能上一次是被手动中断的，所以开始前需要检测并恢复到下一步需要的初始状态，和我们自动化测试 setup 做的事情差不多）。实际做了啥？两个事情，一个是尝试连接 127.0.0.1:8200（结果是 ECONNREFUSED ，连不上），另一个是通过 am force-stop 杀掉 io.appium.uiautomator2.server.test 对应进程（这也是后面 logcat 里会存在 crash 这样的字眼的原因，在 crash 位置往上看就会看到是被 kill 掉了）

同时通过这段分析其实可以发现，带有 [ADB] 的是实际执行命令的信息，我们排查日志关键不是看命令细节，而是看意图，所以后续分析主要看带有 [UiAutomator2] 的

2022-04-27 03:17:48:173 [UiAutomator2] Checking whether app is actually present
...
2022-04-27 03:17:50:329 [UiAutomator2] Forwarding UiAutomator2 Server port 6790 to 8200
...
2022-04-27 03:17:50:551 [UiAutomator2] io.appium.uiautomator2.server installation state: sameVersionInstalled
...
2022-04-27 03:17:51:403 [UiAutomator2] Server packages are not going to be (re) installed
2022-04-27 03:17:51:406 [UiAutomator2] Waiting up to 30000ms for services to be available
...
2022-04-27 03:17:51:680 [UiAutomator2] Instrumentation target 'io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner' is available

只看 [UiAutomator2]，相当清爽，我在末尾补上中文翻译方便查看

2022-04-27 03:17:48:173 [UiAutomator2] Checking whether app is actually present ——判断 app 是否存在
...
2022-04-27 03:17:50:329 [UiAutomator2] Forwarding UiAutomator2 Server port 6790 to 8200 ——把 server 的端口从6790转发8200（和网络请求地址端口号是 8200 对上了）
...
2022-04-27 03:17:50:551 [UiAutomator2] io.appium.uiautomator2.server installation state: sameVersionInstalled ——确认 io.appium.uiautomator2.server  的安装状态为：已安装同版本的应用
...
2022-04-27 03:17:51:403 [UiAutomator2] Server packages are not going to be (re) installed——得出结论：Server安装包不需要再安装
2022-04-27 03:17:51:406 [UiAutomator2] Waiting up to 30000ms for services to be available——等待30秒知道服务初始化完毕（因为之前有可能由于某些原因已经启动了应用，所以这里等上30秒保障之前启动的已经启动完毕）
...
2022-04-27 03:17:51:680 [UiAutomator2] Instrumentation target 'io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner' is available——查到有 io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner 的可用服务，和后面强制停掉服务对上号

看完 appium log ，结合看 logcat

logcat 因为混杂了所有系统信息，所以需要自己想办法捞和自己要查的东西有关的信息。这个过滤方法的核心就是：进程号。要找到进程号，先得找到进程名，搜索 io.appium.uiautomator2.server.test ，找到和它有关的启动信息

04-27 03:17:52.063 5053 5068 I TestRunner: started: startServer(io.appium.uiautomator2.server.test.AppiumUiAutomator2Server)

然后通过这个信息，找到进程号是 5053 ，线程号是 5068（不是高并发，线程号在这里用处不大，可以忽略）。然后找到所有 logcat 里的 5053 内容（推荐保存到文件后，cat + grep 快速过滤）

04-27 03:17:51.933 5053 5053 I art : Late-enabling -Xcheck:jni
04-27 03:17:51.934 5053 5053 W art : Unexpected CPU variant for X86 using defaults: x86
04-27 03:17:51.936 1698 1710 I ActivityManager: Start proc 5053:io.appium.uiautomator2.server/u0a81 for added application io.appium.uiautomator2.server
04-27 03:17:51.952 5053 5060 E art : Failed sending reply to debugger: Broken pipe
04-27 03:17:51.953 5053 5060 I art : Debugger is no longer active
04-27 03:17:51.953 5053 5060 I art : Starting a blocking GC Instrumentation
04-27 03:17:51.958 5053 5053 W System : ClassLoader referenced unknown path: /data/app/io.appium.uiautomator2.server.test-1/lib/x86
04-27 03:17:51.958 5053 5053 W System : ClassLoader referenced unknown path: /data/app/io.appium.uiautomator2.server-1/lib/x86
04-27 03:17:51.961 5053 5053 W System : ClassLoader referenced unknown path:
04-27 03:17:51.971 5053 5053 I MonitoringInstr: Instrumentation started!
04-27 03:17:51.971 5053 5053 I MonitoringInstr: Setting context classloader to 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/data/app/io.appium.uiautomator2.server.test-1/base.apk", zip file "/data/app/io.appium.uiautomator2.server-1/base.apk"],nativeLibraryDirectories=[/data/app/io.appium.uiautomator2.server.test-1/lib/x86, /data/app/io.appium.uiautomator2.server-1/lib/x86, /system/lib, /vendor/lib]]]', Original: 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/data/app/io.appium.uiautomator2.server.test-1/base.apk", zip file "/data/app/io.appium.uiautomator2.server-1/base.apk"],nativeLibraryDirectories=[/data/app/io.appium.uiautomator2.server.test-1/lib/x86, /data/app/io.appium.uiautomator2.server-1/lib/x86, /system/lib, /vendor/lib]]]'
04-27 03:17:51.973 5053 5053 I MonitoringInstr: No JSBridge.
04-27 03:17:51.975 5053 5068 I MonitoringInstr: Setting context classloader to 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/data/app/io.appium.uiautomator2.server.test-1/base.apk", zip file "/data/app/io.appium.uiautomator2.server-1/base.apk"],nativeLibraryDirectories=[/data/app/io.appium.uiautomator2.server.test-1/lib/x86, /data/app/io.appium.uiautomator2.server-1/lib/x86, /system/lib, /vendor/lib]]]', Original: 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/data/app/io.appium.uiautomator2.server.test-1/base.apk", zip file "/data/app/io.appium.uiautomator2.server-1/base.apk"],nativeLibraryDirectories=[/data/app/io.appium.uiautomator2.server.test-1/lib/x86, /data/app/io.appium.uiautomator2.server-1/lib/x86, /system/lib, /vendor/lib]]]'
04-27 03:17:51.979 5053 5068 I UsageTrackerFacilitator: Usage tracking enabled
04-27 03:17:51.979 5053 5068 I TestRequestBuilder: Scanning classpath to find tests in paths [/data/app/io.appium.uiautomator2.server.test-1/base.apk]
04-27 03:17:52.060 5053 5068 D TestExecutor: Adding listener androidx.test.internal.runner.listener.LogRunListener
04-27 03:17:52.060 5053 5068 D TestExecutor: Adding listener androidx.test.internal.runner.listener.InstrumentationResultPrinter
04-27 03:17:52.060 5053 5068 D TestExecutor: Adding listener androidx.test.internal.runner.listener.ActivityFinisherRunListener
04-27 03:17:52.061 5053 5068 I TestRunner: run started: 1 tests
04-27 03:17:52.063 5053 5068 I TestRunner: started: startServer(io.appium.uiautomator2.server.test.AppiumUiAutomator2Server)
04-27 03:17:52.065 5053 5053 I MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
04-27 03:17:52.067 5053 5068 I appium : [AppiumUiAutomator2Server] Starting Server
04-27 03:17:53.072 5053 5068 I appium : AndroidServer created on port 6790
04-27 03:17:53.073 5053 5068 I appium : io.appium.uiautomator2.server started:
04-27 03:17:53.084 5053 5070 I appium : Started UiAutomator2

从最末尾的几条信息看，服务是正常启动了的，没有任何崩溃或者报错相关信息。注意这里有个暗坑，可能手机和电脑时间没达到秒级对齐，所以两边的启动时间稍微有点对不上。

结论

从 logcat 日志看，虽然 appium server 30 秒内都没有能访问通 /status 接口，但也没有明显的崩溃或者退出的错误信息。说明可能两种原因：

1、启动太慢了，30 秒内启动不完。
2、其实已经崩溃了，只是 logcat 没采集到

排查方法也不难，按照 appium 前面指引调大 server 检测的超时时间，同时弄个简单的脚本每秒通过 adb 命令（注意不是网络接口）检测 server 进程是否存活（排除可能性 2）。如果改大后，直到超时进程还存活的话，那继续改大超时；如果已经不存活，从 logcat 里尝试捞崩溃日志再分析。

陈恒捷 #3 · 2022年04月27日

对

马儿不会飞回复

这个是 android 平台，和 ios 的 WDA 没太大关系。 WD = Web Driver 。

黄翔 #4 · 2022年04月28日 Author

对

陈恒捷回复

谢谢指点！
我调大 server 检测的超时时间，'uiautomator2ServerLaunchTimeout':'500000', 还是无法启动 UiAutomator2 server，感觉不是这个设置问题。

我看 logcat 日志里面有这么一行报错，是不是与这个有关？
E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe

另外，如何通过 adb 命令检测 server 进程是否存活？

附上 logcat 日志：
04-28 07:21:31.586 13370 13370 I MonitoringInstr: Instrumentation started!
04-28 07:21:31.609 13370 13370 V TestEventClient: No service name argument was given (testDiscoveryService, testRunEventService or orchestratorService)
04-28 07:21:31.644 13370 13401 I UsageTrackerFacilitator: Usage tracking disabled
04-28 07:21:31.652 13370 13401 I TestRequestBuilder: Scanning classpath to find tests in paths [/data/app/~~DpDz_MtOrwZO3C0yMIuV0A==/io.appium.uiautomator2.server.test-5w5D_m8EN-erDfeyJ8h2aA==/base.apk]
04-28 07:21:31.654 13370 13401 W tomator2.serve: Opening an oat file without a class loader. Are you using the deprecated DexFile APIs?
04-28 07:21:31.892 13370 13401 D TestExecutor: Adding listener androidx.test.internal.runner.listener.LogRunListener
04-28 07:21:31.893 13370 13401 D TestExecutor: Adding listener androidx.test.internal.runner.listener.InstrumentationResultPrinter
04-28 07:21:31.894 13370 13401 D TestExecutor: Adding listener androidx.test.internal.runner.listener.ActivityFinisherRunListener
04-28 07:21:31.897 13370 13401 I TestRunner: run started: 1 tests
04-28 07:21:31.901 13370 13401 I TestRunner: started: startServer(io.appium.uiautomator2.server.test.AppiumUiAutomator2Server)
04-28 07:21:31.910 13370 13401 I appium : [AppiumUiAutomator2Server] Starting Server
04-28 07:21:32.911 13370 13401 I appium : Starting MJPEG Server
04-28 07:21:33.020 13370 13403 V UiAutomation: Init UiAutomation@76f98f7[id=7, flags=0]
04-28 07:21:33.049 13370 13401 I appium : MJPEG Server started
04-28 07:21:33.056 13370 13405 I appium : ServerSocket created on port 7810
04-28 07:21:33.076 13370 13401 I appium : AndroidServer created on port 6790
04-28 07:21:33.077 13370 13401 I appium : io.appium.uiautomator2.server started:
04-28 07:21:33.084 13370 13408 I appium : Started UiAutomator2 io.appium.uiautomator2.http io.appium.uiautomator2.server on port 6790
04-28 07:21:33.170 13370 13409 W tomator2.serve: Accessing hidden method Lsun/misc/VM;->maxDirectMemory() J (greylist, reflection, allowed)
04-28 07:21:33.199 13370 13409 W tomator2.serve: Accessing hidden field Lsun/nio/ch/SelectorImpl;->selectedKeys:Ljava/util/Set; (greylist, reflection, allowed)
04-28 07:21:33.199 13370 13409 W tomator2.serve: Accessing hidden field Lsun/nio/ch/SelectorImpl;->publicSelectedKeys:Ljava/util/Set; (greylist, reflection, allowed)
04-28 07:21:33.298 13370 13370 I Thread-5: type=1400 audit(0.0:901): avc: denied { read } for name="somaxconn" dev="proc" ino=692978 scontext=uuntrusted_app:s0:c212,c256,c512,c768 tcontext=u:object_r:proc_net:s0 tclass=file permissive=1 app=io.appium.uiautomator2.server
04-28 07:21:33.298 13370 13370 I Thread-5: type=1400 audit(0.0:902): avc: denied { open } for path="/proc/sys/net/core/somaxconn" dev="proc" ino=692978 scontext=uuntrusted_app:s0:c212,c256,c512,c768 tcontext=u:object_r:proc_net:s0 tclass=file permissive=1 app=io.appium.uiautomator2.server
04-28 07:21:33.302 13370 13370 I Thread-5: type=1400 audit(0.0:903): avc: denied { getattr } for path="/proc/sys/net/core/somaxconn" dev="proc" ino=692978 scontext=uuntrusted_app:s0:c212,c256,c512,c768 tcontext=u:object_r:proc_net:s0 tclass=file permissive=1 app=io.appium.uiautomator2.server
04-28 07:21:33.854 174 174 I servicemanager: Notifying apexservice they have clients: 1
04-28 07:21:33.841 0 0 I AidlLazyServiceRegistrar: Process has 1 (of 1 available) client(s) in use after notification android.apex.IApexService has clients: 1
04-28 07:21:43.311 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:21:43.311 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:21:44.969 541 580 I ActivityManager: Killing 10915:com.android.keychain/1000 (adj 995): empty for 12917s
04-28 07:21:45.008 286 286 I Zygote : Process 10915 exited due to signal 9 (Killed)
04-28 07:21:45.024 541 583 I libprocessgroup: Successfully killed process cgroup uid 1000 pid 10915 in 46ms
04-28 07:21:48.736 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:21:48.736 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:21:53.666 208 208 I Binder:208_2: type=1400 audit(0.0:904): avc: denied { read } for name="wakeup34" dev="sysfs" ino=19171 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=dir permissive=1
04-28 07:21:53.670 208 208 I Binder:208_2: type=1400 audit(0.0:905): avc: denied { open } for path="/sys/devices/platform/rtc-test.1/wakeup/wakeup34" dev="sysfs" ino=19171 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=dir permissive=1
04-28 07:21:53.670 208 208 I Binder:208_2: type=1400 audit(0.0:906): avc: denied { read } for name="event_count" dev="sysfs" ino=19178 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=file permissive=1
04-28 07:21:53.670 208 208 I Binder:208_2: type=1400 audit(0.0:907): avc: denied { open } for path="/sys/devices/platform/rtc-test.1/wakeup/wakeup34/event_count" dev="sysfs" ino=19178 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=file permissive=1
04-28 07:21:53.670 208 208 I Binder:208_2: type=1400 audit(0.0:908): avc: denied { getattr } for path="/sys/devices/platform/rtc-test.1/wakeup/wakeup34/event_count" dev="sysfs" ino=19178 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=file permissive=1
04-28 07:22:00.024 740 740 D KeyguardClockSwitch: Updating clock: 722
04-28 07:22:23.248 872 13415 D NetworkMonitor/100: PROBE_DNS www.google.com 55ms OK 173.244.217.42,2001::9f8a:1414
04-28 07:22:23.257 872 13416 D NetworkMonitor/100: PROBE_DNS connectivitycheck.gstatic.com 63ms OK 203.208.40.34
04-28 07:22:23.394 872 13416 D NetworkMonitor/100: PROBE_HTTP http://connectivitycheck.gstatic.com/generate_204 time=133ms ret=204 request={Connection=[close], User-Agent=[Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.32 Safari/537.36]} headers={null=[HTTP/1.1 204 No Content], Connection=[close], Content-Length=[0], Date=[Thu, 28 Apr 2022 07:22:24 GMT], X-Android-Received-Millis=[1651130543393], X-Android-Response-Source=[NETWORK 204], X-Android-Selected-Protocol=[http/1.1], X-Android-Sent-Millis=[1651130543306]}
04-28 07:22:36.242 872 13414 D NetworkMonitor/100: PROBE_FALLBACK http://play.googleapis.com/generate_204 Probe failed with exception java.net.SocketTimeoutException: failed to connect to play.googleapis.com/142.251.42.234 (port 80) from /10.0.2.15 (port 59198) after 10000ms
04-28 07:22:43.289 872 13415 D NetworkMonitor/100: PROBE_HTTPS https://www.google.com/generate_204 Probe failed with exception java.net.SocketTimeoutException: failed to connect to www.google.com/173.244.217.42 (port 443) from /10.0.2.15 (port 58190) after 10000ms
04-28 07:22:43.317 872 13414 D NetworkMonitor/100: isCaptivePortal: isSuccessful()=false isPortal()=false RedirectUrl=null isPartialConnectivity()=true Time=20111ms
04-28 07:22:43.329 541 581 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.net.conn.NETWORK_CONDITIONS_MEASURED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
04-28 07:22:43.330 541 664 D ConnectivityService: [100 CELLULAR] validation failed
04-28 07:22:43.374 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:22:43.374 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:22:48.744 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:22:48.744 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:23:00.024 740 740 D KeyguardClockSwitch: Updating clock: 723
04-28 07:23:43.428 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:23:43.428 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:23:48.769 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:23:48.769 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:23:59.329 541 656 E WifiScoringParams: Invalid frequency(-1), using 5G as default rssi array
04-28 07:23:59.374 1278 3759 W TapAndPayGcmRegistratio: No gcm id available, rescheduling [CONTEXT service_id=79 ]
04-28 07:24:00.017 740 740 D KeyguardClockSwitch: Updating clock: 724
04-28 07:24:03.084 541 1572 D WifiNl80211Manager: Scan result ready event
04-28 07:24:03.088 541 1572 D WifiNative: Scan result ready event
04-28 07:24:04.738 208 208 I Binder:208_2: type=1400 audit(0.0:909): avc: denied { read } for name="wakeup34" dev="sysfs" ino=19171 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=dir permissive=1
04-28 07:24:04.738 208 208 I Binder:208_2: type=1400 audit(0.0:910): avc: denied { open } for path="/sys/devices/platform/rtc-test.1/wakeup/wakeup34" dev="sysfs" ino=19171 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=dir permissive=1
04-28 07:24:04.742 208 208 I Binder:208_2: type=1400 audit(0.0:911): avc: denied { read } for name="event_count" dev="sysfs" ino=19178 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=file permissive=1
04-28 07:24:04.742 208 208 I Binder:208_2: type=1400 audit(0.0:912): avc: denied { open } for path="/sys/devices/platform/rtc-test.1/wakeup/wakeup34/event_count" dev="sysfs" ino=19178 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=file permissive=1
04-28 07:24:04.742 208 208 I Binder:208_2: type=1400 audit(0.0:913): avc: denied { getattr } for path="/sys/devices/platform/rtc-test.1/wakeup/wakeup34/event_count" dev="sysfs" ino=19178 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=file permissive=1
04-28 07:24:43.473 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:24:43.473 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:24:48.825 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:24:48.826 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:24:51.426 872 13432 D NetworkMonitor/100: PROBE_DNS connectivitycheck.gstatic.com 25ms OK 203.208.40.34
04-28 07:24:51.435 872 13431 D NetworkMonitor/100: PROBE_DNS www.google.com 33ms OK 128.242.240.157,2001::9f8a:1414
04-28 07:24:51.546 872 13432 D NetworkMonitor/100: PROBE_HTTP http://connectivitycheck.gstatic.com/generate_204 time=117ms ret=204 request={Connection=[close], User-Agent=[Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.32 Safari/537.36]} headers={null=[HTTP/1.1 204 No Content], Connection=[close], Content-Length=[0], Date=[Thu, 28 Apr 2022 07:24:52 GMT], X-Android-Received-Millis=[1651130691543], X-Android-Response-Source=[NETWORK 204], X-Android-Selected-Protocol=[http/1.1], X-Android-Sent-Millis=[1651130691471]}
04-28 07:25:00.007 740 740 D KeyguardClockSwitch: Updating clock: 725
04-28 07:25:11.464 872 13431 D NetworkMonitor/100: PROBE_HTTPS https://www.google.com/generate_204 Probe failed with exception java.net.SocketTimeoutException: failed to connect to www.google.com/2001::9f8a:1414 (port 443) from /fec0::24f5:adee:d837:a257 (port 50184) after 10000ms
04-28 07:25:14.455 872 13430 D NetworkMonitor/100: PROBE_FALLBACK http://www.google.com/gen_204 Probe failed with exception java.net.SocketTimeoutException: failed to connect to www.google.com/2001::9f8a:1414 (port 80) from /fec0::24f5:adee:d837:a257 (port 52760) after 10000ms
04-28 07:25:14.475 872 13430 D NetworkMonitor/100: isCaptivePortal: isSuccessful()=false isPortal()=false RedirectUrl=null isPartialConnectivity()=true Time=23060ms
04-28 07:25:14.476 541 581 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.net.conn.NETWORK_CONDITIONS_MEASURED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
04-28 07:25:14.486 541 664 D ConnectivityService: [100 CELLULAR] validation failed
04-28 07:25:43.502 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:25:43.502 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:25:48.887 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:25:48.887 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:26:00.023 740 740 D KeyguardClockSwitch: Updating clock: 726
04-28 07:26:43.545 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:26:43.545 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:26:48.948 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:26:48.948 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:26:59.391 541 656 E WifiScoringParams: Invalid frequency(-1), using 5G as default rssi array
04-28 07:27:00.028 740 740 D KeyguardClockSwitch: Updating clock: 727
04-28 07:27:03.151 541 1571 D WifiNl80211Manager: Scan result ready event
04-28 07:27:03.152 541 1571 D WifiNative: Scan result ready event
04-28 07:27:05.962 208 208 I Binder:208_2: type=1400 audit(0.0:914): avc: denied { read } for name="event_count" dev="sysfs" ino=19178 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=file permissive=1
04-28 07:27:05.962 208 208 I Binder:208_2: type=1400 audit(0.0:915): avc: denied { open } for path="/sys/devices/platform/rtc-test.1/wakeup/wakeup34/event_count" dev="sysfs" ino=19178 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=file permissive=1
04-28 07:27:05.962 208 208 I Binder:208_2: type=1400 audit(0.0:916): avc: denied { getattr } for path="/sys/devices/platform/rtc-test.1/wakeup/wakeup34/event_count" dev="sysfs" ino=19178 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=file permissive=1
04-28 07:27:26.446 208 208 I Binder:208_2: type=1400 audit(0.0:917): avc: denied { read } for name="wakeup34" dev="sysfs" ino=19171 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=dir permissive=1
04-28 07:27:26.446 208 208 I Binder:208_2: type=1400 audit(0.0:918): avc: denied { open } for path="/sys/devices/platform/rtc-test.1/wakeup/wakeup34" dev="sysfs" ino=19171 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=dir permissive=1
04-28 07:27:43.554 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:27:43.554 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:27:48.970 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:27:48.970 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:28:00.035 740 740 D KeyguardClockSwitch: Updating clock: 728
04-28 07:28:43.561 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:28:43.561 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:28:48.988 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:28:48.989 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:29:00.003 740 740 D KeyguardClockSwitch: Updating clock: 729
04-28 07:29:30.567 872 13452 D NetworkMonitor/100: PROBE_DNS www.google.com 56ms OK 69.30.25.21,2001::4a75:b685
04-28 07:29:30.572 872 13453 D NetworkMonitor/100: PROBE_DNS connectivitycheck.gstatic.com 60ms OK 203.208.41.66
04-28 07:29:30.707 872 13453 D NetworkMonitor/100: PROBE_HTTP http://connectivitycheck.gstatic.com/generate_204 time=132ms ret=204 request={Connection=[close], User-Agent=[Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.32 Safari/537.36]} headers={null=[HTTP/1.1 204 No Content], Connection=[close], Content-Length=[0], Date=[Thu, 28 Apr 2022 07:29:31 GMT], X-Android-Received-Millis=[1651130970703], X-Android-Response-Source=[NETWORK 204], X-Android-Selected-Protocol=[http/1.1], X-Android-Sent-Millis=[1651130970616]}
04-28 07:29:43.579 872 13451 D NetworkMonitor/100: PROBE_FALLBACK http://play.googleapis.com/generate_204 Probe failed with exception java.net.SocketTimeoutException: failed to connect to play.googleapis.com/172.217.163.42 (port 80) from /10.0.2.15 (port 40156) after 10000ms
04-28 07:29:43.580 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:29:43.580 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:29:49.038 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:29:49.038 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:29:49.702 541 10207 I ActivityManager: Force stopping com.mmbox.xbrowser appid=10197 user=0: from pid 13463
04-28 07:29:49.710 978 978 D CarrierSvcBindHelper: No carrier app for: 0
04-28 07:29:49.843 13469 13471 I cmd : oneway function results will be dropped but finished with status OK and parcel size 4
04-28 07:29:50.245 304 363 D goldfish-address-space: claimShared: Ask to claim region [0x3fca8c000 0x3fce10000]
04-28 07:29:50.257 176 176 I hwservicemanager: getTransport: Cannot find entry android.hardware.graphics.mapper@4.0::IMapper/default in either framework or device manifest.
04-28 07:29:50.258 13485 13485 I Gralloc4: mapper 4.x is not supported
04-28 07:29:50.263 13485 13485 D HostConnection: createUnique: call
04-28 07:29:50.263 13485 13485 D HostConnection: HostConnection::get() New Host Connection established 0xf6380ef0, tid 13485
04-28 07:29:50.263 13485 13485 D goldfish-address-space: allocate: Ask for block of size 0x100
04-28 07:29:50.264 13485 13485 D goldfish-address-space: allocate: ioctl allocate returned offset 0x3fbffe000 size 0x2000
04-28 07:29:50.273 13485 13485 D HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_native_sync_v2 ANDROID_EMU_native_sync_v3 ANDROID_EMU_native_sync_v4 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_vulkan ANDROID_EMU_deferred_vulkan_commands ANDROID_EMU_vulkan_null_optional_strings ANDROID_EMU_vulkan_create_resources_with_requirements ANDROID_EMU_YUV_Cache ANDROID_EMU_vulkan_ignored_handles ANDROID_EMU_has_shared_slots_host_memory_allocator ANDROID_EMU_vulkan_free_memory_sync ANDROID_EMU_vulkan_shader_float16_int8 ANDROID_EMU_vulkan_async_queue_submit ANDROID_EMU_sync_buffer_data ANDROID_EMU_read_color_buffer_dma GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_host_side_tracing ANDROID_EMU_gles_max_version_2
04-28 07:29:50.378 13489 13491 I cmd : oneway function results will be dropped but finished with status OK and parcel size 4
04-28 07:29:50.380 1437 2789 I MediaProvider: Begin Intent { act=android.intent.action.MEDIA_SCANNER_SCAN_FILE dat=file:///sdcard/screen.png flg=0x1400010 cmp=com.android.providers.media.module/com.android.providers.media.MediaService }
04-28 07:29:50.378 1437 1437 I com.android.providers.media.module: type=1400 audit(0.0:919): avc: denied { read } for comm=4173796E635461736B202331 name="primary" dev="tmpfs" ino=23780 scontext=umediaprovider_app:s0:c120,c256,c512,c768 tcontext=u:object_r:mnt_pass_through_file:s0 tclass=lnk_file permissive=1 app=com.android.providers.media.module
04-28 07:29:50.401 1437 2789 I MediaProvider: End Intent { act=android.intent.action.MEDIA_SCANNER_SCAN_FILE dat=file:///sdcard/screen.png flg=0x1400010 cmp=com.android.providers.media.module/com.android.providers.media.MediaService }
04-28 07:29:50.600 872 13452 D NetworkMonitor/100: PROBE_HTTPS https://www.google.com/generate_204 Probe failed with exception java.net.SocketTimeoutException: failed to connect to www.google.com/2001::4a75:b685 (port 443) from /fec0::24f5:adee:d837:a257 (port 55128) after 10000ms
04-28 07:29:50.605 872 13451 D NetworkMonitor/100: isCaptivePortal: isSuccessful()=false isPortal()=false RedirectUrl=null isPartialConnectivity()=true Time=20095ms
04-28 07:29:50.606 541 581 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.net.conn.NETWORK_CONDITIONS_MEASURED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
04-28 07:29:50.608 541 664 D ConnectivityService: [100 CELLULAR] validation failed
04-28 07:29:59.431 541 656 E WifiScoringParams: Invalid frequency(-1), using 5G as default rssi array
04-28 07:30:00.013 740 740 D KeyguardClockSwitch: Updating clock: 730
04-28 07:30:03.217 541 10207 D WifiNl80211Manager: Scan result ready event
04-28 07:30:03.217 541 10207 D WifiNative: Scan result ready event
04-28 07:30:20.532 1811 13500 I GmscoreIpa: Starting mediastore instant index
04-28 07:30:20.567 541 959 D CompatibilityChangeReporter: Compat change id reported: 149924527; UID 10087; state: ENABLED
04-28 07:30:20.571 541 959 D CompatibilityChangeReporter: Compat change id reported: 132649864; UID 10087; state: DISABLED
04-28 07:30:43.582 462 462 E netmgr : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
04-28 07:30:43.582 462 462 E netmgr : Failed to open QEMU pipe 'qemud:network': Invalid argument
04-28 07:30:44.210 0 0 D logd : logdr: UID=0 GID=0 PID=13501 b tail=0 logMask=99 pid=0 start=0ns timeout=0ns
04-28 07:30:49.100 470 470 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
04-28 07:30:49.100 470 470 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
04-28 07:30:58.426 208 208 I Binder:208_2: type=1400 audit(0.0:920): avc: denied { read } for name="wakeup34" dev="sysfs" ino=19171 scontext=usystem_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=dir permissive=1

黄翔 #5 · 2022年04月28日 Author

对

马儿不会飞回复

谢谢，有这个可能。可是如何找到合适的 SDK 版本呢？

陈恒捷 #6 · 2022年04月29日

如何通过 adb 命令检测 server 进程是否存活

你之前贴的 appium 日志里就有：2022-04-27 03:17:51:407 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell pm list instrumentation'

E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe

查了下，你这个的进程号和 UIAutomator 无关，而且出现了 N 次，不过既然涉及 port ，确实有一定概率是有关的。要排除也很简单，在关闭 Uiautomator2 server 后，继续捕获 logcat 日志，看会不会出现。会的话说明没关系。

关闭 UIAutomator2 server 的方式，可以参照 appium 日志 2022-04-27 03:17:52:252 [ADB] Running '/lib/android-sdk/platform-tools/adb -P 5037 -s emulator-5554 shell am force-stop io.appium.uiautomator2.server.test'

我调大 server 检测的超时时间，'uiautomator2ServerLaunchTimeout':'500000', 还是无法启动 UiAutomator2 server

从快速解决问题的角度，建议你直接换台别的测试机试试。如果要继续定位，可以参照我上面写的来看，日志实在没线索的话，需要继续追到 UIAutomator2 server 源码。

需要登录后方可回复, 如果你还没有账号请点击这里注册。