Case 运行过程中不断重启 uiautomator，kill process(ps): uiautomator uiautomator-v2 is starting ... left: 40.0s

[llliuyx]

在华为 Mate40、鸿蒙 2.0 手机中运行自动化 case ，运行过程中不断输出以下日志信息，均是 jsonrpc 请求超时导致重启 uiautomator，麻烦有时间帮忙看一下。 备注：应该不是鸿蒙导致的，华为 P30、Andorid10 也有同样问题

[D 211217 18:15:43 init:644] [pid:92845] kill process(ps): uiautomator [D 211217 18:15:44 init:665] [pid:92845] uiautomator-v2 is starting ... left: 40.0s [D 211217 18:15:45 init:665] [pid:92845] uiautomator-v2 is starting ... left: 39.0s [D 211217 18:15:46 init:665] [pid:92845] uiautomator-v2 is starting ... left: 38.0s [D 211217 18:15:47 init:665] [pid:92845] uiautomator-v2 is starting ... left: 36.9s [D 211217 18:15:48 init:665] [pid:92845] uiautomator-v2 is starting ... left: 35.9s [D 211217 18:15:49 init:665] [pid:92845] uiautomator-v2 is starting ... left: 34.9s [D 211217 18:15:50 init:665] [pid:92845] uiautomator-v2 is starting ... left: 33.9s [D 211217 18:15:51 init:665] [pid:92845] uiautomator-v2 is starting ... left: 32.9s [D 211217 18:15:54 init:665] [pid:92845] uiautomator-v2 is starting ... left: 29.8s [D 211217 18:15:57 init:665] [pid:92845] uiautomator-v2 is starting ... left: 26.8s [D 211217 18:16:00 init:665] [pid:92845] uiautomator-v2 is starting ... left: 23.8s [D 211217 18:16:03 init:665] [pid:92845] uiautomator-v2 is starting ... left: 20.8s [D 211217 18:16:06 init:665] [pid:92845] uiautomator-v2 is starting ... left: 17.8s [D 211217 18:16:09 init:665] [pid:92845] uiautomator-v2 is starting ... left: 14.7s [D 211217 18:16:12 init:665] [pid:92845] uiautomator-v2 is starting ... left: 11.7s [D 211217 18:16:15 init:665] [pid:92845] uiautomator-v2 is starting ... left: 8.7s [D 211217 18:16:18 init:665] [pid:92845] uiautomator-v2 is starting ... left: 5.6s [D 211217 18:16:21 init:665] [pid:92845] uiautomator-v2 is starting ... left: 2.6s [I 211217 18:16:25 init:609] [pid:92845] restart-uiautomator since "HTTPConnectionPool(host='127.0.0.1', port=53505): Read timed out. (read timeout=15)" [D 211217 18:16:27 init:644] [pid:92845] kill process(ps): uiautomator [D 211217 18:16:27 init:706] [pid:92845] grant permissions [D 211217 18:16:28 init:665] [pid:92845] uiautomator-v2 is starting ... left: 40.0s [D 211217 18:16:29 init:665] [pid:92845] uiautomator-v2 is starting ... left: 39.0s [D 211217 18:16:30 init:665] [pid:92845] uiautomator-v2 is starting ... left: 38.0s [D 211217 18:16:31 init:665] [pid:92845] uiautomator-v2 is starting ... left: 37.0s [D 211217 18:16:32 init:665] [pid:92845] uiautomator-v2 is starting ... left: 35.9s [D 211217 18:16:33 init:665] [pid:92845] uiautomator-v2 is starting ... left: 34.9s [D 211217 18:16:34 init:665] [pid:92845] uiautomator-v2 is starting ... left: 33.9s [D 211217 18:16:35 init:665] [pid:92845] uiautomator-v2 is starting ... left: 32.9s [I 211217 18:16:35 init:626] [pid:92845] uiautomator back to normal [D 211217 18:18:14 init:644] [pid:92845] kill process(ps): uiautomator [D 211217 18:18:15 init:665] [pid:92845] uiautomator-v2 is starting ... left: 40.0s [D 211217 18:18:16 init:665] [pid:92845] uiautomator-v2 is starting ... left: 39.0s [D 211217 18:18:17 init:665] [pid:92845] uiautomator-v2 is starting ... left: 38.0s [D 211217 18:18:18 init:665] [pid:92845] uiautomator-v2 is starting ... left: 36.9s [D 211217 18:18:19 init:665] [pid:92845] uiautomator-v2 is starting ... left: 35.9s [D 211217 18:18:20 init:665] [pid:92845] uiautomator-v2 is starting ... left: 34.9s [D 211217 18:18:21 init:665] [pid:92845] uiautomator-v2 is starting ... left: 33.9s [I 211217 18:18:21 init:626] [pid:92845] uiautomator back to normal [D 211217 18:19:29 init:644] [pid:92845] kill process(ps): uiautomator [D 211217 18:19:30 init:665] [pid:92845] uiautomator-v2 is starting ... left: 40.0s [D 211217 18:19:31 init:665] [pid:92845] uiautomator-v2 is starting ... left: 39.0s [D 211217 18:19:32 init:665] [pid:92845] uiautomator-v2 is starting ... left: 38.0s [D 211217 18:19:33 init:665] [pid:92845] uiautomator-v2 is starting ... left: 36.9s [D 211217 18:19:34 init:665] [pid:92845] uiautomator-v2 is starting ... left: 35.9s [D 211217 18:19:35 init:665] [pid:92845] uiautomator-v2 is starting ... left: 34.9s [D 211217 18:19:36 init:665] [pid:92845] uiautomator-v2 is starting ... left: 33.9s [I 211217 18:19:36 init:626] [pid:92845] uiautomator back to normal [D 211217 18:19:54 init:644] [pid:92845] kill process(ps): uiautomator [D 211217 18:19:55 init:665] [pid:92845] uiautomator-v2 is starting ... left: 40.0s [D 211217 18:19:56 init:665] [pid:92845] uiautomator-v2 is starting ... left: 39.0s [D 211217 18:19:57 init:665] [pid:92845] uiautomator-v2 is starting ... left: 38.0s [D 211217 18:19:58 init:665] [pid:92845] uiautomator-v2 is starting ... left: 36.9s [D 211217 18:19:59 init:665] [pid:92845] uiautomator-v2 is starting ... left: 35.9s [D 211217 18:20:00 init:665] [pid:92845] uiautomator-v2 is starting ... left: 34.9s [D 211217 18:20:01 init:665] [pid:92845] uiautomator-v2 is starting ... left: 33.9s [D 211217 18:20:02 init:665] [pid:92845] uiautomator-v2 is starting ... left: 32.8s [D 211217 18:20:05 init:665] [pid:92845] uiautomator-v2 is starting ... left: 29.8s [D 211217 18:20:08 init:665] [pid:92845] uiautomator-v2 is starting ... left: 26.8s [D 211217 18:20:11 init:665] [pid:92845] uiautomator-v2 is starting ... left: 23.8s [D 211217 18:20:14 init:665] [pid:92845] uiautomator-v2 is starting ... left: 20.7s [D 211217 18:20:17 init:665] [pid:92845] uiautomator-v2 is starting ... left: 17.7s [D 211217 18:20:20 init:665] [pid:92845] uiautomator-v2 is starting ... left: 14.7s [D 211217 18:20:23 init:665] [pid:92845] uiautomator-v2 is starting ... left: 11.7s [D 211217 18:20:26 init:665] [pid:92845] uiautomator-v2 is starting ... left: 8.6s [D 211217 18:20:29 init:665] [pid:92845] uiautomator-v2 is starting ... left: 5.6s [D 211217 18:20:32 init:665] [pid:92845] uiautomator-v2 is starting ... left: 2.6s [I 211217 18:20:35 init:609] [pid:92845] restart-uiautomator since "HTTPConnectionPool(host='127.0.0.1', port=53505): Read timed out. (read timeout=15)"

"HTTPConnectionPool(host='127.0.0.1', port=53505): Read timed out.

一些排查进展： 疑点一： 在抛异常出加以下代码，能够获取 version 值，证明 pc 端与手机端 forward 建立的网络没问题，仅 jsonrpc 相关请求失败

疑点二： 查看 atx-agent.daemon.log 日志，发现大量 proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 错误，怀疑 go 服务与android-uiautomator-server 服务建立的连接有问题， 好像是 android-uiautomator-server 服务有问题，该日志报错与 Case 中重启 uiautomator 时间点能够对上，但是不知道接下来该怎么查了，go 服务源码中也没有找到 reverseproxy.go 文件 手机中查看 9008 端口显示内容： HWOCE-L:/ $ netstat -anl | grep 9008 tcp 0 0 127.0.0.1:44420 127.0.0.1:9008 ESTABLISHED tcp6 1 0 :::9008 :::* LISTEN tcp6 366 0 ::ffff:127.0.0.1:9008 ::ffff:127.0.0.1:44420 ESTABLISHED

atx-agent.daemon.log日志 2021/12/17 18:18:17 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:18:18 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:18:19 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:18:20 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:18:21 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:19:27 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:19:29 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:19:30 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused INSTRUMENTATION_STATUS: class=com.github.uiautomator.stub.Stub INSTRUMENTATION_STATUS: current=1 INSTRUMENTATION_STATUS: id=AndroidJUnitRunner INSTRUMENTATION_STATUS: numtests=1 INSTRUMENTATION_STATUS: stream= com.github.uiautomator.stub.Stub: INSTRUMENTATION_STATUS: test=testUIAutomatorStub INSTRUMENTATION_STATUS_CODE: 1 2021/12/17 18:19:31 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:19:32 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:19:33 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:19:34 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:19:35 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:19:53 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:19:55 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:19:56 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused INSTRUMENTATION_STATUS: class=com.github.uiautomator.stub.Stub INSTRUMENTATION_STATUS: current=1 INSTRUMENTATION_STATUS: id=AndroidJUnitRunner INSTRUMENTATION_STATUS: numtests=1 INSTRUMENTATION_STATUS: stream= com.github.uiautomator.stub.Stub: INSTRUMENTATION_STATUS: test=testUIAutomatorStub INSTRUMENTATION_STATUS_CODE: 1 2021/12/17 18:19:57 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:19:58 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:19:59 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:20:00 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:20:01 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:20:02 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:20:05 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:08 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:11 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:14 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:17 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:20 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:23 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:26 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:29 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:32 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:35 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:38 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:20:39 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused INSTRUMENTATION_STATUS: class=com.github.uiautomator.stub.Stub INSTRUMENTATION_STATUS: current=1 INSTRUMENTATION_STATUS: id=AndroidJUnitRunner INSTRUMENTATION_STATUS: numtests=1 INSTRUMENTATION_STATUS: stream= com.github.uiautomator.stub.Stub: INSTRUMENTATION_STATUS: test=testUIAutomatorStub INSTRUMENTATION_STATUS_CODE: 1 2021/12/17 18:20:40 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:20:41 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:20:43 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:20:44 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:20:45 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:21:52 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:21:54 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:21:55 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused INSTRUMENTATION_STATUS: class=com.github.uiautomator.stub.Stub INSTRUMENTATION_STATUS: current=1 INSTRUMENTATION_STATUS: id=AndroidJUnitRunner INSTRUMENTATION_STATUS: numtests=1 INSTRUMENTATION_STATUS: stream= com.github.uiautomator.stub.Stub: INSTRUMENTATION_STATUS: test=testUIAutomatorStub INSTRUMENTATION_STATUS_CODE: 1 2021/12/17 18:21:56 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:21:57 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:21:58 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:21:59 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:22:00 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused 2021/12/17 18:22:18 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:22:20 reverseproxy.go:437: http: proxy error: context canceled 2021/12/17 18:22:21 reverseproxy.go:437: http: proxy error: dial tcp 127.0.0.1:9008: connect: connection refused

[llliuyx]

貌似已经解决，Android doze 模式使 App 在后台时网络请求延迟。执行以下命令将应用加到白名单中然后再重启手机就行了 adb shell dumpsys deviceidle whitelist +com.github.uiautomator adb shell dumpsys deviceidle whitelist +com.github.uiautomator.test

如果还不行，可以再执行 adb shell dumpsys deviceidle disable all 将其关闭，然后再重启试试