Mac2 Driver Issue

Support
1

I find WDAM very prone to interruption anomalies
Could you help keep Xctest running even if there are some errors
Version: [email protected] [installed (NPM)]

For example,
2022-05-18 16:51:54:757 - [debug] [WD Proxy] Matched ‘/element’ to command name ‘findElement’
2022-05-18 16:51:54:757 - [debug] [WD Proxy] Proxying [POST /element] to [POST http://127.0.0.1:9002/session/E275EC34-E77C-46C9-8615-300E1C2901CC/element] with body: {“using”:“predicate string”,“value”:“elementType == 48 AND value == ‘Live’”}
2022-05-18 16:51:54:758 - [debug] [WebDriverAgentMac] [xcodebuild] t = 297.34s Get all elements bound by accessibility element for: Elements matching predicate ‘elementType == 48 AND value == “Live”’
2022-05-18 16:51:55:132 - [debug] [WebDriverAgentMac] [xcodebuild] WebDriverAgentRunner.m:54: Expected failure in -[UITestingUITests testRunner]: Failed to resolve query: Failed to resolve remote element AX element pid: 82592, token: oEIBAAAAAABvY29jKgAAAAAAAAA=. (Underlying Error: Timed out snapshotting io.appium.WebDriverAgentRunner.xctrunner, app is either unresponsive or taking too long to snapshot.)Reason: (Ignore all failures)
2022-05-18 16:51:55:135 - [WD Proxy] Got response with status 404: {“value”:{“error”:“no such element”,“message”:“unable to find an element using ‘predicate string’, value ‘elementType == 48 AND value == ‘Live’’”,“traceback”:"(\n\t0 WebDriverAgentLib 0x00000001058f2a62 FBNoSuchElementErrorResponseForRequest + 290\n\t1 WebDriverAgentLib 0x00000001058f27ea +[FBFindElementCommands handleFindElement:] + 426\n\t2 WebDriverAgentLib 0x00000001059386cc -[FBRoute_TargetAction mountRequest:intoResponse:] + 172\n\t3 WebDriverAgentLib 0x00000001059324a9 __37-[FBWebServer registerRouteHandlers:]_block_invoke + 777\n\t4 WebDriverAgentLib 0x000000010592ba9d -[RoutingHTTPServer handleRoute:withRequest:response:] + 189\n\t5 WebDriverAgentLib 0x000000010592c7f1 __72-[RoutingHTTPServer routeMethod:withPath:parameters:request:connection:]_block_invoke + 65\n\t6 libdispatch.dylib 0x00007fff20251806 _dispatch_client_callout + 8\n\t7 libdispatch.dylib …
2022-05-18 16:51:55:135 - [debug] [W3C] Matched W3C error code ‘no such element’ to NoSuchElementError
2022-05-18 16:51:55:135 - [debug] [Mac2Driver@0b55 (5b556c85)] Encountered internal error running command: NoSuchElementError: unable to find an element using ‘predicate string’, value ‘elementType == 48 AND value == ‘Live’’
2022-05-18 16:51:55:135 - [debug] [Mac2Driver@0b55 (5b556c85)] at errorFromW3CJsonCode (/Users/rcadmin/.appium/node_modules/appium-mac2-driver/node_modules/@appium/base-driver/lib/protocol/errors.js:780:25)
2022-05-18 16:51:55:135 - [debug] [Mac2Driver@0b55 (5b556c85)] at ProxyRequestError.getActualError (/Users/rcadmin/.appium/node_modules/appium-mac2-driver/node_modules/@appium/base-driver/lib/protocol/errors.js:663:14)
2022-05-18 16:51:55:135 - [debug] [Mac2Driver@0b55 (5b556c85)] at WDAMacProxy.command (/Users/rcadmin/.appium/node_modules/appium-mac2-driver/node_modules/@appium/base-driver/lib/jsonwp-proxy/proxy.js:275:19)
2022-05-18 16:51:55:135 - [debug] [Mac2Driver@0b55 (5b556c85)] at runMicrotasks ()
2022-05-18 16:51:55:135 - [debug] [Mac2Driver@0b55 (5b556c85)] at processTicksAndRejections (internal/process/task_queues.js:97:5)
2022-05-18 16:51:55:137 - [HTTP] <-- POST /wd/hub/session/5b556c85-8d5b-4c34-b942-2d2ae8c8e567/element 404 381 ms - 850
2022-05-18 16:51:55:137 - [HTTP]
2022-05-18 16:51:55:137 - [debug] [WebDriverAgentMac] [xcodebuild] t = 297.72s Tear Down
2022-05-18 16:51:55:139 - [debug] [WebDriverAgentMac] [xcodebuild] Test Case ‘-[UITestingUITests testRunner]’ passed (297.719 seconds).
2022-05-18 16:51:55:139 - [debug] [WebDriverAgentMac] [xcodebuild] Test Suite ‘UITestingUITests’ passed at 2022-05-18 16:51:55.139.
2022-05-18 16:51:55:140 - [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 297.719 (297.721) seconds
2022-05-18 16:51:55:146 - [debug] [WebDriverAgentMac] [xcodebuild] Test Suite ‘WebDriverAgentRunner.xctest’ passed at 2022-05-18 16:51:55.140.
2022-05-18 16:51:55:147 - [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 297.719 (297.722) seconds
2022-05-18 16:51:55:148 - [debug] [WebDriverAgentMac] [xcodebuild] Test Suite ‘All tests’ passed at 2022-05-18 16:51:55.140.
2022-05-18 16:51:55:148 - [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 297.719 (297.723) seconds

1 Like
2

The other case：
2022-05-19 16:09:39:704 - [HTTP] --> POST /wd/hub/session/ea872223-2f36-4c52-bb46-9ceadcb6cec1/execute/sync
2022-05-19 16:09:39:704 - [HTTP] {“script”:“macos: click”,“args”:[{“x”:“1019”,“y”:“416”}]}
2022-05-19 16:09:39:704 - [debug] [Mac2Driver@fed6 (ea872223)] Calling AppiumDriver.execute() with args: [“macos: click”,[{“x”:“1019”,“y”:“416”}],“ea872223-2f36-4c52-bb46-9ceadcb6cec1”]
2022-05-19 16:09:39:704 - [AppiumDriver@0a4f] Plugins which can handle cmd ‘execute’: images
2022-05-19 16:09:39:704 - [AppiumDriver@0a4f] Plugin images is now handling cmd ‘execute’
2022-05-19 16:09:39:704 - [AppiumDriver@0a4f] Executing default handling behavior for command ‘execute’
2022-05-19 16:09:39:704 - [Mac2Driver] Executing extension command ‘macos: click’
2022-05-19 16:09:39:706 - [debug] [WD Proxy] Proxying [POST /wda/click] to [POST http://127.0.0.1:8540/session/89138B70-AF74-4B67-8A9F-3F0EF107F877/wda/click] with body: {“x”:“1019”,“y”:“416”}
2022-05-19 16:09:39:707 - [debug] [WebDriverAgentMac] [xcodebuild] t = 103.33s Click <XCUIElementProxy: 0x600002860900>[0.53, 0.39]
2022-05-19 16:09:39:707 - [debug] [WebDriverAgentMac] [xcodebuild] t = 103.34s Wait for com.xxx.xx to idle
2022-05-19 16:09:39:709 - [debug] [WebDriverAgentMac] [xcodebuild] t = 103.34s Find the Application ‘com.xxx.xx’
2022-05-19 16:09:39:712 - [debug] [WebDriverAgentMac] [xcodebuild] t = 103.34s Synthesize event
2022-05-19 16:09:43:355 - [debug] [AppiumDriver@0a4f] Responding to client with driver.getSessions() result: [{“id”:“ea872223-2f36-4c52-bb46-9ceadcb6cec1”,“capabilities”:{“platformName”:“mac”,“automationName”:“Mac2”,“bundleId”:“com.xxx.xx”,“createSessionTimeout”:30000,“deviceName”:“XMNA100:10.32.35.148”,“newCommandTimeout”:600,“noReset”:true,“platformVersion”:“11.5.2”,“showServerLogs”:true,“skipAppKill”:true,“systemPort”:8540,“udid”:“10.32.35.148”}}]
2022-05-19 16:09:43:357 - [HTTP] <-- GET /wd/hub/sessions 200 3 ms - 366
2022-05-19 16:09:43:357 - [HTTP]
2022-05-19 16:09:48:540 - [debug] [AppiumDriver@0a4f] Responding to client with driver.getSessions() result: [{“id”:“ea872223-2f36-4c52-bb46-9ceadcb6cec1”,“capabilities”:{“platformName”:“mac”,“automationName”:“Mac2”,“bundleId”:“com.xxx.xx”,“createSessionTimeout”:30000,“deviceName”:“XMNA100:10.32.35.148”,“newCommandTimeout”:600,“noReset”:true,“platformVersion”:“11.5.2”,“showServerLogs”:true,“skipAppKill”:true,“systemPort”:8540,“udid”:“10.32.35.148”}}]
2022-05-19 16:09:48:540 - [HTTP] <-- GET /wd/hub/sessions 200 2 ms - 366
2022-05-19 16:09:48:540 - [HTTP]
2022-05-19 16:09:53:852 - [debug] [AppiumDriver@0a4f] Responding to client with driver.getSessions() result: [{“id”:“ea872223-2f36-4c52-bb46-9ceadcb6cec1”,“capabilities”:{“platformName”:“mac”,“automationName”:“Mac2”,“bundleId”:“com.xxx.xx”,“createSessionTimeout”:30000,“deviceName”:“XMNA100:10.32.35.148”,“newCommandTimeout”:600,“noReset”:true,“platformVersion”:“11.5.2”,“showServerLogs”:true,“skipAppKill”:true,“systemPort”:8540,“udid”:“10.32.35.148”}}]
2022-05-19 16:09:53:854 - [HTTP] <-- GET /wd/hub/sessions 200 2 ms - 366
2022-05-19 16:09:53:854 - [HTTP]
2022-05-19 16:09:59:216 - [debug] [AppiumDriver@0a4f] Responding to client with driver.getSessions() result: [{“id”:“ea872223-2f36-4c52-bb46-9ceadcb6cec1”,“capabilities”:{“platformName”:“mac”,“automationName”:“Mac2”,“bundleId”:“com.xxx.xx”,“createSessionTimeout”:30000,“deviceName”:“XMNA100:10.32.35.148”,“newCommandTimeout”:600,“noReset”:true,“platformVersion”:“11.5.2”,“showServerLogs”:true,“skipAppKill”:true,“systemPort”:8540,“udid”:“10.32.35.148”}}]
2022-05-19 16:09:59:216 - [HTTP] <-- GET /wd/hub/sessions 200 2 ms - 366
2022-05-19 16:09:59:216 - [HTTP]
2022-05-19 16:10:04:430 - [debug] [AppiumDriver@0a4f] Responding to client with driver.getSessions() result: [{“id”:“ea872223-2f36-4c52-bb46-9ceadcb6cec1”,“capabilities”:{“platformName”:“mac”,“automationName”:“Mac2”,“bundleId”:“com.xxx.xx”,“createSessionTimeout”:30000,“deviceName”:“XMNA100:10.32.35.148”,“newCommandTimeout”:600,“noReset”:true,“platformVersion”:“11.5.2”,“showServerLogs”:true,“skipAppKill”:true,“systemPort”:8540,“udid”:“10.32.35.148”}}]
2022-05-19 16:10:04:431 - [HTTP] <-- GET /wd/hub/sessions 200 1 ms - 366
2022-05-19 16:10:04:431 - [HTTP]
2022-05-19 16:10:09:689 - [debug] [AppiumDriver@0a4f] Responding to client with driver.getSessions() result: [{“id”:“ea872223-2f36-4c52-bb46-9ceadcb6cec1”,“capabilities”:{“platformName”:“mac”,“automationName”:“Mac2”,“bundleId”:“com.xxx.xx”,“createSessionTimeout”:30000,“deviceName”:“XMNA100:10.32.35.148”,“newCommandTimeout”:600,“noReset”:true,“platformVersion”:“11.5.2”,“showServerLogs”:true,“skipAppKill”:true,“systemPort”:8540,“udid”:“10.32.35.148”}}]
2022-05-19 16:10:09:689 - [HTTP] <-- GET /wd/hub/sessions 200 2 ms - 366
2022-05-19 16:10:09:690 - [HTTP]
2022-05-19 16:10:10:013 - [debug] [WebDriverAgentMac] [xcodebuild] t = 133.64s Failed: Timed out while synthesizing event.
2022-05-19 16:10:15:089 - [debug] [WebDriverAgentMac] [xcodebuild] WebDriverAgentRunner.m:54: Expected failure in -[UITestingUITests testRunner]: Failed to synthesize event: Timed out while synthesizing event.Reason: (Ignore all failures)
2022-05-19 16:10:15:090 - [debug] [WD Proxy] Got response with status 200: {“value”:null,“sessionId”:“89138B70-AF74-4B67-8A9F-3F0EF107F877”}
2022-05-19 16:10:15:090 - [debug] [Mac2Driver@fed6 (ea872223)] Responding to client with driver.execute() result: null
2022-05-19 16:10:15:091 - [HTTP] <-- POST /wd/hub/session/ea872223-2f36-4c52-bb46-9ceadcb6cec1/execute/sync 200 35388 ms - 14
2022-05-19 16:10:15:091 - [HTTP]
2022-05-19 16:10:15:091 - [debug] [WebDriverAgentMac] [xcodebuild] t = 138.72s Tear Down
2022-05-19 16:10:15:091 - [debug] [WebDriverAgentMac] Test Case ‘-[UITestingUITests testRunner]’ passed (138.720 seconds).
2022-05-19 16:10:15:091 - [debug] [WebDriverAgentMac] [xcodebuild] Test Suite ‘UITestingUITests’ passed at 2022-05-19 16:10:15.091.
2022-05-19 16:10:15:091 - [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 138.720 (138.722) seconds
2022-05-19 16:10:15:092 - [debug] [WebDriverAgentMac] [xcodebuild] Test Suite ‘WebDriverAgentRunner.xctest’ passed at 2022-05-19 16:10:15.092.
2022-05-19 16:10:15:092 - [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 138.720 (138.723) seconds
2022-05-19 16:10:15:092 - [debug] [WebDriverAgentMac] [xcodebuild] Test Suite ‘All tests’ passed at 2022-05-19 16:10:15.092.
2022-05-19 16:10:15:093 - [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 138.720 (138.724) seconds
2022-05-19 16:10:15:142 - [debug] [AppiumDriver@0a4f] Responding to client with driver.getSessions() result: [{“id”:“ea872223-2f36-4c52-bb46-9ceadcb6cec1”,“capabilities”:{“platformName”:“mac”,“automationName”:“Mac2”,“bundleId”:“com.xxx.xx”,“createSessionTimeout”:30000,“deviceName”:“XMNA100:10.32.35.148”,“newCommandTimeout”:600,“noReset”:true,“platformVersion”:“11.5.2”,“showServerLogs”:true,“skipAppKill”:true,“systemPort”:8540,“udid”:“10.32.35.148”}}]
2022-05-19 16:10:15:142 - [HTTP] <-- GET /wd/hub/sessions 200 2 ms - 366

3

It would be useful if you could provide a reliable way to reproduce this issue in my local env.

5

Here are some cases maybe you can try：
1.excute macos: click when application under close
2.excute macos: click for application get microphone permissions popup

6

02%20AM
Screen Shot 2022-05-20 at 12.06.02 AM.jpg1000×1022 150 KB

I execute macOS: click for OK button will reproduce

7

excute macos: click application get microphone permissions popup

I assume this is a common XCTest issue in general: Stop the message "appName would li… | Apple Developer Forums

excute macos: click when application under close

Could you please be more specific about the steps I need to run? I don’t get what needs to be done.

8

I added an exception catch
Finding this exception causes the loop to exit

2022-05-20 10:54:53:833 - [debug] [WebDriverAgentMac] [xcodebuild] WebDriverAgentRunner.m:55: Expected failure in -[UITestingUITests testRunner]: Failed to synthesize event: Timed out while synthesizing event.Reason: (Ignore all failures)
2022-05-20 10:54:53:834 - [debug] [WD Proxy] Got response with status 200: {“value”:null,“sessionId”:“0CE5F837-C9FC-42E6-BD87-627BD9D104D3”}
2022-05-20 10:54:53:835 - [debug] [Mac2Driver@3ea3 (68ce7b03)] Responding to client with driver.execute() result: null
2022-05-20 10:54:53:835 - [HTTP] <-- POST /wd/hub/session/68ce7b03-f640-49c1-bf3f-cfcf1c7a01d8/execute/sync 200 35400 ms - 14
2022-05-20 10:54:53:835 - [HTTP]
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] [xcodebuild] 2022-05-20 10:54:53.836850+0800 WebDriverAgentRunner-Runner[49451:1297238] Exception at (
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] 0 CoreFoundation 0x00007fff2058283b __exceptionPreprocess + 242
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] 1 libobjc.A.dylib 0x00007fff202bad92 objc_exception_throw + 48
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] 2 CoreFoundation 0x00007fff2058269f +[NSException raise:format:] + 189
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] 3 XCTestCore 0x0000000104c8aa95 __26-[XCTestCase performTest:]_block_invoke.358 + 252
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] 4 CoreFoundation 0x00007fff20507d01 CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION + 23
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] 5 CoreFoundation 0x00007fff20507b95 __CFRunLoopDoObservers + 543
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] 6 CoreFoundation 0x00007fff20506694 CFRunLoopRunSpecific + 683
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] 7 Foundation 0x00007fff21296607 -[NSRunLoop(NSRunLoop) runMode:beforeDate:] + 212
2022-05-20 10:54:53:837 - [debug] [WebDriverAgentMac] 8 WebDriverAgentLib 0x000000010768e30a -[FBWebServer startServing] + 298

9

It looks work when I change this:
while (self.keepAlive &&
[runLoop runMode:NSDefaultRunLoopMode beforeDate:[NSDate distantFuture]]);
==>
NSRunLoop *runLoop = [NSRunLoop mainRunLoop];
while (self.keepAlive){
@try {
BOOL runStatus = [runLoop runMode:NSDefaultRunLoopMode beforeDate:[NSDate distantFuture]];
if (!runStatus) {
break;
}
} @catch (NSException *exception) {
[FBLogger logFmt:@“appear exception %@”,exception.reason];
}
};

Maybe can add some retry on runMode:beforeDate?