Appium:未知错误：处理命令时发生未知服务器端错误。原始错误：超过240000毫秒的超时

Question

更新到appium版本1.20.0后，这个未知的服务器端错误开始更频繁地发生，我以前见过这个错误，但真的是零星的，我认为这是由于断开引起的超时，现在每次我在同一个版本中运行测试时都会发生执行点。

Appium版本：1.20.0设备：Pixel 3（仿真器）Android API 30

鸦片原木

[HTTP] --> POST /wd/hub/session/43679e36-4a7a-4510-92eb-ca185983324c/elements
[HTTP] {"using":"accessibility id","value":"log ind"}
[debug] [W3C (43679e36)] Calling AppiumDriver.findElements() with args: ["accessibility id","log ind","43679e36-4a7a-4510-92eb-ca185983324c"]
[debug] [BaseDriver] Valid locator strategies for this request: xpath, id, class name, accessibility id, css selector, -android uiautomator
[debug] [BaseDriver] Waiting up to 20000 ms for condition
[debug] [WD Proxy] Matched '/elements' to command name 'findElements'
[debug] [WD Proxy] Proxying [POST /elements] to [POST http://127.0.0.1:8201/wd/hub/session/e7a87712-7afd-47bf-9b98-24754f12ba38/elements] with body: {"strategy":"accessibility id","selector":"log ind","context":"","multiple":true}
[WD Proxy] Error: timeout of 240000ms exceeded
[WD Proxy]     at createError (/usr/local/lib/node_modules/appium/node_modules/axios/lib/core/createError.js:16:15)
[WD Proxy]     at RedirectableRequest.handleRequestTimeout (/usr/local/lib/node_modules/appium/node_modules/axios/lib/adapters/http.js:280:16)
[WD Proxy]     at Object.onceWrapper (events.js:422:26)
[WD Proxy]     at RedirectableRequest.emit (events.js:315:20)
[WD Proxy]     at ClientRequest.eventHandlers.<computed> (/usr/local/lib/node_modules/appium/node_modules/follow-redirects/index.js:13:24)
[WD Proxy]     at ClientRequest.emit (events.js:315:20)
[WD Proxy]     at Socket.emitRequestTimeout (_http_client.js:768:9)
[WD Proxy]     at Object.onceWrapper (events.js:421:28)
[WD Proxy]     at Socket.emit (events.js:327:22)
[WD Proxy]     at Socket._onTimeout (net.js:480:8)
[WD Proxy]     at listOnTimeout (internal/timers.js:549:17)
[WD Proxy]     at processTimers (internal/timers.js:492:7)
[debug] [W3C (43679e36)] Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: Could not proxy command to the remote server. Original error: timeout of 240000ms exceeded
[debug] [W3C (43679e36)]     at UIA2Proxy.command (/usr/local/lib/node_modules/appium/node_modules/appium-base-driver/lib/jsonwp-proxy/proxy.js:275:13)
[debug] [W3C (43679e36)]     at processTicksAndRejections (internal/process/task_queues.js:97:5)
[debug] [W3C (43679e36)]     at AndroidUiautomator2Driver.helpers.doFindElementOrEls (/usr/local/lib/node_modules/appium/node_modules/appium-uiautomator2-driver/lib/commands/find.js:30:12)
[debug] [W3C (43679e36)]     at doFind (/usr/local/lib/node_modules/appium/node_modules/appium-android-driver/lib/commands/find.js:36:17)
[debug] [W3C (43679e36)]     at wrappedCondFn (/usr/local/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/commands/timeout.js:151:12)
[debug] [W3C (43679e36)]     at spin (/usr/local/lib/node_modules/appium/node_modules/asyncbox/lib/asyncbox.js:138:20)
[debug] [W3C (43679e36)]     at waitForCondition (/usr/local/lib/node_modules/appium/node_modules/asyncbox/lib/asyncbox.js:154:10)
[debug] [W3C (43679e36)]     at AndroidUiautomator2Driver.implicitWaitForCondition (/usr/local/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/commands/timeout.js:153:10)
[debug] [W3C (43679e36)]     at AndroidUiautomator2Driver.findElOrEls (/usr/local/lib/node_modules/appium/node_modules/appium-android-driver/lib/commands/find.js:60:5)
[debug] [W3C (43679e36)]     at AndroidUiautomator2Driver.findElOrElsWithProcessing (/usr/local/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/commands/find.js:33:12)
[debug] [W3C (43679e36)]     at AndroidUiautomator2Driver.findElements (/usr/local/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/commands/find.js:63:10)
[HTTP] <-- POST /wd/hub/session/43679e36-4a7a-4510-92eb-ca185983324c/elements 500 60006 ms - 1876

亚洲开发银行日志

01-10 02:37:11.063   565   637 I DropBoxManagerService: add tag=event_data isTagEnabled=true flags=0x2
01-10 02:37:11.066   565   608 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
01-10 02:37:11.066   565   608 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
01-10 02:37:11.103  7038  8988 I NetworkScheduler.Stats: Task com.google.android.gms/com.google.android.gms.checkin.EventLogService finished executing. cause:2 result: 1 elapsed_millis: 177 uptime_millis: 177 exec_start_elapsed_seconds: 12769 [CONTEXT service_id=218 ]
01-10 02:37:12.895   565   608 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
01-10 02:37:12.895   565   608 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
01-10 02:37:20.885   565   599 E JobScheduler.Background: App com.google.android.gms became active but still in NEVER bucket
01-10 02:37:20.887   565   608 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
01-10 02:37:22.895   565   608 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
01-10 02:37:22.895   565   608 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
01-10 02:37:26.085   266 25461 E android.system.suspend@1.0-service: Error opening kernel wakelock stats for: wakeup34: Permission denied
01-10 02:37:26.079   266   266 W Binder:266_3: type=1400 audit(0.0:10881): avc: denied { read } for name="wakeup34" dev="sysfs" ino=17466 scontext=u:r:system_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=dir permissive=0
01-10 02:37:26.091   266 25461 E android.system.suspend@1.0-service: Error opening kernel wakelock stats for: wakeup35: Permission denied
01-10 02:37:26.087   266   266 W Binder:266_3: type=1400 audit(0.0:10882): avc: denied { read } for name="wakeup35" dev="sysfs" ino=17526 scontext=u:r:system_suspend:s0 tcontext=u:object_r:sysfs:s0 tclass=dir permissive=0
01-10 02:37:38.154   435   435 E netmgr  : qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:network' service: Invalid argument
01-10 02:37:38.154   435   435 E netmgr  : Failed to open QEMU pipe 'qemud:network': Invalid argument
01-10 02:37:38.538   438   438 E wifi_forwarder: qemu_pipe_open_ns:62: Could not connect to the 'pipe:qemud:wififorward' service: Invalid argument
01-10 02:37:38.538   438   438 E wifi_forwarder: RemoteConnection failed to initialize: RemoteConnection failed to open pipe
01-10 02:38:13.546   565   565 D CompatibilityChangeReporter: Compat change id reported: 135634846; UID 10115; state: DISABLED
01-10 02:38:13.546   565   609 D CompatibilityChangeReporter: Compat change id reported: 143937733; UID 10115; state: DISABLED
01-10 02:38:13.569   565  1750 D WifiNl80211Manager: Scan result ready event
01-10 02:38:13.569   565  1750 D WifiNative: Scan result ready event
01-10 02:38:13.577   357   357 D Zygote  : Forked child process 13230
01-10 02:38:13.584   565   609 I ActivityManager: Start proc 13230:com.google.android.videos/u0a115 for service {com.google.android.videos/androidx.work.impl.background.systemjob.SystemJobService}
01-10 02:38:13.599 13230 13230 W .android.video: Unexpected CPU variant for X86 using defaults: x86
01-10 02:38:13.615 13230 13230 E .android.video: Not starting debugger since process cannot load the jdwp agent.
01-10 02:38:13.656 13230 13230 D ApplicationLoaders: Returning zygote-cached class loader: /system/framework/android.test.base.jar
01-10 02:38:13.659 13230 13230 I .android.video: The ClassLoaderContext is a special shared library.
01-10 02:38:13.674 13230 13230 I .android.video: The ClassLoaderContext is a special shared library.
01-10 02:38:13.706 13230 13230 D NetworkSecurityConfig: No Network Security Config specified, using platform default
01-10 02:38:13.707 13230 13230 D NetworkSecurityConfig: No Network Security Config specified, using platform default
01-10 02:38:13.869 13230 13230 I TetheringManager: registerTetheringEventCallback:com.google.android.videos
01-10 02:38:14.007 13230 13266 W PlayMovies: esk.run:3 User config found

Answer 1

当io.appium.uiautomator2.server应用程序在Android端被杀死时，通常会引发此异常。在测试运行期间，系统可能会杀死它。还要确保设备在测试期间没有锁定。

基于1.20.0版本说明，他们对这些包做了一些更改。我建议您从设备中删除它们（通过设置-

Appium将io.Appium.settings、io.Appium.uiautomator2.server和io.Appium.uiautomator2.server.test添加为设备的Doze白名单，以保持Appium-uiautomator2-driver#420正常工作