最近写用例碰到特定场景下的 tap‘卡死’ 情况，特定场景是啥也就不细说了，后面看造成卡死的原因更直观。

一.查看 appium server 日志

遇到这种问题，首先肯定是查看日志了，查看 appium desktop 的 server 端日志，发现是请求并没有 response 返回：

[HTTP] --> POST /wd/hub/session/eb76cf26-2009-41ca-a5e7-f46d8ba994f3/touch/perform {"sessionId":"eb76cf26-2009-41ca-a5e7-f46d8ba994f3","actions":[{"action":"tap","options":{"y":647,"x":325,"count":1}}]}
[MJSONWP] Calling AppiumDriver.performTouch() with args: [[{"action":"tap","options":{"y":647,"x":325,"count":1}}],"eb76cf26-2009-41ca-a5e7-f46d8ba994f3"]
[XCUITest] Executing command 'performTouch'
[XCUITest] Received the following touch action: tap(options={"y":647,"x":325,"count":1})
[XCUITest] Found matching gesture: tap
[JSONWP Proxy] Proxying [POST /wda/tap/0] to [POST http://localhost:8100/session/6012A53D-F30C-4EFD-8F57-C02122276164/wda/tap/0] with body: {"x":325,"y":647}
[JSONWP Proxy] Got response with status 200: {"value":{},"sessionId":"6012A53D-F30C-4EFD-8F57-C02122276164","status":0}
[MJSONWP] Responding to client with driver.performTouch() result: null
[HTTP] <-- POST /wd/hub/session/eb76cf26-2009-41ca-a5e7-f46d8ba994f3/touch/perform 200 361951 ms - 76 

看到这里,小菜鸟马上无脑的跑去 appium-python-client 提了个 issue，人家没搭理，后来再想想自己真是挺无脑的，明明是 client 端发送 request 之后 server 没返回，于是马上去 close 掉之前提的 issue，然后又继续无脑的先转给 appium 先，自己再继续查下去，感觉这样总是多一丝希望。

二.WebDriverAgent 添加日志调试

将这个 issue 转给 appium 之后，那边倒是回复挺快的，好像是说不是他们的问题，他们直接透传之类的吧，让我转给 WebDriverAgent(以下简称 WDA)，那还用说肯定是先转了再说，也算是保留另外的一线希望吧，当然自己也没停歇，打开了 WDA（如果是想通过运行 appium 打印 log，就得进到 appium 目录下的 wda）工程，研究起来，当时也就想在关键代码位置添加自己的 log，看下执行 server 端是在哪里卡住了，没有将 response 返回到 client，于是在WebServer.m的请求转发的路由器注册方法里分别将 request 和 response 打印，接着就是找到执行 tap 命令的方法了，在FBElementCommands.m文件中 tap 执行前后都加上了日志，截取代码如下：

WebServer.m 文件

- (void)registerRouteHandlers:(NSArray *)commandHandlerClasses
{
  for (Class<FBCommandHandler> commandHandler in commandHandlerClasses) {
    NSArray *routes = [commandHandler routes];
    for (FBRoute *route in routes) {
      [self.server handleMethod:route.verb withPath:route.path block:^(RouteRequest *request, RouteResponse *response) {
        NSDictionary *arguments = [NSJSONSerialization JSONObjectWithData:request.body options:NSJSONReadingMutableContainers error:NULL];
        FBRouteRequest *routeParams = [FBRouteRequest
          routeRequestWithURL:request.url
          parameters:request.params
          arguments:arguments ?: @{}
        ];

        [FBLogger verboseLog:routeParams.description];
        [FBLogger logFmt:@"custom Log in method registerRouteHandlers request : %@",request.description]; //自己加上的日志
        [FBLogger logFmt:@"custom Log in method registerRouteHandlers response : %@",response.description]; //自己加上的日志
        @try {
          [route mountRequest:routeParams intoResponse:response];
        }
        @catch (NSException *exception) {
          [FBLogger logFmt:@"custom Log in method registerRouteHandlers throw exception: %@", exception];
          [self handleException:exception forResponse:response];
        }
      }];
    }
  }
}

FBElementCommands.m 文件

+ (id<FBResponsePayload>)handleTap:(FBRouteRequest *)request
{
  FBElementCache *elementCache = request.session.elementCache;
  CGPoint tapPoint = CGPointMake((CGFloat)[request.arguments[@"x"] doubleValue], (CGFloat)[request.arguments[@"y"] doubleValue]);
  XCUIElement *element = [elementCache elementForUUID:request.parameters[@"uuid"]];
  if (nil == element) {
      XCUICoordinate *tapCoordinate = [self.class gestureCoordinateWithCoordinate:tapPoint application:request.session.application shouldApplyOrientationWorkaround:YES];
      [FBLogger logFmt:@"custom Log in method handleTap tap start"];  //自己加上的日志
      [tapCoordinate tap];
      [FBLogger logFmt:@"custom Log in method handleTap tap finish"];   //自己加上的日志
  } else {
    NSError *error;
    if (![element fb_tapCoordinate:tapPoint error:&error]) {
      return FBResponseWithError(error);
    }
  }
  id<FBResponsePayload> responsePayload = FBResponseWithOK();
  [FBLogger logFmt:@"custom Log in method handleTap return responsePayload: %@", responsePayload];   //自己加上的日志

  return responsePayload;
}

加上自己的 log 之后，再次运行 appium，同时打开模拟器的 system.log 日志文件搜索自己日志（这里推荐在终端使用tail -f <filepath> | grep 'custom Log in method'过滤日志更直观），很快就发现是在执行[tapCoordinate tap];方法没能继续往下执行了，总算找到问题所在了。

Apr 26 10:33:10 iStevendeMacBook-Pro XCTRunner[53169]: custom Log in method registerRouteHandlers request : POST /session/2DBDFBEA-D766-4EC7-8B2A-9AB1FB4853B8/element/0A3F20E7-31D8-4074-B7ED-820B169F65F8/click HTTP/1.1

    Host: localhost:8100

    Accept: */*

    Content-Type: application/json

    User-Agent: appium

    Content-Length: 96

    Connection: keep-alive



    {"sessionId":"c2d6c2f2-1347-46c9-8f5a-bfb588f6277e","id":"0A3F20E7-31D8-4074-B7ED-820B169F65F8"}
Apr 26 10:33:10 iStevendeMacBook-Pro XCTRunner[53169]: custom Log in method registerRouteHandlers response : <RouteResponse: 0x600000432700>
Apr 26 10:33:11 iStevendeMacBook-Pro XCTRunner[53169]: custom Log in method registerRouteHandlers request : POST /session/2DBDFBEA-D766-4EC7-8B2A-9AB1FB4853B8/wda/tap/0 HTTP/1.1

    Host: localhost:8100

    Accept: */*

    Content-Type: application/json

    User-Agent: appium

    Content-Length: 15

    Connection: keep-alive



    {"x":40,"y":48}
Apr 26 10:33:11 iStevendeMacBook-Pro XCTRunner[53169]: custom Log in method registerRouteHandlers response : <RouteResponse: 0x60000042b3e0>
Apr 26 10:33:11 iStevendeMacBook-Pro XCTRunner[53169]: custom Log in method handleTap tap start

可是 tap 方法是私有的，并不能再进一步看到其实现，也就没有办法了解更多详细信息了，于是觉得必须通过 XCode 来运行 WDA 进行 debug，看能否查看更多信息，以及调用栈，线程相关信息。

三.终端 curl 模拟请求，WebDriverAgent Debug

对 Appium 有一定了解的同学肯定知道该框架是一个基于 WebDriver 协议的 C/S 模式测试框架，而服务端就是用的 WDA，于是我们想可以绕过 Appium，这样一来就不是通过命令 xcodebuild 启动的服务，直接通过 Xcode 启动 server，再通过终端模拟请求，就可以进行 debug 了。

1.首先打开 WebDriverAgent 工程，Product->Test，开启服务端，看到ServerURLHere->http://10.180.185.191:8100<-ServerURLHere成功

2017-04-26 17:21:19.326 XCTRunner[65123:1790615] Running tests...
2017-04-26 17:21:20.688 XCTRunner[65123:1790615] Continuing to run tests in the background with task ID 1
Test Suite 'All tests' started at 2017-04-26 17:21:21.642
Test Suite 'WebDriverAgentRunner.xctest' started at 2017-04-26 17:21:21.643
Test Suite 'UITestingUITests' started at 2017-04-26 17:21:21.644
Test Case '-[UITestingUITests testRunner]' started.
    t =     0.00s     Start Test at 2017-04-26 17:21:21.645
    t =     0.00s     Set Up
2017-04-26 17:21:21.651 XCTRunner[65123:1790615] Built at Apr 26 2017 17:20:53
2017-04-26 17:21:21.670 XCTRunner[65123:1790615] ServerURLHere->http://10.180.185.191:8100<-ServerURLHere

2.然后打开终端执行 curl 命令给 server 端发送请求，模拟出现 tap‘卡死’ 的复现步骤

(1) 启动 app

Request

curl -X POST '-H "Content-Type:application/json"' -d "{\"desiredCapabilities\":{\"bundleId\":\"com.your app bundleId\"}}"  http://localhost:8100/session

Response

{
  "value" : {
    "sessionId" : "316201BF-AC36-4C48-B267-E427FFD32DB5",
    "capabilities" : {
      "device" : "iphone",
      "browserName" : "小爽bank",
      "sdkVersion" : "10.3",
      "CFBundleIdentifier" : "com.tzbank.pingAnFF"
    }
  },
  "sessionId" : "316201BF-AC36-4C48-B267-E427FFD32DB5",
  "status" : 0
}%       

后续请求带上返回的 sessionId 即可

(2) tap 点击’ 我的’

Request

curl -X POST '-H "Content-Type:application/json"' -d "{\"x\":\"325\",\"y\":\"647\"}" http://localhost:8100/session/316201BF-AC36-4C48-B267-E427FFD32DB5/wda/tap/0

更多请求查看WebDriverAgent Wiki
示例中没有 tap 坐标的例子，google 到的有些也是过期的，建议直接查看FBElementCommands

如图：

再到控制台输出其实就可以看出问题了，每次在执行Synthesize event之前都要Wait for app to idle,也就是说要等待 app 空闲才会去执行 XCTest 的事件，而再看没有返回的那次请求多了一行App animations complete notification not received, will attempt to continue.,有了这个关键信息基本上就可以面向 google 编程找到答案了。

正常的一次 tap

2017-04-26 11:29:06.603 XCTRunner[54676:1544841] custom Log in method handleTap tap start
    t =   352.89s     Tap Target Application 0x6080000b11c0[0.00, 0.00] -> (40.0, 48.0)
    t =   352.89s         Find the Target Application 0x6080000b11c0
    t =   352.89s             Use cached accessibility hierarchy for com.xxx
    t =   353.01s             Wait for app to idle
    t =   353.04s         Synthesize event
    t =   353.04s             Find the Target Application 0x6080000b11c0
    t =   353.04s                 Snapshot accessibility hierarchy for com.xxx
2017-04-26 11:29:10.516 XCTRunner[54676:1544841] custom Log in method handleTap tap finish
2017-04-26 11:29:10.517 XCTRunner[54676:1544841] custom Log in method handleTap return responsePayload: {
    sessionId = "316201BF-AC36-4C48-B267-E427FFD32DB5";
    status = 0;
    value =     {
    };
}

卡住的一次 tap

2017-04-26 11:29:06.603 XCTRunner[54676:1544841] custom Log in method handleTap tap start
    t =   352.89s     Tap Target Application 0x6080000b11c0[0.00, 0.00] -> (40.0, 48.0)
    t =   352.89s         Find the Target Application 0x6080000b11c0
    t =   352.89s             Use cached accessibility hierarchy for com.xxx
    t =   353.01s             Wait for app to idle
    t =   500.28s                 App animations complete notification not received, will attempt to continue.
    t =   500.28s         Synthesize event
    t =   500.34s             Find the Target Application 0x6080000b11c0
    t =   500.34s                 Snapshot accessibility hierarchy for com.xxx
2017-04-26 11:33:05.516 XCTRunner[54676:1544841] custom Log in method handleTap tap finish
2017-04-26 11:33:05.517 XCTRunner[54676:1544841] custom Log in method handleTap return responsePayload: {
    sessionId = "316201BF-AC36-4C48-B267-E427FFD32DB5";
    status = 0;
    value =     {
    };
}

四. 面向 google 编程，stackoverflow 找到真相

这里就不多说了，直接贴上http://stackoverflow.com/questions/40983184/xcode-8-ui-testing-taking-very-long
根据上面描述，确实我们这个用例的操作路径存在登录完成回到 ‘我的’ 页面有个主动下拉刷新的操作，最后也确实注释掉这个动画就正常了，至于是否是动画状态不对是接下来要去查的问题了，至少之前这个让我都不知道怎么去 google 的 ‘卡死’ 问题解决了...

如果有知道更细信息的同学，希望可以不吝赐教，期待与大家一起学习交流。