appium / appium-mac2-driver

Next-gen Appium macOS driver, backed by Apple XCTest
Apache License 2.0
125 stars 24 forks source link

Popover dismissed when searching for element #29

Closed lassebm closed 3 years ago

lassebm commented 3 years ago

When searching for a visible popover element, the popover is dismissed. This is not reproducible with the "Mac" driver. See sample code using both "Mac" and "Mac2" driver and macOS "Music" app as target.

Appium: Git 604170a7adb022334c541b0e82b671323a74909c Appium Mac2 driver: 0.4.1 macOS: 10.15.7

Appium output:

[Appium] Welcome to Appium v1.20.0-beta.0 (REV 604170a7adb022334c541b0e82b671323a74909c)
[Appium] Appium REST http interface listener started on 0.0.0.0:4723
[debug] [HTTP] Request idempotency key: f51fb4f0-c2c2-4ec8-afdd-f58e2227ad8b
[HTTP] --> POST /wd/hub/session
[HTTP] {"capabilities":{"firstMatch":[{"platformName":"Mac","appium:app":"/System/Applications/Music.app"}]},"desiredCapabilities":{"platformName":"Mac","app":"/System/Applications/Music.app"}}
[debug] [W3C] Calling AppiumDriver.createSession() with args: [{"platformName":"Mac","app":"/System/Applications/Music.app"},null,{"firstMatch":[{"platformName":"Mac","appium:app":"/System/Applications/Music.app"}]}]
[debug] [BaseDriver] Event 'newSessionRequested' logged at 1607529271990 (16:54:31 GMT+0100 (Central European Standard Time))
[Appium] Appium v1.20.0-beta.0 creating new MacDriver (v1.10.1) session
[debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
[debug] [BaseDriver] Creating session with W3C capabilities: {
[debug] [BaseDriver]   "alwaysMatch": {
[debug] [BaseDriver]     "platformName": "Mac",
[debug] [BaseDriver]     "appium:app": "/System/Applications/Music.app"
[debug] [BaseDriver]   },
[debug] [BaseDriver]   "firstMatch": [
[debug] [BaseDriver]     {}
[debug] [BaseDriver]   ]
[debug] [BaseDriver] }
[BaseDriver] Session created with session id: f3796fd0-6c8d-4600-bd1f-29f9d101e2b4
[debug] [MacDriver] The path to AppiumForMac server has not been provided explicitly. Trying to autodetect it
[MacDriver] Autodetected AppiumForMac server's location at '/Applications/AppiumForMac.app'
[MacDriver] Killing any old AppiumForMac
[MacDriver] Successfully cleaned up old Appium4Mac servers
[MacDriver] Spawning AppiumForMac with: /Applications/AppiumForMac.app
[Appium4Mac] [STDERR] 2020-12-09 16:54:32:386 AppiumForMac[75334:307] HTTPServer: Started HTTP server on port 4622
[debug] [WD Proxy] Matched '/session' to command name 'createSession'
[debug] [WD Proxy] Proxying [POST /session] to [POST http://127.0.0.1:4622/wd/hub/session] with body: {"desiredCapabilities":{"platformName":"Mac","app":"/System/Applications/Music.app"}}
[debug] [WD Proxy] Got response with status 200: {"status":0,"sessionId":"K3Z9aHoN","value":{"locationContextEnabled":false,"webStorageEnabled":false,"browserName":"Mac","platform":"Mac","databaseEnabled":false,"version":"10.15.7","javascriptEnabled":true,"takesScreenshot":true,"nativeEvents":true}}
[WD Proxy] Determined the downstream protocol as 'MJSONWP'
[MacDriver] Automatically navigating to app '/System/Applications/Music.app'
[debug] [WD Proxy] Matched '/url' to command name 'setUrl'
[debug] [WD Proxy] Proxying [POST /url] to [POST http://127.0.0.1:4622/wd/hub/session/K3Z9aHoN/url] with body: {"url":"/System/Applications/Music.app"}
[debug] [WD Proxy] Got response with status 200: {"status":0,"sessionId":"K3Z9aHoN","value":null}
[Appium] New MacDriver session created successfully, session f3796fd0-6c8d-4600-bd1f-29f9d101e2b4 added to master session list
[debug] [BaseDriver] Event 'newSessionStarted' logged at 1607529273300 (16:54:33 GMT+0100 (Central European Standard Time))
[debug] [W3C (f3796fd0)] Cached the protocol value 'W3C' for the new session f3796fd0-6c8d-4600-bd1f-29f9d101e2b4
[debug] [W3C (f3796fd0)] Responding to client with driver.createSession() result: {"capabilities":{"platformName":"Mac","app":"/System/Applications/Music.app"}}
[HTTP] <-- POST /wd/hub/session 200 1315 ms - 139
[HTTP]
[HTTP] --> POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element
[HTTP] {"using":"xpath","value":"/AXApplication/AXWindow/AXSplitGroup/AXPopUpButton[@AXDescription='airplay']"}
[W3C (f3796fd0)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element] to [POST http://127.0.0.1:4622/wd/hub/session/K3Z9aHoN/element] with body: {"using":"xpath","value":"/AXApplication/AXWindow/AXSplitGroup/AXPopUpButton[@AXDescription='airplay']"}
[Appium4Mac] [STDERR] 2020-12-09 16:54:33.313 AppiumForMac[75334:5032926]
[Appium4Mac] [STDERR]
[Appium4Mac] [STDERR]
[Appium4Mac] [STDERR] ************* findAllUsingAbsoluteAXPath: /AXApplication/AXWindow/AXSplitGroup/AXPopUpButton[@AXDescription='airplay']
[Appium4Mac] [STDERR] 2020-12-09 16:54:33.313 AppiumForMac[75334:5032926] axPathComponents:(
[Appium4Mac] [STDERR] AXApplication,
[Appium4Mac] [STDERR] AXWindow,
[Appium4Mac] [STDERR] AXSplitGroup,
[Appium4Mac] [STDERR] "AXPopUpButton[@AXDescription='airplay']"
[Appium4Mac] [STDERR] )
[Appium4Mac] [STDERR] 2020-12-09 16:54:33.959 AppiumForMac[75334:5032926]
[Appium4Mac] [STDERR] ************* findAllUsingAbsoluteAXPath matchedNodes:(
[Appium4Mac] [STDERR] "<PFUIElement: 0x7ff13cca0ca0> {\n    AXDescription = airplay;\n    AXHelp = \"<null>\";\n    AXRole = AXPopUpButton;\n    AXRoleDescription = \"pop-up button\";\n    AXSubrole = \"<null>\";\n    AXTitle = \"\";\n}"
[Appium4Mac] [STDERR] )
[Appium4Mac] [STDERR]
[Appium4Mac] [STDERR]
[debug] [WD Proxy] Got response with status 200: {"status":0,"sessionId":"K3Z9aHoN","value":{"ELEMENT":"1"}}
[WD Proxy] Replacing sessionId K3Z9aHoN with f3796fd0-6c8d-4600-bd1f-29f9d101e2b4
[HTTP] <-- POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element 200 654 ms - 118
[HTTP]
[HTTP] --> POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/1/click
[HTTP] {"id":"1"}
[W3C (f3796fd0)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/1/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/1/click] to [POST http://127.0.0.1:4622/wd/hub/session/K3Z9aHoN/element/1/click] with body: {"id":"1"}
[debug] [WD Proxy] Got response with status 200: {"status":0,"sessionId":"K3Z9aHoN","value":null}
[WD Proxy] Replacing sessionId K3Z9aHoN with f3796fd0-6c8d-4600-bd1f-29f9d101e2b4
[HTTP] <-- POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/1/click 200 235 ms - 65
[HTTP]
[HTTP] --> POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/elements
[HTTP] {"using":"xpath","value":"/AXApplication/AXWindow/AXSplitGroup/AXPopUpButton[@AXDescription='airplay']/AXPopover/AXScrollArea/AXTable/AXRow[@AXSubrole='AXTableRow']"}
[W3C (f3796fd0)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/elements' to command name 'findElements'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/elements] to [POST http://127.0.0.1:4622/wd/hub/session/K3Z9aHoN/elements] with body: {"using":"xpath","value":"/AXApplication/AXWindow/AXSplitGroup/AXPopUpButton[@AXDescription='airplay']/AXPopover/AXScrollArea/AXTable/AXRow[@AXSubrole='AXTableRow']"}
[Appium4Mac] [STDERR] 2020-12-09 16:54:36.211 AppiumForMac[75334:5032937]
[Appium4Mac] [STDERR]
[Appium4Mac] [STDERR]
[Appium4Mac] [STDERR] ************* findAllUsingAbsoluteAXPath: /AXApplication/AXWindow/AXSplitGroup/AXPopUpButton[@AXDescription='airplay']/AXPopover/AXScrollArea/AXTable/AXRow[@AXSubrole='AXTableRow']
[Appium4Mac] [STDERR] 2020-12-09 16:54:36.211 AppiumForMac[75334:5032937] axPathComponents:(
[Appium4Mac] [STDERR] AXApplication,
[Appium4Mac] [STDERR] AXWindow,
[Appium4Mac] [STDERR] AXSplitGroup,
[Appium4Mac] [STDERR] "AXPopUpButton[@AXDescription='airplay']",
[Appium4Mac] [STDERR] AXPopover,
[Appium4Mac] [STDERR] AXScrollArea,
[Appium4Mac] [STDERR] AXTable,
[Appium4Mac] [STDERR] "AXRow[@AXSubrole='AXTableRow']"
[Appium4Mac] [STDERR] )
[Appium4Mac] [STDERR] 2020-12-09 16:54:36.274 AppiumForMac[75334:5032937]
[Appium4Mac] [STDERR] ************* findAllUsingAbsoluteAXPath matchedNodes:(
[Appium4Mac] [STDERR] "<PFUIElement: 0x7ff13ce5f670> {\n    AXDescription = \"Computer , (volume) 0.41, selected\";\n    AXHelp = \"<null>\";\n    AXRole = AXRow;\n    AXRoleDescription = \"table row\";\n    AXSubrole = AXTableRow;\n    AXTitle = \"<null>\";\n}",
[Appium4Mac] [STDERR] "<PFUIElement: 0x7ff13ce60890> {\n    AXDescription = \"Lasses Desk Roma , password protected, unselected\";\n    AXHelp = \"<null>\";\n    AXRole = AXRow;\n    AXRoleDescription = \"table row\";\n    AXSubrole = AXTableRow;\n    AXTitle = \"<null>\";\n}"
[Appium4Mac] [STDERR] )
[Appium4Mac] [STDERR]
[Appium4Mac] [STDERR]
[debug] [WD Proxy] Got response with status 200: {"status":0,"sessionId":"K3Z9aHoN","value":[{"ELEMENT":"2"},{"ELEMENT":"3"}]}
[WD Proxy] Replacing sessionId K3Z9aHoN with f3796fd0-6c8d-4600-bd1f-29f9d101e2b4
[HTTP] <-- POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/elements 200 71 ms - 178
[HTTP]
[HTTP] --> GET /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/attribute/AXDescription
[HTTP] {}
[W3C (f3796fd0)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/attribute/AXDescription' to command name 'getAttribute'
[debug] [WD Proxy] Proxying [GET /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/attribute/AXDescription] to [GET http://127.0.0.1:4622/wd/hub/session/K3Z9aHoN/element/2/attribute/AXDescription] with no body
[debug] [WD Proxy] Got response with status 200: {"status":0,"sessionId":"K3Z9aHoN","value":"Computer , (volume) 0.41, selected"}
[WD Proxy] Replacing sessionId K3Z9aHoN with f3796fd0-6c8d-4600-bd1f-29f9d101e2b4
[HTTP] <-- GET /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/attribute/AXDescription 200 7 ms - 97
[HTTP]
[HTTP] --> POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/click
[HTTP] {"id":"2"}
[W3C (f3796fd0)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/click] to [POST http://127.0.0.1:4622/wd/hub/session/K3Z9aHoN/element/2/click] with body: {"id":"2"}
[debug] [WD Proxy] Got response with status 200: {"status":0,"sessionId":"K3Z9aHoN","value":null}
[WD Proxy] Replacing sessionId K3Z9aHoN with f3796fd0-6c8d-4600-bd1f-29f9d101e2b4
[HTTP] <-- POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/click 200 9 ms - 65
[HTTP]
[HTTP] --> DELETE /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4
[HTTP] {}
[debug] [W3C (f3796fd0)] Calling AppiumDriver.deleteSession() with args: ["f3796fd0-6c8d-4600-bd1f-29f9d101e2b4"]
[debug] [BaseDriver] Event 'quitSessionRequested' logged at 1607529278303 (16:54:38 GMT+0100 (Central European Standard Time))
[Appium] Removing session f3796fd0-6c8d-4600-bd1f-29f9d101e2b4 from our master session list
[debug] [MacDriver] Deleting AppiumForMac session
[debug] [MacDriver] Deleting AppiumForMac server session
[debug] [WD Proxy] Matched '/' to command name 'deleteSession'
[debug] [WD Proxy] Proxying [DELETE /] to [DELETE http://127.0.0.1:4622/wd/hub/session/K3Z9aHoN] with no body
[debug] [WD Proxy] Got response with status 200: {"status":0,"sessionId":"K3Z9aHoN","value":null}
[MacDriver] AppiumForMac exited unexpectedly with code null, signal SIGTERM
[debug] [BaseDriver] Event 'quitSessionFinished' logged at 1607529278313 (16:54:38 GMT+0100 (Central European Standard Time))
[debug] [W3C (f3796fd0)] Received response: null
[debug] [W3C (f3796fd0)] But deleting session, so not returning
[debug] [W3C (f3796fd0)] Responding to client with driver.deleteSession() result: null
[HTTP] <-- DELETE /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4 200 13 ms - 14
[HTTP]
[debug] [HTTP] Request idempotency key: 8fd756fe-1ab0-4c18-8b18-7ac269c8eaba
[HTTP] --> POST /wd/hub/session
[HTTP] {"capabilities":{"firstMatch":[{"platformName":"Mac","appium:automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true}]},"desiredCapabilities":{"platformName":"Mac","automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true}}
[debug] [W3C] Calling AppiumDriver.createSession() with args: [{"platformName":"Mac","automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true},null,{"firstMatch":[{"platformName":"Mac","appium:automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true}]}]
[debug] [BaseDriver] Event 'newSessionRequested' logged at 1607529278322 (16:54:38 GMT+0100 (Central European Standard Time))
[Appium] Appium v1.20.0-beta.0 creating new Mac2Driver (v0.4.1) session
[debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
[debug] [BaseDriver] Creating session with W3C capabilities: {
[debug] [BaseDriver]   "alwaysMatch": {
[debug] [BaseDriver]     "platformName": "Mac",
[debug] [BaseDriver]     "appium:automationName": "Mac2",
[debug] [BaseDriver]     "appium:bundleId": "com.apple.Music",
[debug] [BaseDriver]     "appium:showServerLogs": true
[debug] [BaseDriver]   },
[debug] [BaseDriver]   "firstMatch": [
[debug] [BaseDriver]     {}
[debug] [BaseDriver]   ]
[debug] [BaseDriver] }
[BaseDriver] Session created with session id: 316ab0e2-8469-499b-a17a-d746ef6a526c
[debug] [WebDriverAgentMac] Using bootstrap root: /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac
[debug] [WebDriverAgentMac] Using xcodebuild binary at '/usr/bin/xcodebuild'
[debug] [WebDriverAgentMac] Using port 10100
[WebDriverAgentMac] Starting Mac2Driver host process: xcodebuild build-for-testing test-without-building -project /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac/WebDriverAgentMac.xcodeproj -scheme WebDriverAgentRunner COMPILER_INDEX_STORE_ENABLE\=NO
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] Command line invocation:
[debug] [WebDriverAgentMac] [xcodebuild] /Applications/Xcode.app/Contents/Developer/usr/bin/xcodebuild build-for-testing test-without-building -project /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac/WebDriverAgentMac.xcodeproj -scheme WebDriverAgentRunner COMPILER_INDEX_STORE_ENABLE=NO
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac] Build settings from command line:
[debug] [WebDriverAgentMac]     COMPILER_INDEX_STORE_ENABLE = NO
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] note: Using new build system
[debug] [WebDriverAgentMac] [xcodebuild] note: Building targets in parallel
[debug] [WebDriverAgentMac] [xcodebuild] note: Planning build
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] note: Using build description from disk
[debug] [WebDriverAgentMac] [xcodebuild] ** TEST BUILD SUCCEEDED **
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:43.474 xcodebuild[75340:5033283]  IDETestOperationsObserverDebug: Writing diagnostic log for test session to:
[debug] [WebDriverAgentMac] /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Logs/Test/Test-WebDriverAgentRunner-2020.12.09_16-54-41-+0100.xcresult/Staging/2_Test/Diagnostics/WebDriverAgentRunner-F69B6578-3809-493F-81B4-595734F54716/WebDriverAgentRunner-E3609C03-152C-4F22-A037-16BABABDA4E0/Session-WebDriverAgentRunner-2020-12-09_165443-zT326t.log
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:43.475 xcodebuild[75340:5033199] [MT] IDETestOperationsObserverDebug: (3927A861-FBE8-484B-8175-7DA2264684D3) Beginning test session WebDriverAgentRunner-3927A861-FBE8-484B-8175-7DA2264684D3 at 2020-12-09 16:54:43.475 with Xcode 12B45b on target <DVTLocalComputer: 0x7fe4c9530db0 (My Mac | x86_64h)> (10.15.7 (19H15))
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:43.498 xcodebuild[75340:5033199] [MT] IDETestOperationsObserverDebug: (3927A861-FBE8-484B-8175-7DA2264684D3) Finished requesting crash reports. Continuing with testing.
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:43.843023+0100 WebDriverAgentRunner-Runner[75346:5033483] Running tests...
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'All tests' started at 2020-12-09 16:54:43.965
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'WebDriverAgentRunner.xctest' started at 2020-12-09 16:54:43.966
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'UITestingUITests' started at 2020-12-09 16:54:43.966
[debug] [WebDriverAgentMac] [xcodebuild] t =      nans Suite Set Up
[debug] [WebDriverAgentMac] [xcodebuild] Test Case '-[UITestingUITests testRunner]' started.
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.00s Start Test at 2020-12-09 16:54:43.969
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.00s Set Up
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:44.037800+0100 WebDriverAgentRunner-Runner[75346:5033934] [Arbitration] starting DTServiceHub child handshake.0 (send: 0x4907, receive: 0x3813)
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:44.037952+0100 WebDriverAgentRunner-Runner[75346:5033483] [Arbitration] attempting connection to singleton: 75344 with send port: 0x4b07
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:44.038438+0100 WebDriverAgentRunner-Runner[75346:5033483] [Arbitration] handshake SUCCESSFUL (child: 75348 -> singleton: 75344)
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:44.038761+0100 WebDriverAgentRunner-Runner[75346:5033483] Built at Dec  8 2020 09:11:58
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:44.046697+0100 WebDriverAgentRunner-Runner[75346:5033483] ServerURLHere->http://localhost:10100<-ServerURLHere
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:44.409049+0100 WebDriverAgentRunner-Runner[75346:5033483] The data couldn’t be read because it isn’t in the correct format.
[debug] [WD Proxy] Got response with status 200: {"value":{"message":"WebDriverAgent is ready to accept commands","state":"success","os":{"version":"Version 10.15.7 (Build 19H15)"},"ready":true,"build":{"time":"Dec  8 2020 09:11:59"}},"sessionId":null}
[WebDriverAgentMac] The host process is ready within 6157ms
[debug] [WD Proxy] Matched '/session' to command name 'createSession'
[debug] [WD Proxy] Proxying [POST /session] to [POST http://127.0.0.1:10100/session] with body: {"capabilities":{"firstMatch":[{}],"alwaysMatch":{"platformName":"Mac","automationName":"Mac2","bundleId":"com.apple.Music","showServerLogs":true}}}
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.57s Open com.apple.Music
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.57s     Launch com.apple.Music
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.57s         Terminate com.apple.Music:75337
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:54:45.618810+0100 WebDriverAgentRunner-Runner[75346:5033483] Launching macOS application via NSWorkspace while sandboxed. Launch arguments and environment variables may be dropped.
[debug] [WebDriverAgentMac] [xcodebuild] t =     1.92s         Wait for accessibility to load
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.77s         Setting up automation session
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.78s         Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":{"sessionId":"56C50E03-E57A-4AA6-ACA6-FB7C088E013C","capabilities":{"CFBundleIdentifier":"com.apple.Music"}},"sessionId":"56C50E03-E57A-4AA6-ACA6-FB7C088E013C"}
[WD Proxy] Determined the downstream protocol as 'W3C'
[Appium] New Mac2Driver session created successfully, session 316ab0e2-8469-499b-a17a-d746ef6a526c added to master session list
[debug] [BaseDriver] Event 'newSessionStarted' logged at 1607529286756 (16:54:46 GMT+0100 (Central European Standard Time))
[debug] [W3C (316ab0e2)] Cached the protocol value 'W3C' for the new session 316ab0e2-8469-499b-a17a-d746ef6a526c
[debug] [W3C (316ab0e2)] Responding to client with driver.createSession() result: {"capabilities":{"platformName":"Mac","automationName":"Mac2","bundleId":"com.apple.Music","showServerLogs":true}}
[HTTP] <-- POST /wd/hub/session 200 8436 ms - 175
[HTTP]
[HTTP] --> POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element
[HTTP] {"using":"-ios class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]"}
[debug] [W3C (316ab0e2)] Calling AppiumDriver.findElement() with args: ["-ios class chain","**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]","316ab0e2-8469-499b-a17a-d746ef6a526c"]
[debug] [BaseDriver] Valid locator strategies for this request: id, name, accessibility id, xpath, class name, -ios predicate string, predicate string, -ios class chain, class chain
[debug] [WD Proxy] Matched '/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /element] to [POST http://127.0.0.1:10100/session/56C50E03-E57A-4AA6-ACA6-FB7C088E013C/element] with body: {"using":"class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.80s Get all elements bound by accessibility element for: Elements matching predicate 'label == "airplay"'
[debug] [WD Proxy] Got response with status 200: {"value":{"ELEMENT":"B02AF79C-BC77-4172-AB01-FBE9B74BE49F","element-6066-11e4-a52e-4f735466cecf":"B02AF79C-BC77-4172-AB01-FBE9B74BE49F"},"sessionId":"56C50E03-E57A-4AA6-ACA6-FB7C088E013C"}
[debug] [W3C (316ab0e2)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":"B02AF79C-BC77-4172-AB01-FBE9B74BE49F","ELEMENT":"B02AF79C-BC77-4172-AB01-FBE9B74BE49F"}
[HTTP] <-- POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element 200 6263 ms - 137
[HTTP]
[HTTP] --> POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/B02AF79C-BC77-4172-AB01-FBE9B74BE49F/click
[HTTP] {"id":"B02AF79C-BC77-4172-AB01-FBE9B74BE49F"}
[W3C (316ab0e2)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/B02AF79C-BC77-4172-AB01-FBE9B74BE49F/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/B02AF79C-BC77-4172-AB01-FBE9B74BE49F/click] to [POST http://127.0.0.1:10100/session/56C50E03-E57A-4AA6-ACA6-FB7C088E013C/element/B02AF79C-BC77-4172-AB01-FBE9B74BE49F/click] with body: {"id":"B02AF79C-BC77-4172-AB01-FBE9B74BE49F"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.06s Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.18s Click "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.18s     Wait for com.apple.Music to idle
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.18s     Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.35s     Synthesize event
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.67s     Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":"56C50E03-E57A-4AA6-ACA6-FB7C088E013C"}
[WD Proxy] Replacing sessionId 56C50E03-E57A-4AA6-ACA6-FB7C088E013C with 316ab0e2-8469-499b-a17a-d746ef6a526c
[HTTP] <-- POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/B02AF79C-BC77-4172-AB01-FBE9B74BE49F/click 200 611 ms - 65
[HTTP]
[HTTP] --> POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element
[HTTP] {"using":"-ios class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]"}
[debug] [W3C (316ab0e2)] Calling AppiumDriver.findElement() with args: ["-ios class chain","**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]","316ab0e2-8469-499b-a17a-d746ef6a526c"]
[debug] [BaseDriver] Valid locator strategies for this request: id, name, accessibility id, xpath, class name, -ios predicate string, predicate string, -ios class chain, class chain
[debug] [WD Proxy] Matched '/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /element] to [POST http://127.0.0.1:10100/session/56C50E03-E57A-4AA6-ACA6-FB7C088E013C/element] with body: {"using":"class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]"}
[debug] [WebDriverAgentMac] [xcodebuild] t =    11.68s Get all elements bound by accessibility element for: Elements matching predicate 'label BEGINSWITH "Computer , "'
[debug] [WD Proxy] Got response with status 200: {"value":{"ELEMENT":"513664CD-CDF6-4209-967E-4BC5BC0BA143","element-6066-11e4-a52e-4f735466cecf":"513664CD-CDF6-4209-967E-4BC5BC0BA143"},"sessionId":"56C50E03-E57A-4AA6-ACA6-FB7C088E013C"}
[debug] [W3C (316ab0e2)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":"513664CD-CDF6-4209-967E-4BC5BC0BA143","ELEMENT":"513664CD-CDF6-4209-967E-4BC5BC0BA143"}
[HTTP] <-- POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element 200 144 ms - 137
[HTTP]
[HTTP] --> POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/513664CD-CDF6-4209-967E-4BC5BC0BA143/click
[HTTP] {"id":"513664CD-CDF6-4209-967E-4BC5BC0BA143"}
[W3C (316ab0e2)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/513664CD-CDF6-4209-967E-4BC5BC0BA143/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/513664CD-CDF6-4209-967E-4BC5BC0BA143/click] to [POST http://127.0.0.1:10100/session/56C50E03-E57A-4AA6-ACA6-FB7C088E013C/element/513664CD-CDF6-4209-967E-4BC5BC0BA143/click] with body: {"id":"513664CD-CDF6-4209-967E-4BC5BC0BA143"}
[debug] [WebDriverAgentMac] [xcodebuild] t =    13.83s Find the "Computer , (volume) 0.41, selected" TableRow
[debug] [WebDriverAgentMac] [xcodebuild] t =    14.96s     Find the "Computer , (volume) 0.41, selected" TableRow (retry 1)
[debug] [WebDriverAgentMac] [xcodebuild] t =    16.08s     Find the "Computer , (volume) 0.41, selected" TableRow (retry 2)
[WD Proxy] Got response with status 404: {"value":{"error":"stale element reference","message":"The element \"\"Computer , (volume) 0.41, selected\" TableRow\" identified by \"513664CD-CDF6-4209-967E-4BC5BC0BA143\" is not present on the current view (No matches found for Children matching type Popover from input {(\n    PopUpButton, label: 'airplay'\n)}). Make sure the current view is the expected one","traceback":"(\n\t0   CoreFoundation                      0x00007fff2dc7fb57 __exceptionPreprocess + 250\n\t1   libobjc.A.dylib                     0x00007fff66acb5bf objc_exception_throw + 48\n\t2   WebDriverAgentLib                   0x000000010724c7ff -[FBElementCache elementForUUID:] + 1167\n\t3   WebDriverAgentLib                   0x000000010722c6dd +[FBElementCommands handleClick:] + 205\n\t4   WebDriverAgentLib                   0x000000010724a266 -[FBRoute_TargetAction mountRequest:intoResponse:] + 182\n\t5   WebDriverAgentLib                   0x0000000107243e23 __37-[FBWebServer registerRouteHandlers:]_block_invoke + 723\n\t6   WebDriver...
[debug] [W3C] Matched W3C error code 'stale element reference' to StaleElementReferenceError
[HTTP] <-- POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/513664CD-CDF6-4209-967E-4BC5BC0BA143/click 404 2416 ms - 1090
[HTTP]
[HTTP] --> DELETE /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c
[HTTP] {}
[debug] [W3C (316ab0e2)] Calling AppiumDriver.deleteSession() with args: ["316ab0e2-8469-499b-a17a-d746ef6a526c"]
[debug] [BaseDriver] Event 'quitSessionRequested' logged at 1607529300211 (16:55:00 GMT+0100 (Central European Standard Time))
[Appium] Removing session 316ab0e2-8469-499b-a17a-d746ef6a526c from our master session list
[debug] [WD Proxy] Matched '/session/56C50E03-E57A-4AA6-ACA6-FB7C088E013C' to command name 'deleteSession'
[debug] [WD Proxy] Proxying [DELETE /session/56C50E03-E57A-4AA6-ACA6-FB7C088E013C] to [DELETE http://127.0.0.1:10100/session/56C50E03-E57A-4AA6-ACA6-FB7C088E013C] with no body
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-09 16:55:00.213338+0100 WebDriverAgentRunner-Runner[75346:5033483] The data couldn’t be read because it isn’t in the correct format.
[debug] [WebDriverAgentMac] [xcodebuild] t =    16.24s Terminate com.apple.Music:75351
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":null}
[debug] [BaseDriver] Event 'quitSessionFinished' logged at 1607529301259 (16:55:01 GMT+0100 (Central European Standard Time))
[debug] [W3C (316ab0e2)] Received response: null
[debug] [W3C (316ab0e2)] But deleting session, so not returning
[debug] [W3C (316ab0e2)] Responding to client with driver.deleteSession() result: null
[HTTP] <-- DELETE /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c 200 1049 ms - 14
[HTTP]

Sample code output:

DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session {"capabilities": {"firstMatch": [{"platformName": "Mac", "appium:app": "/System/Applications/Music.app"}]}, "desiredCapabilities": {"platformName": "Mac", "app": "/System/Applications/Music.app"}}
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 192.168.65.2
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session HTTP/1.1" 200 139
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element {"using": "xpath", "value": "/AXApplication/AXWindow/AXSplitGroup/AXPopUpButton[@AXDescription='airplay']"}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element HTTP/1.1" 200 118
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/1/click {"id": "1"}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/1/click HTTP/1.1" 200 65
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/elements {"using": "xpath", "value": "/AXApplication/AXWindow/AXSplitGroup/AXPopUpButton[@AXDescription='airplay']/AXPopover/AXScrollArea/AXTable/AXRow[@AXSubrole='AXTableRow']"}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/elements HTTP/1.1" 200 178
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:GET http://192.168.65.2:4723/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/attribute/AXDescription {"name": "AXDescription", "id": "2"}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "GET /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/attribute/AXDescription HTTP/1.1" 200 97
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
Mac driver: Found row in popover: <appium.webdriver.webelement.WebElement (session="f3796fd0-6c8d-4600-bd1f-29f9d101e2b4", element="2")>
DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/click {"id": "2"}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4/element/2/click HTTP/1.1" 200 65
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:DELETE http://192.168.65.2:4723/wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4 {}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "DELETE /wd/hub/session/f3796fd0-6c8d-4600-bd1f-29f9d101e2b4 HTTP/1.1" 200 14
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session {"capabilities": {"firstMatch": [{"platformName": "Mac", "appium:automationName": "Mac2", "appium:bundleId": "com.apple.Music", "appium:showServerLogs": true}]}, "desiredCapabilities": {"platformName": "Mac", "automationName": "Mac2", "appium:bundleId": "com.apple.Music", "appium:showServerLogs": true}}
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 192.168.65.2
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session HTTP/1.1" 200 175
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element {"using": "-ios class chain", "value": "**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]"}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element HTTP/1.1" 200 137
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/B02AF79C-BC77-4172-AB01-FBE9B74BE49F/click {"id": "B02AF79C-BC77-4172-AB01-FBE9B74BE49F"}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/B02AF79C-BC77-4172-AB01-FBE9B74BE49F/click HTTP/1.1" 200 65
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element {"using": "-ios class chain", "value": "**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]"}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element HTTP/1.1" 200 137
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
Mac2 driver: Found row in popover: <appium.webdriver.webelement.WebElement (session="316ab0e2-8469-499b-a17a-d746ef6a526c", element="513664CD-CDF6-4209-967E-4BC5BC0BA143")>
DEBUG:selenium.webdriver.remote.remote_connection:POST http://192.168.65.2:4723/wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/513664CD-CDF6-4209-967E-4BC5BC0BA143/click {"id": "513664CD-CDF6-4209-967E-4BC5BC0BA143"}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "POST /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c/element/513664CD-CDF6-4209-967E-4BC5BC0BA143/click HTTP/1.1" 404 1090
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
DEBUG:selenium.webdriver.remote.remote_connection:DELETE http://192.168.65.2:4723/wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c {}
DEBUG:urllib3.connectionpool:http://192.168.65.2:4723 "DELETE /wd/hub/session/316ab0e2-8469-499b-a17a-d746ef6a526c HTTP/1.1" 200 14
DEBUG:selenium.webdriver.remote.remote_connection:Finished Request
Traceback (most recent call last):
  File "popover_dismissed.py", line 66, in <module>
    airplay_popover_computer_row.click()
  File "/usr/local/lib/python3.6/dist-packages/selenium/webdriver/remote/webelement.py", line 80, in click
    self._execute(Command.CLICK_ELEMENT)
  File "/usr/local/lib/python3.6/dist-packages/selenium/webdriver/remote/webelement.py", line 633, in _execute
    return self._parent.execute(command, params)
  File "/usr/local/lib/python3.6/dist-packages/selenium/webdriver/remote/webdriver.py", line 321, in execute
    self.error_handler.check_response(response)
  File "/usr/local/lib/python3.6/dist-packages/appium/webdriver/errorhandler.py", line 29, in check_response
    raise wde
  File "/usr/local/lib/python3.6/dist-packages/appium/webdriver/errorhandler.py", line 24, in check_response
    super(MobileErrorHandler, self).check_response(response)
  File "/usr/local/lib/python3.6/dist-packages/selenium/webdriver/remote/errorhandler.py", line 242, in check_response
    raise exception_class(message, screen, stacktrace)
selenium.common.exceptions.StaleElementReferenceException: Message: The element ""Computer , (volume) 0.41, selected" TableRow" identified by "513664CD-CDF6-4209-967E-4BC5BC0BA143" is not present on the current view (No matches found for Children matching type Popover from input {(
    PopUpButton, label: 'airplay'
)}). Make sure the current view is the expected one
mykola-mokhnach commented 3 years ago

The error looks expected to me. You could try the same workaround as in https://github.com/appium/appium-mac2-driver/issues/27#issuecomment-741813560 though

lassebm commented 3 years ago

@mykola-mokhnach I already gave that a try, see line 53 of the sample code:

driver.update_settings({"boundElementsByIndex": True})

The issue is that the popover is being dismissed when performing the actual search for the element.

mykola-mokhnach commented 3 years ago

I don't see any alls to settings API in the logs. Also double check the XCTest logs. It could be the popover gets dismissed by the default XCTest UI interruption handler

If you could confirm this is true then we may try to insert a custom handler to avoid the default interruption handler being executed.

lassebm commented 3 years ago

@mykola-mokhnach The update_settings() line is commented out in the sample code, but the issue is reproducible regardless of the boundElementsByIndex flag. As suggested, I patched WebDriverAgentMac with a UI interruption handler just logging it's invocation and returning true. The handler is never called.

WebDriverAgentMac patch:

--- WebDriverAgentMac/WebDriverAgentRunner/WebDriverAgentRunner.m.orig  2020-12-10 10:50:35.000000000 +0100
+++ WebDriverAgentMac/WebDriverAgentRunner/WebDriverAgentRunner.m   2020-12-10 10:50:44.000000000 +0100
@@ -17,6 +17,7 @@
 #import <XCTest/XCTest.h>

 #import <WebDriverAgentLib/WebDriverAgentLib.h>
+#import "FBLogger.h"

 @interface UITestingUITests : XCTestCase <FBWebServerDelegate>
 @end
@@ -35,6 +36,11 @@
  */
 - (void)testRunner
 {
+  [FBLogger logFmt:@"Adding UI interruption handler"];
+  [self addUIInterruptionMonitorWithDescription:@"Test handler" handler:^BOOL(XCUIElement * _Nonnull interruptingElement) {
+    [FBLogger logFmt:@"Handling UI interruption"];
+    return YES;
+  }];
   FBWebServer *webServer = [[FBWebServer alloc] init];
   webServer.delegate = self;
   [webServer startServing];

Appium log with boundElementsByIndex flag set and patched WebDriverAgentMac:

[Appium] Welcome to Appium v1.20.0-beta.0 (REV 0256991162023ea40de6dcd45ec9bd6ce192d171)
[Appium] Appium REST http interface listener started on 0.0.0.0:4723
[debug] [HTTP] Request idempotency key: 68df41c8-8a8c-4872-861c-0b6dfb1a9197
[HTTP] --> POST /wd/hub/session
[HTTP] {"capabilities":{"firstMatch":[{"platformName":"Mac","appium:automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true}]},"desiredCapabilities":{"platformName":"Mac","automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true}}
[debug] [W3C] Calling AppiumDriver.createSession() with args: [{"platformName":"Mac","automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true},null,{"firstMatch":[{"platformName":"Mac","appium:automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true}]}]
[debug] [BaseDriver] Event 'newSessionRequested' logged at 1607595949153 (11:25:49 GMT+0100 (Central European Standard Time))
[Appium] Appium v1.20.0-beta.0 creating new Mac2Driver (v0.4.2) session
[debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
[debug] [BaseDriver] Creating session with W3C capabilities: {
[debug] [BaseDriver]   "alwaysMatch": {
[debug] [BaseDriver]     "platformName": "Mac",
[debug] [BaseDriver]     "appium:automationName": "Mac2",
[debug] [BaseDriver]     "appium:bundleId": "com.apple.Music",
[debug] [BaseDriver]     "appium:showServerLogs": true
[debug] [BaseDriver]   },
[debug] [BaseDriver]   "firstMatch": [
[debug] [BaseDriver]     {}
[debug] [BaseDriver]   ]
[debug] [BaseDriver] }
[BaseDriver] Session created with session id: 7a71579b-9598-4113-9b25-a745b3f23f62
[debug] [WebDriverAgentMac] Using bootstrap root: /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac
[debug] [WebDriverAgentMac] Using xcodebuild binary at '/usr/bin/xcodebuild'
[debug] [WebDriverAgentMac] Using port 10100
[WebDriverAgentMac] Starting Mac2Driver host process: xcodebuild build-for-testing test-without-building -project /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac/WebDriverAgentMac.xcodeproj -scheme WebDriverAgentRunner COMPILER_INDEX_STORE_ENABLE\=NO
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] Command line invocation:
[debug] [WebDriverAgentMac] [xcodebuild] /Applications/Xcode.app/Contents/Developer/usr/bin/xcodebuild build-for-testing test-without-building -project /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac/WebDriverAgentMac.xcodeproj -scheme WebDriverAgentRunner COMPILER_INDEX_STORE_ENABLE=NO
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac] Build settings from command line:
[debug] [WebDriverAgentMac]     COMPILER_INDEX_STORE_ENABLE = NO
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] note: Using new build system
[debug] [WebDriverAgentMac] [xcodebuild] note: Building targets in parallel
[debug] [WebDriverAgentMac] [xcodebuild] note: Planning build
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] note: Using build description from disk
[debug] [WebDriverAgentMac] [xcodebuild] PBXCp /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentLib.framework /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app/Contents/PlugIns/WebDriverAgentRunner.xctest/Contents/Frameworks/WebDriverAgentLib.framework (in target 'WebDriverAgentRunner' from project 'WebDriverAgentMac')
[debug] [WebDriverAgentMac]     cd /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac
[debug] [WebDriverAgentMac]     builtin-copy -exclude .DS_Store -exclude CVS -exclude .svn -exclude .git -exclude .hg -exclude Headers -exclude PrivateHeaders -exclude Modules -exclude \*.tbd -resolve-src-symlinks /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentLib.framework /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app/Contents/PlugIns/WebDriverAgentRunner.xctest/Contents/Frameworks
[debug] [WebDriverAgentMac] [xcodebuild] CodeSign /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app/Contents/PlugIns/WebDriverAgentRunner.xctest/Contents/Frameworks/WebDriverAgentLib.framework/Versions/A (in target 'WebDriverAgentRunner' from project 'WebDriverAgentMac')
[debug] [WebDriverAgentMac]     cd /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac
[debug] [WebDriverAgentMac]     export CODESIGN_ALLOCATE\=/Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/codesign_allocate
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac] Signing Identity:     "-"
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac]     /usr/bin/codesign --force --sign - --timestamp\=none --preserve-metadata\=identifier,entitlements,flags /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app/Contents/PlugIns/WebDriverAgentRunner.xctest/Contents/Frameworks/WebDriverAgentLib.framework/Versions/A
[debug] [WebDriverAgentMac] [xcodebuild] /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app/Contents/PlugIns/WebDriverAgentRunner.xctest/Contents/Frameworks/WebDriverAgentLib.framework/Versions/A: replacing existing signature
[debug] [WebDriverAgentMac] [xcodebuild] CodeSign /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app/Contents/PlugIns/WebDriverAgentRunner.xctest (in target 'WebDriverAgentRunner' from project 'WebDriverAgentMac')
[debug] [WebDriverAgentMac]     cd /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac
[debug] [WebDriverAgentMac]     export CODESIGN_ALLOCATE\=/Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/codesign_allocate
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac] Signing Identity:     "-"
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac]     /usr/bin/codesign --force --sign - --entitlements /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Intermediates.noindex/WebDriverAgentMac.build/Debug/WebDriverAgentRunner.build/WebDriverAgentRunner.xctest.xcent --timestamp\=none /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app/Contents/PlugIns/WebDriverAgentRunner.xctest
[debug] [WebDriverAgentMac] [xcodebuild] /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app/Contents/PlugIns/WebDriverAgentRunner.xctest: replacing existing signature
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[debug] [WebDriverAgentMac] [xcodebuild] CodeSign /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app (in target 'WebDriverAgentRunner' from project 'WebDriverAgentMac')
[debug] [WebDriverAgentMac]     cd /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac
[debug] [WebDriverAgentMac]     export CODESIGN_ALLOCATE\=/Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/codesign_allocate
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac] Signing Identity:     "-"
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac]     /usr/bin/codesign --force --sign - --entitlements /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Intermediates.noindex/WebDriverAgentMac.build/Debug/WebDriverAgentRunner.build/WebDriverAgentRunner.xctest.xcent --timestamp\=none /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Build/Products/Debug/WebDriverAgentRunner-Runner.app: replacing existing signature
[debug] [WebDriverAgentMac] [xcodebuild] ** TEST BUILD SUCCEEDED **
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.418 xcodebuild[82429:5200853]  IDETestOperationsObserverDebug: Writing diagnostic log for test session to:
[debug] [WebDriverAgentMac] /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Logs/Test/Test-WebDriverAgentRunner-2020.12.10_11-25-52-+0100.xcresult/Staging/2_Test/Diagnostics/WebDriverAgentRunner-D9C95E18-870D-4675-9D33-369934ABF18E/WebDriverAgentRunner-0170CA22-FAD9-4C83-96AD-ED6D098D23BB/Session-WebDriverAgentRunner-2020-12-10_112554-sdjMCw.log
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.418 xcodebuild[82429:5200771] [MT] IDETestOperationsObserverDebug: (1C41D011-C4CC-4687-ACA2-EAA2FB52B8BD) Beginning test session WebDriverAgentRunner-1C41D011-C4CC-4687-ACA2-EAA2FB52B8BD at 2020-12-10 11:25:54.419 with Xcode 12B45b on target <DVTLocalComputer: 0x7fc263973d80 (My Mac | x86_64h)> (10.15.7 (19H15))
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.440 xcodebuild[82429:5200771] [MT] IDETestOperationsObserverDebug: (1C41D011-C4CC-4687-ACA2-EAA2FB52B8BD) Finished requesting crash reports. Continuing with testing.
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.724370+0100 WebDriverAgentRunner-Runner[82440:5201187] Running tests...
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'All tests' started at 2020-12-10 11:25:54.853
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'WebDriverAgentRunner.xctest' started at 2020-12-10 11:25:54.853
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'UITestingUITests' started at 2020-12-10 11:25:54.853
[debug] [WebDriverAgentMac] [xcodebuild] t =      nans Suite Set Up
[debug] [WebDriverAgentMac] [xcodebuild] Test Case '-[UITestingUITests testRunner]' started.
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.00s Start Test at 2020-12-10 11:25:54.856
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.00s Set Up
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.982245+0100 WebDriverAgentRunner-Runner[82440:5201669] [Arbitration] starting DTServiceHub child handshake.0 (send: 0x3807, receive: 0x3713)
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.982401+0100 WebDriverAgentRunner-Runner[82440:5201187] [Arbitration] attempting connection to singleton: 82438 with send port: 0x3507
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.982730+0100 WebDriverAgentRunner-Runner[82440:5201187] [Arbitration] handshake SUCCESSFUL (child: 82442 -> singleton: 82438)
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.983123+0100 WebDriverAgentRunner-Runner[82440:5201187] Adding UI interruption handler
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.983345+0100 WebDriverAgentRunner-Runner[82440:5201187] Built at Dec 10 2020 10:59:10
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:54.991525+0100 WebDriverAgentRunner-Runner[82440:5201187] ServerURLHere->http://localhost:10100<-ServerURLHere
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:55.292049+0100 WebDriverAgentRunner-Runner[82440:5201187] The data couldn’t be read because it isn’t in the correct format.
[debug] [WD Proxy] Got response with status 200: {"value":{"message":"WebDriverAgent is ready to accept commands","state":"success","os":{"version":"Version 10.15.7 (Build 19H15)"},"ready":true,"build":{"time":"Dec 10 2020 10:59:11"}},"sessionId":null}
[WebDriverAgentMac] The host process is ready within 6158ms
[debug] [WD Proxy] Matched '/session' to command name 'createSession'
[debug] [WD Proxy] Proxying [POST /session] to [POST http://127.0.0.1:10100/session] with body: {"capabilities":{"firstMatch":[{}],"alwaysMatch":{"platformName":"Mac","automationName":"Mac2","bundleId":"com.apple.Music","showServerLogs":true}}}
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.56s Open com.apple.Music
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.56s     Launch com.apple.Music
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:25:55.418687+0100 WebDriverAgentRunner-Runner[82440:5201187] Launching macOS application via NSWorkspace while sandboxed. Launch arguments and environment variables may be dropped.
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.79s         Wait for accessibility to load
[debug] [WebDriverAgentMac] [xcodebuild] t =     1.76s         Setting up automation session
[debug] [WebDriverAgentMac] [xcodebuild] t =     1.77s         Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":{"sessionId":"F71822C6-9C34-4E70-8C28-703852839B4D","capabilities":{"CFBundleIdentifier":"com.apple.Music"}},"sessionId":"F71822C6-9C34-4E70-8C28-703852839B4D"}
[WD Proxy] Determined the downstream protocol as 'W3C'
[Appium] New Mac2Driver session created successfully, session 7a71579b-9598-4113-9b25-a745b3f23f62 added to master session list
[debug] [BaseDriver] Event 'newSessionStarted' logged at 1607595956626 (11:25:56 GMT+0100 (Central European Standard Time))
[debug] [W3C (7a71579b)] Cached the protocol value 'W3C' for the new session 7a71579b-9598-4113-9b25-a745b3f23f62
[debug] [W3C (7a71579b)] Responding to client with driver.createSession() result: {"capabilities":{"platformName":"Mac","automationName":"Mac2","bundleId":"com.apple.Music","showServerLogs":true}}
[HTTP] <-- POST /wd/hub/session 200 7477 ms - 175
[HTTP]
[HTTP] --> POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/appium/settings
[HTTP] {"settings":{"boundElementsByIndex":true}}
[debug] [W3C (7a71579b)] Calling AppiumDriver.updateSettings() with args: [{"boundElementsByIndex":true},"7a71579b-9598-4113-9b25-a745b3f23f62"]
[debug] [W3C (7a71579b)] Responding to client with driver.updateSettings() result: null
[HTTP] <-- POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/appium/settings 200 10 ms - 14
[HTTP]
[HTTP] --> GET /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/appium/settings
[HTTP] {}
[debug] [W3C (7a71579b)] Calling AppiumDriver.getSettings() with args: ["7a71579b-9598-4113-9b25-a745b3f23f62"]
[debug] [W3C (7a71579b)] Responding to client with driver.getSettings() result: {"imageMatchThreshold":0.4,"fixImageFindScreenshotDims":true,"fixImageTemplateSize":false,"fixImageTemplateScale":false,"defaultImageTemplateScale":1,"checkForImageElementStaleness":true,"autoUpdateImageElementPosition":false,"imageElementTapStrategy":"w3cActions","getMatchedImageResult":false,"boundElementsByIndex":true}
[HTTP] <-- GET /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/appium/settings 200 8 ms - 333
[HTTP]
[HTTP] --> POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element
[HTTP] {"using":"-ios class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]"}
[debug] [W3C (7a71579b)] Calling AppiumDriver.findElement() with args: ["-ios class chain","**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]","7a71579b-9598-4113-9b25-a745b3f23f62"]
[debug] [BaseDriver] Valid locator strategies for this request: id, name, accessibility id, xpath, class name, -ios predicate string, predicate string, -ios class chain, class chain
[debug] [WD Proxy] Matched '/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /element] to [POST http://127.0.0.1:10100/session/F71822C6-9C34-4E70-8C28-703852839B4D/element] with body: {"using":"class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     1.81s Get all elements bound by accessibility element for: Elements matching predicate 'label == "airplay"'
[debug] [WD Proxy] Got response with status 200: {"value":{"ELEMENT":"F220C14A-35EA-4C39-B596-A9F4C34D3ECD","element-6066-11e4-a52e-4f735466cecf":"F220C14A-35EA-4C39-B596-A9F4C34D3ECD"},"sessionId":"F71822C6-9C34-4E70-8C28-703852839B4D"}
[debug] [W3C (7a71579b)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":"F220C14A-35EA-4C39-B596-A9F4C34D3ECD","ELEMENT":"F220C14A-35EA-4C39-B596-A9F4C34D3ECD"}
[HTTP] <-- POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element 200 292 ms - 137
[HTTP]
[HTTP] --> POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element/F220C14A-35EA-4C39-B596-A9F4C34D3ECD/click
[HTTP] {"id":"F220C14A-35EA-4C39-B596-A9F4C34D3ECD"}
[W3C (7a71579b)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element/F220C14A-35EA-4C39-B596-A9F4C34D3ECD/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element/F220C14A-35EA-4C39-B596-A9F4C34D3ECD/click] to [POST http://127.0.0.1:10100/session/F71822C6-9C34-4E70-8C28-703852839B4D/element/F220C14A-35EA-4C39-B596-A9F4C34D3ECD/click] with body: {"id":"F220C14A-35EA-4C39-B596-A9F4C34D3ECD"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.11s Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.21s Click "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.21s     Wait for com.apple.Music to idle
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.21s     Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.36s     Synthesize event
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.68s     Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":"F71822C6-9C34-4E70-8C28-703852839B4D"}
[WD Proxy] Replacing sessionId F71822C6-9C34-4E70-8C28-703852839B4D with 7a71579b-9598-4113-9b25-a745b3f23f62
[HTTP] <-- POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element/F220C14A-35EA-4C39-B596-A9F4C34D3ECD/click 200 578 ms - 65
[HTTP]
[HTTP] --> POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element
[HTTP] {"using":"-ios class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]"}
[debug] [W3C (7a71579b)] Calling AppiumDriver.findElement() with args: ["-ios class chain","**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]","7a71579b-9598-4113-9b25-a745b3f23f62"]
[debug] [BaseDriver] Valid locator strategies for this request: id, name, accessibility id, xpath, class name, -ios predicate string, predicate string, -ios class chain, class chain
[debug] [WD Proxy] Matched '/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /element] to [POST http://127.0.0.1:10100/session/F71822C6-9C34-4E70-8C28-703852839B4D/element] with body: {"using":"class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     4.69s Get all elements bound by accessibility element for: Elements matching predicate 'label BEGINSWITH "Computer , "'
[debug] [WD Proxy] Got response with status 200: {"value":{"ELEMENT":"F922980B-735A-4F7A-B4AA-6D5F05FE8DB8","element-6066-11e4-a52e-4f735466cecf":"F922980B-735A-4F7A-B4AA-6D5F05FE8DB8"},"sessionId":"F71822C6-9C34-4E70-8C28-703852839B4D"}
[debug] [W3C (7a71579b)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":"F922980B-735A-4F7A-B4AA-6D5F05FE8DB8","ELEMENT":"F922980B-735A-4F7A-B4AA-6D5F05FE8DB8"}
[HTTP] <-- POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element 200 127 ms - 137
[HTTP]
[HTTP] --> POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element/F922980B-735A-4F7A-B4AA-6D5F05FE8DB8/click
[HTTP] {"id":"F922980B-735A-4F7A-B4AA-6D5F05FE8DB8"}
[W3C (7a71579b)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element/F922980B-735A-4F7A-B4AA-6D5F05FE8DB8/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element/F922980B-735A-4F7A-B4AA-6D5F05FE8DB8/click] to [POST http://127.0.0.1:10100/session/F71822C6-9C34-4E70-8C28-703852839B4D/element/F922980B-735A-4F7A-B4AA-6D5F05FE8DB8/click] with body: {"id":"F922980B-735A-4F7A-B4AA-6D5F05FE8DB8"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     6.82s Find the "Computer , unselected" TableRow
[debug] [WebDriverAgentMac] [xcodebuild] t =     7.94s     Find the "Computer , unselected" TableRow (retry 1)
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.06s     Find the "Computer , unselected" TableRow (retry 2)
[WD Proxy] Got response with status 404: {"value":{"error":"stale element reference","message":"The element \"\"Computer , unselected\" TableRow\" identified by \"F922980B-735A-4F7A-B4AA-6D5F05FE8DB8\" is not present on the current view (No matches found for Children matching type Popover from input {(\n    PopUpButton, label: 'airplay'\n)}). Make sure the current view is the expected one","traceback":"(\n\t0   CoreFoundation                      0x00007fff2dc7fb57 __exceptionPreprocess + 250\n\t1   libobjc.A.dylib                     0x00007fff66acb5bf objc_exception_throw + 48\n\t2   WebDriverAgentLib                   0x000000010302480f -[FBElementCache elementForUUID:] + 1167\n\t3   WebDriverAgentLib                   0x00000001030046ed +[FBElementCommands handleClick:] + 205\n\t4   WebDriverAgentLib                   0x0000000103022276 -[FBRoute_TargetAction mountRequest:intoResponse:] + 182\n\t5   WebDriverAgentLib                   0x000000010301be33 __37-[FBWebServer registerRouteHandlers:]_block_invoke + 723\n\t6   WebDriverAgentLib     ...
[debug] [W3C] Matched W3C error code 'stale element reference' to StaleElementReferenceError
[HTTP] <-- POST /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62/element/F922980B-735A-4F7A-B4AA-6D5F05FE8DB8/click 404 2412 ms - 1064
[HTTP]
[HTTP] --> DELETE /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62
[HTTP] {}
[debug] [W3C (7a71579b)] Calling AppiumDriver.deleteSession() with args: ["7a71579b-9598-4113-9b25-a745b3f23f62"]
[debug] [BaseDriver] Event 'quitSessionRequested' logged at 1607595964087 (11:26:04 GMT+0100 (Central European Standard Time))
[Appium] Removing session 7a71579b-9598-4113-9b25-a745b3f23f62 from our master session list
[debug] [WD Proxy] Matched '/session/F71822C6-9C34-4E70-8C28-703852839B4D' to command name 'deleteSession'
[debug] [WD Proxy] Proxying [DELETE /session/F71822C6-9C34-4E70-8C28-703852839B4D] to [DELETE http://127.0.0.1:10100/session/F71822C6-9C34-4E70-8C28-703852839B4D] with no body
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 11:26:04.089547+0100 WebDriverAgentRunner-Runner[82440:5201187] The data couldn’t be read because it isn’t in the correct format.
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.23s Terminate com.apple.Music:82445
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":null}
[debug] [BaseDriver] Event 'quitSessionFinished' logged at 1607595965123 (11:26:05 GMT+0100 (Central European Standard Time))
[debug] [W3C (7a71579b)] Received response: null
[debug] [W3C (7a71579b)] But deleting session, so not returning
[debug] [W3C (7a71579b)] Responding to client with driver.deleteSession() result: null
[HTTP] <-- DELETE /wd/hub/session/7a71579b-9598-4113-9b25-a745b3f23f62 200 1037 ms - 14
[HTTP]
mykola-mokhnach commented 3 years ago

It looks like the setting value does not get applied. Please try changing the setting with https://github.com/appium/appium-mac2-driver/pull/30

lassebm commented 3 years ago

@mykola-mokhnach I've tried your patch, issue still reproducible.

Appium log with boundElementsByIndex flag set and patch from #30:

[Appium] Welcome to Appium v1.20.0-beta.0 (REV 0256991162023ea40de6dcd45ec9bd6ce192d171)
[Appium] Appium REST http interface listener started on 0.0.0.0:4723
[debug] [HTTP] Request idempotency key: 367ee9ca-410d-4b6b-8441-49f90bdcd7c7
[HTTP] --> POST /wd/hub/session
[HTTP] {"capabilities":{"firstMatch":[{"platformName":"Mac","appium:automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true}]},"desiredCapabilities":{"platformName":"Mac","automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true}}
[debug] [W3C] Calling AppiumDriver.createSession() with args: [{"platformName":"Mac","automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true},null,{"firstMatch":[{"platformName":"Mac","appium:automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true}]}]
[debug] [BaseDriver] Event 'newSessionRequested' logged at 1607603394362 (13:29:54 GMT+0100 (Central European Standard Time))
[Appium] Appium v1.20.0-beta.0 creating new Mac2Driver (v0.4.2) session
[debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
[debug] [BaseDriver] Creating session with W3C capabilities: {
[debug] [BaseDriver]   "alwaysMatch": {
[debug] [BaseDriver]     "platformName": "Mac",
[debug] [BaseDriver]     "appium:automationName": "Mac2",
[debug] [BaseDriver]     "appium:bundleId": "com.apple.Music",
[debug] [BaseDriver]     "appium:showServerLogs": true
[debug] [BaseDriver]   },
[debug] [BaseDriver]   "firstMatch": [
[debug] [BaseDriver]     {}
[debug] [BaseDriver]   ]
[debug] [BaseDriver] }
[BaseDriver] Session created with session id: 65322b56-57ed-417a-a552-d2d456d1a18f
[debug] [WebDriverAgentMac] Using bootstrap root: /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac
[debug] [WebDriverAgentMac] Using xcodebuild binary at '/usr/bin/xcodebuild'
[debug] [WebDriverAgentMac] Using port 10100
[WebDriverAgentMac] Starting Mac2Driver host process: xcodebuild build-for-testing test-without-building -project /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac/WebDriverAgentMac.xcodeproj -scheme WebDriverAgentRunner COMPILER_INDEX_STORE_ENABLE\=NO
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] Command line invocation:
[debug] [WebDriverAgentMac] [xcodebuild] /Applications/Xcode.app/Contents/Developer/usr/bin/xcodebuild build-for-testing test-without-building -project /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac/WebDriverAgentMac.xcodeproj -scheme WebDriverAgentRunner COMPILER_INDEX_STORE_ENABLE=NO
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac] Build settings from command line:
[debug] [WebDriverAgentMac]     COMPILER_INDEX_STORE_ENABLE = NO
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] note: Using new build system
[debug] [WebDriverAgentMac] [xcodebuild] note: Building targets in parallel
[debug] [WebDriverAgentMac] [xcodebuild] note: Planning build
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] note: Using build description from disk
[debug] [WebDriverAgentMac] [xcodebuild] ** TEST BUILD SUCCEEDED **
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:58.118 xcodebuild[90435:5318024]  IDETestOperationsObserverDebug: Writing diagnostic log for test session to:
[debug] [WebDriverAgentMac] /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Logs/Test/Test-WebDriverAgentRunner-2020.12.10_13-29-56-+0100.xcresult/Staging/2_Test/Diagnostics/WebDriverAgentRunner-7030B9A8-7B27-447E-9E2C-B67E8F3EA0A3/WebDriverAgentRunner-44E2CD27-61AE-4BE3-B23F-9994EDCE46B8/Session-WebDriverAgentRunner-2020-12-10_132958-VuiHCi.log
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:58.119 xcodebuild[90435:5317943] [MT] IDETestOperationsObserverDebug: (94669630-4215-4154-AB19-88D77EEAC9F2) Beginning test session WebDriverAgentRunner-94669630-4215-4154-AB19-88D77EEAC9F2 at 2020-12-10 13:29:58.119 with Xcode 12B45b on target <DVTLocalComputer: 0x7f9061257180 (My Mac | x86_64h)> (10.15.7 (19H15))
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:58.132 xcodebuild[90435:5317943] [MT] IDETestOperationsObserverDebug: (94669630-4215-4154-AB19-88D77EEAC9F2) Finished requesting crash reports. Continuing with testing.
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:58.391232+0100 WebDriverAgentRunner-Runner[90440:5318214] Running tests...
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'All tests' started at 2020-12-10 13:29:58.501
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'WebDriverAgentRunner.xctest' started at 2020-12-10 13:29:58.501
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'UITestingUITests' started at 2020-12-10 13:29:58.502
[debug] [WebDriverAgentMac] [xcodebuild] t =      nans Suite Set Up
[debug] [WebDriverAgentMac] [xcodebuild] Test Case '-[UITestingUITests testRunner]' started.
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.00s Start Test at 2020-12-10 13:29:58.504
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.00s Set Up
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:58.572452+0100 WebDriverAgentRunner-Runner[90440:5318689] [Arbitration] starting DTServiceHub child handshake.0 (send: 0x3607, receive: 0x490f)
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:58.572586+0100 WebDriverAgentRunner-Runner[90440:5318214] [Arbitration] attempting connection to singleton: 90438 with send port: 0x3907
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:58.573019+0100 WebDriverAgentRunner-Runner[90440:5318214] [Arbitration] handshake SUCCESSFUL (child: 90442 -> singleton: 90438)
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:58.573240+0100 WebDriverAgentRunner-Runner[90440:5318214] Built at Dec 10 2020 12:58:07
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:58.580722+0100 WebDriverAgentRunner-Runner[90440:5318214] ServerURLHere->http://localhost:10100<-ServerURLHere
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:59.472498+0100 WebDriverAgentRunner-Runner[90440:5318214] The data couldn’t be read because it isn’t in the correct format.
[debug] [WD Proxy] Got response with status 200: {"value":{"message":"WebDriverAgent is ready to accept commands","state":"success","os":{"version":"Version 10.15.7 (Build 19H15)"},"ready":true,"build":{"time":"Dec 10 2020 12:58:07"}},"sessionId":null}
[WebDriverAgentMac] The host process is ready within 5130ms
[debug] [WD Proxy] Matched '/session' to command name 'createSession'
[debug] [WD Proxy] Proxying [POST /session] to [POST http://127.0.0.1:10100/session] with body: {"capabilities":{"firstMatch":[{}],"alwaysMatch":{"platformName":"Mac","automationName":"Mac2","bundleId":"com.apple.Music","showServerLogs":true}}}
[debug] [WebDriverAgentMac] [xcodebuild] t =     1.08s Open com.apple.Music
[debug] [WebDriverAgentMac] [xcodebuild] t =     1.08s     Launch com.apple.Music
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:29:59.580028+0100 WebDriverAgentRunner-Runner[90440:5318214] Launching macOS application via NSWorkspace while sandboxed. Launch arguments and environment variables may be dropped.
[debug] [WebDriverAgentMac] [xcodebuild] t =     1.27s         Wait for accessibility to load
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.09s         Setting up automation session
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.10s         Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":{"sessionId":"F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90","capabilities":{"CFBundleIdentifier":"com.apple.Music"}},"sessionId":"F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90"}
[WD Proxy] Determined the downstream protocol as 'W3C'
[Appium] New Mac2Driver session created successfully, session 65322b56-57ed-417a-a552-d2d456d1a18f added to master session list
[debug] [BaseDriver] Event 'newSessionStarted' logged at 1607603400609 (13:30:00 GMT+0100 (Central European Standard Time))
[debug] [W3C (65322b56)] Cached the protocol value 'W3C' for the new session 65322b56-57ed-417a-a552-d2d456d1a18f
[debug] [W3C (65322b56)] Responding to client with driver.createSession() result: {"capabilities":{"platformName":"Mac","automationName":"Mac2","bundleId":"com.apple.Music","showServerLogs":true}}
[HTTP] <-- POST /wd/hub/session 200 6252 ms - 175
[HTTP]
[HTTP] --> POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/appium/settings
[HTTP] {"settings":{"boundElementsByIndex":true}}
[debug] [W3C (65322b56)] Calling AppiumDriver.updateSettings() with args: [{"boundElementsByIndex":true},"65322b56-57ed-417a-a552-d2d456d1a18f"]
[debug] [WD Proxy] Matched '/appium/settings' to command name 'updateSettings'
[debug] [WD Proxy] Proxying [POST /appium/settings] to [POST http://127.0.0.1:10100/session/F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90/appium/settings] with body: {"settings":{"boundElementsByIndex":true}}
[debug] [WD Proxy] Got response with status 200: {"value":{"boundElementsByIndex":true},"sessionId":"F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90"}
[debug] [W3C (65322b56)] Responding to client with driver.updateSettings() result: null
[HTTP] <-- POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/appium/settings 200 21 ms - 14
[HTTP]
[HTTP] --> GET /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/appium/settings
[HTTP] {}
[debug] [W3C (65322b56)] Calling AppiumDriver.getSettings() with args: ["65322b56-57ed-417a-a552-d2d456d1a18f"]
[debug] [W3C (65322b56)] Responding to client with driver.getSettings() result: {"imageMatchThreshold":0.4,"fixImageFindScreenshotDims":true,"fixImageTemplateSize":false,"fixImageTemplateScale":false,"defaultImageTemplateScale":1,"checkForImageElementStaleness":true,"autoUpdateImageElementPosition":false,"imageElementTapStrategy":"w3cActions","getMatchedImageResult":false,"boundElementsByIndex":true}
[HTTP] <-- GET /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/appium/settings 200 8 ms - 333
[HTTP]
[HTTP] --> POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element
[HTTP] {"using":"-ios class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]"}
[debug] [W3C (65322b56)] Calling AppiumDriver.findElement() with args: ["-ios class chain","**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]","65322b56-57ed-417a-a552-d2d456d1a18f"]
[debug] [BaseDriver] Valid locator strategies for this request: id, name, accessibility id, xpath, class name, -ios predicate string, predicate string, -ios class chain, class chain
[debug] [WD Proxy] Matched '/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /element] to [POST http://127.0.0.1:10100/session/F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90/element] with body: {"using":"class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.15s Get all elements bound by index for: Elements matching predicate 'label == "airplay"'
[debug] [WD Proxy] Got response with status 200: {"value":{"ELEMENT":"93A2112F-48DF-4DAD-9394-124E024B9F12","element-6066-11e4-a52e-4f735466cecf":"93A2112F-48DF-4DAD-9394-124E024B9F12"},"sessionId":"F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90"}
[debug] [W3C (65322b56)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":"93A2112F-48DF-4DAD-9394-124E024B9F12","ELEMENT":"93A2112F-48DF-4DAD-9394-124E024B9F12"}
[HTTP] <-- POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element 200 233 ms - 137
[HTTP]
[HTTP] --> POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element/93A2112F-48DF-4DAD-9394-124E024B9F12/click
[HTTP] {"id":"93A2112F-48DF-4DAD-9394-124E024B9F12"}
[W3C (65322b56)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element/93A2112F-48DF-4DAD-9394-124E024B9F12/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element/93A2112F-48DF-4DAD-9394-124E024B9F12/click] to [POST http://127.0.0.1:10100/session/F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90/element/93A2112F-48DF-4DAD-9394-124E024B9F12/click] with body: {"id":"93A2112F-48DF-4DAD-9394-124E024B9F12"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.39s Find the PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.52s Click "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.52s     Wait for com.apple.Music to idle
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.53s     Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.74s     Synthesize event
[debug] [WebDriverAgentMac] [xcodebuild] t =     3.06s     Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":"F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90"}
[WD Proxy] Replacing sessionId F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90 with 65322b56-57ed-417a-a552-d2d456d1a18f
[HTTP] <-- POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element/93A2112F-48DF-4DAD-9394-124E024B9F12/click 200 673 ms - 65
[HTTP]
[HTTP] --> POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element
[HTTP] {"using":"-ios class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]"}
[debug] [W3C (65322b56)] Calling AppiumDriver.findElement() with args: ["-ios class chain","**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]","65322b56-57ed-417a-a552-d2d456d1a18f"]
[debug] [BaseDriver] Valid locator strategies for this request: id, name, accessibility id, xpath, class name, -ios predicate string, predicate string, -ios class chain, class chain
[debug] [WD Proxy] Matched '/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /element] to [POST http://127.0.0.1:10100/session/F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90/element] with body: {"using":"class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`]"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     5.07s Get all elements bound by index for: Elements matching predicate 'label BEGINSWITH "Computer , "'
[debug] [WD Proxy] Got response with status 200: {"value":{"ELEMENT":"F4E6E477-1F4C-44A7-9407-5631ED2EF3FD","element-6066-11e4-a52e-4f735466cecf":"F4E6E477-1F4C-44A7-9407-5631ED2EF3FD"},"sessionId":"F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90"}
[debug] [W3C (65322b56)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":"F4E6E477-1F4C-44A7-9407-5631ED2EF3FD","ELEMENT":"F4E6E477-1F4C-44A7-9407-5631ED2EF3FD"}
[HTTP] <-- POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element 200 127 ms - 137
[HTTP]
[HTTP] --> POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element/F4E6E477-1F4C-44A7-9407-5631ED2EF3FD/click
[HTTP] {"id":"F4E6E477-1F4C-44A7-9407-5631ED2EF3FD"}
[W3C (65322b56)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element/F4E6E477-1F4C-44A7-9407-5631ED2EF3FD/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element/F4E6E477-1F4C-44A7-9407-5631ED2EF3FD/click] to [POST http://127.0.0.1:10100/session/F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90/element/F4E6E477-1F4C-44A7-9407-5631ED2EF3FD/click] with body: {"id":"F4E6E477-1F4C-44A7-9407-5631ED2EF3FD"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     7.20s Find the TableRow
[debug] [WebDriverAgentMac] [xcodebuild] t =     8.33s     Find the TableRow (retry 1)
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.45s     Find the TableRow (retry 2)
[WD Proxy] Got response with status 404: {"value":{"error":"stale element reference","message":"The element \"TableRow\" identified by \"F4E6E477-1F4C-44A7-9407-5631ED2EF3FD\" is not present on the current view (No matches found for Children matching type Popover from input {(\n    PopUpButton, label: 'airplay'\n)}). Make sure the current view is the expected one","traceback":"(\n\t0   CoreFoundation                      0x00007fff2dc7fb57 __exceptionPreprocess + 250\n\t1   libobjc.A.dylib                     0x00007fff66acb5bf objc_exception_throw + 48\n\t2   WebDriverAgentLib                   0x000000010473a80f -[FBElementCache elementForUUID:] + 1167\n\t3   WebDriverAgentLib                   0x000000010471a6ed +[FBElementCommands handleClick:] + 205\n\t4   WebDriverAgentLib                   0x0000000104738276 -[FBRoute_TargetAction mountRequest:intoResponse:] + 182\n\t5   WebDriverAgentLib                   0x0000000104731e33 __37-[FBWebServer registerRouteHandlers:]_block_invoke + 723\n\t6   WebDriverAgentLib                   0x0000000104...
[debug] [W3C] Matched W3C error code 'stale element reference' to StaleElementReferenceError
[HTTP] <-- POST /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f/element/F4E6E477-1F4C-44A7-9407-5631ED2EF3FD/click 404 2422 ms - 1012
[HTTP]
[HTTP] --> DELETE /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f
[HTTP] {}
[debug] [W3C (65322b56)] Calling AppiumDriver.deleteSession() with args: ["65322b56-57ed-417a-a552-d2d456d1a18f"]
[debug] [BaseDriver] Event 'quitSessionRequested' logged at 1607603408129 (13:30:08 GMT+0100 (Central European Standard Time))
[Appium] Removing session 65322b56-57ed-417a-a552-d2d456d1a18f from our master session list
[debug] [WD Proxy] Matched '/session/F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90' to command name 'deleteSession'
[debug] [WD Proxy] Proxying [DELETE /session/F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90] to [DELETE http://127.0.0.1:10100/session/F8EE6FD2-8BCA-4FC6-BB41-9C27D53E6A90] with no body
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-10 13:30:08.131157+0100 WebDriverAgentRunner-Runner[90440:5318214] The data couldn’t be read because it isn’t in the correct format.
[debug] [WebDriverAgentMac] [xcodebuild] t =     9.63s Terminate com.apple.Music:90445
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":null}
[debug] [BaseDriver] Event 'quitSessionFinished' logged at 1607603409187 (13:30:09 GMT+0100 (Central European Standard Time))
[debug] [W3C (65322b56)] Received response: null
[debug] [W3C (65322b56)] But deleting session, so not returning
[debug] [W3C (65322b56)] Responding to client with driver.deleteSession() result: null
[HTTP] <-- DELETE /wd/hub/session/65322b56-57ed-417a-a552-d2d456d1a18f 200 1059 ms - 14
[HTTP]
mykola-mokhnach commented 3 years ago

The lookup now works properly. Unfortunately I don't have any other ideas regarding that. Most likely it is an XCTest issue, since we don't have much in the server code on top of the "standard" stuff

lassebm commented 3 years ago

@mykola-mokhnach As an alternative approach, I tried fetching the coordinates and clicking the element with the macos: click command, without success: Invalid parameter not satisfying: point.x != INFINITY && point.y != INFINITY. I'm reaching a dead end.

Appium log:

[Appium] Welcome to Appium v1.20.0-beta.0 (REV a1ef920af1d6e14c55ea2c7161bc74dd40e70053)
[Appium] Appium REST http interface listener started on 0.0.0.0:4723
[debug] [HTTP] Request idempotency key: b76130fc-28a0-4574-a993-31be6ccabac5
[HTTP] --> POST /wd/hub/session
[HTTP] {"capabilities":{"firstMatch":[{"platformName":"Mac","appium:automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true,"appium:skipAppKill":true}]},"desiredCapabilities":{"platformName":"Mac","automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true,"appium:skipAppKill":true}}
[debug] [W3C] Calling AppiumDriver.createSession() with args: [{"platformName":"Mac","automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true,"appium:skipAppKill":true},null,{"firstMatch":[{"platformName":"Mac","appium:automationName":"Mac2","appium:bundleId":"com.apple.Music","appium:showServerLogs":true,"appium:skipAppKill":true}]}]
[debug] [BaseDriver] Event 'newSessionRequested' logged at 1607937715989 (10:21:55 GMT+0100 (Central European Standard Time))
[Appium] Appium v1.20.0-beta.0 creating new Mac2Driver (v0.5.0) session
[debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
[debug] [BaseDriver] Creating session with W3C capabilities: {
[debug] [BaseDriver]   "alwaysMatch": {
[debug] [BaseDriver]     "platformName": "Mac",
[debug] [BaseDriver]     "appium:automationName": "Mac2",
[debug] [BaseDriver]     "appium:bundleId": "com.apple.Music",
[debug] [BaseDriver]     "appium:showServerLogs": true,
[debug] [BaseDriver]     "appium:skipAppKill": true
[debug] [BaseDriver]   },
[debug] [BaseDriver]   "firstMatch": [
[debug] [BaseDriver]     {}
[debug] [BaseDriver]   ]
[debug] [BaseDriver] }
[BaseDriver] Session created with session id: 09237a47-3d8f-4445-9397-6292b98d4ff7
[debug] [WebDriverAgentMac] Using bootstrap root: /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac
[debug] [WebDriverAgentMac] Using xcodebuild binary at '/usr/bin/xcodebuild'
[debug] [WebDriverAgentMac] Using port 10100
[WebDriverAgentMac] Starting Mac2Driver host process: xcodebuild build-for-testing test-without-building -project /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac/WebDriverAgentMac.xcodeproj -scheme WebDriverAgentRunner COMPILER_INDEX_STORE_ENABLE\=NO
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] Command line invocation:
[debug] [WebDriverAgentMac]     /Applications/Xcode.app/Contents/Developer/usr/bin/xcodebuild build-for-testing test-without-building -project /Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/WebDriverAgentMac/WebDriverAgentMac.xcodeproj -scheme WebDriverAgentRunner COMPILER_INDEX_STORE_ENABLE=NO
[debug] [WebDriverAgentMac]
[debug] [WebDriverAgentMac] Build settings from command line:
[debug] [WebDriverAgentMac]     COMPILER_INDEX_STORE_ENABLE = NO
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] note: Using new build system
[debug] [WebDriverAgentMac] [xcodebuild] note: Building targets in parallel
[debug] [WebDriverAgentMac] [xcodebuild] note: Planning build
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] note: Using build description from disk
[debug] [WebDriverAgentMac] [xcodebuild] ** TEST BUILD SUCCEEDED **
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:01.993 xcodebuild[19771:5922012]  IDETestOperationsObserverDebug: Writing diagnostic log for test session to:
[debug] [WebDriverAgentMac] /Users/lmikkelsen/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-fvtbngtcnodvmagenfvpidkbbgwu/Logs/Test/Test-WebDriverAgentRunner-2020.12.14_10-22-00-+0100.xcresult/Staging/2_Test/Diagnostics/WebDriverAgentRunner-94B748FE-CE0C-4492-8607-FC7F605B1FA7/WebDriverAgentRunner-A0D20826-73C4-4AF7-997A-B9F6AD8322AC/Session-WebDriverAgentRunner-2020-12-14_102201-GPblEn.log
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:01.994 xcodebuild[19771:5921875] [MT] IDETestOperationsObserverDebug: (97C76111-9434-480E-85F9-7D8AAC2F9CA0) Beginning test session WebDriverAgentRunner-97C76111-9434-480E-85F9-7D8AAC2F9CA0 at 2020-12-14 10:22:01.994 with Xcode 12B45b on target <DVTLocalComputer: 0x7ff8a9d55c70 (My Mac | x86_64h)> (10.15.7 (19H15))
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:02.038 xcodebuild[19771:5921875] [MT] IDETestOperationsObserverDebug: (97C76111-9434-480E-85F9-7D8AAC2F9CA0) Finished requesting crash reports. Continuing with testing.
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[WD Proxy] connect ECONNREFUSED 127.0.0.1:10100
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:02.313076+0100 WebDriverAgentRunner-Runner[19778:5922234] Running tests...
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'All tests' started at 2020-12-14 10:22:02.475
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'WebDriverAgentRunner.xctest' started at 2020-12-14 10:22:02.475
[debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'UITestingUITests' started at 2020-12-14 10:22:02.475
[debug] [WebDriverAgentMac] [xcodebuild] t =      nans Suite Set Up
[debug] [WebDriverAgentMac] [xcodebuild] Test Case '-[UITestingUITests testRunner]' started.
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.00s Start Test at 2020-12-14 10:22:02.478
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.00s Set Up
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:02.622127+0100 WebDriverAgentRunner-Runner[19778:5922562] [Arbitration] starting DTServiceHub child handshake.0 (send: 0x3607, receive: 0x370f)
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:02.622347+0100 WebDriverAgentRunner-Runner[19778:5922234] [Arbitration] attempting connection to singleton: 19776 with send port: 0x390b
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:02.622759+0100 WebDriverAgentRunner-Runner[19778:5922234] [Arbitration] handshake SUCCESSFUL (child: 19780 -> singleton: 19776)
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:02.623120+0100 WebDriverAgentRunner-Runner[19778:5922234] Built at Dec 14 2020 10:19:20
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:02.631856+0100 WebDriverAgentRunner-Runner[19778:5922234] ServerURLHere->http://localhost:10100<-ServerURLHere
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://127.0.0.1:10100/status] with no body
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:03.127686+0100 WebDriverAgentRunner-Runner[19778:5922234] The data couldn’t be read because it isn’t in the correct format.
[debug] [WD Proxy] Got response with status 200: {"value":{"message":"WebDriverAgent is ready to accept commands","state":"success","os":{"version":"Version 10.15.7 (Build 19H15)"},"ready":true,"build":{"time":"Dec 14 2020 10:19:19"}},"sessionId":null}
[WebDriverAgentMac] The host process is ready within 7209ms
[debug] [WD Proxy] Matched '/session' to command name 'createSession'
[debug] [WD Proxy] Proxying [POST /session] to [POST http://127.0.0.1:10100/session] with body: {"capabilities":{"firstMatch":[{}],"alwaysMatch":{"platformName":"Mac","automationName":"Mac2","bundleId":"com.apple.Music","showServerLogs":true,"skipAppKill":true}}}
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.82s Open com.apple.Music
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.82s     Launch com.apple.Music
[debug] [WebDriverAgentMac] [xcodebuild] t =     0.82s         Terminate com.apple.Music:19728
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:04.376120+0100 WebDriverAgentRunner-Runner[19778:5922234] Launching macOS application via NSWorkspace while sandboxed. Launch arguments and environment variables may be dropped.
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.11s         Wait for accessibility to load
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.94s         Setting up automation session
[debug] [WebDriverAgentMac] [xcodebuild] t =     2.96s         Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":{"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C","capabilities":{"CFBundleIdentifier":"com.apple.Music"}},"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C"}
[WD Proxy] Determined the downstream protocol as 'W3C'
[Appium] New Mac2Driver session created successfully, session 09237a47-3d8f-4445-9397-6292b98d4ff7 added to master session list
[debug] [BaseDriver] Event 'newSessionStarted' logged at 1607937725445 (10:22:05 GMT+0100 (Central European Standard Time))
[debug] [W3C (09237a47)] Cached the protocol value 'W3C' for the new session 09237a47-3d8f-4445-9397-6292b98d4ff7
[debug] [W3C (09237a47)] Responding to client with driver.createSession() result: {"capabilities":{"platformName":"Mac","automationName":"Mac2","bundleId":"com.apple.Music","showServerLogs":true,"skipAppKill":true}}
[HTTP] <-- POST /wd/hub/session 200 9460 ms - 194
[HTTP]
[HTTP] --> POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/appium/settings
[HTTP] {"settings":{"boundElementsByIndex":true,"useDefaultUiInterruptionsHandling":false}}
[debug] [W3C (09237a47)] Calling AppiumDriver.updateSettings() with args: [{"boundElementsByIndex":true,"useDefaultUiInterruptionsHandling":false},"09237a47-3d8f-4445-9397-6292b98d4ff7"]
[debug] [WD Proxy] Matched '/appium/settings' to command name 'updateSettings'
[debug] [WD Proxy] Proxying [POST /appium/settings] to [POST http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C/appium/settings] with body: {"settings":{"boundElementsByIndex":true}}
[debug] [WD Proxy] Got response with status 200: {"value":{"boundElementsByIndex":true,"useDefaultUiInterruptionsHandling":1},"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C"}
[debug] [WD Proxy] Matched '/appium/settings' to command name 'updateSettings'
[debug] [WD Proxy] Proxying [POST /appium/settings] to [POST http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C/appium/settings] with body: {"settings":{"useDefaultUiInterruptionsHandling":false}}
[debug] [WD Proxy] Got response with status 200: {"value":{"boundElementsByIndex":true,"useDefaultUiInterruptionsHandling":0},"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C"}
[debug] [W3C (09237a47)] Responding to client with driver.updateSettings() result: null
[HTTP] <-- POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/appium/settings 200 21 ms - 14
[HTTP]
[HTTP] --> POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element
[HTTP] {"using":"-ios class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]"}
[debug] [W3C (09237a47)] Calling AppiumDriver.findElement() with args: ["-ios class chain","**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]","09237a47-3d8f-4445-9397-6292b98d4ff7"]
[debug] [BaseDriver] Valid locator strategies for this request: id, name, accessibility id, xpath, class name, -ios predicate string, predicate string, -ios class chain, class chain
[debug] [WD Proxy] Matched '/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /element] to [POST http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C/element] with body: {"using":"class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     3.00s Get all elements bound by index for: Elements matching predicate 'label == "airplay"'
[debug] [WD Proxy] Got response with status 200: {"value":{"ELEMENT":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC","element-6066-11e4-a52e-4f735466cecf":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC"},"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C"}
[debug] [W3C (09237a47)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC","ELEMENT":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC"}
[HTTP] <-- POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element 200 169 ms - 137
[HTTP]
[HTTP] --> POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click
[HTTP] {"id":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC"}
[W3C (09237a47)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click] to [POST http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click] with body: {"id":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     3.17s Find the PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     3.30s Click "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     3.30s     Wait for com.apple.Music to idle
[debug] [WebDriverAgentMac] [xcodebuild] t =     3.30s     Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     3.39s     Application is configured to skip UI interruption handling
[debug] [WebDriverAgentMac] [xcodebuild] t =     3.39s     Synthesize event
[debug] [WebDriverAgentMac] [xcodebuild] t =     3.76s     Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C"}
[WD Proxy] Replacing sessionId 58834BB5-6A4A-4029-83BF-FECC885B842C with 09237a47-3d8f-4445-9397-6292b98d4ff7
[HTTP] <-- POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click 200 597 ms - 65
[HTTP]
[HTTP] --> POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element
[HTTP] {"using":"-ios class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`][-1]"}
[debug] [W3C (09237a47)] Calling AppiumDriver.findElement() with args: ["-ios class chain","**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`][-1]","09237a47-3d8f-4445-9397-6292b98d4ff7"]
[debug] [BaseDriver] Valid locator strategies for this request: id, name, accessibility id, xpath, class name, -ios predicate string, predicate string, -ios class chain, class chain
[debug] [WD Proxy] Matched '/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /element] to [POST http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C/element] with body: {"using":"class chain","value":"**/XCUIElementTypeSplitGroup/XCUIElementTypePopUpButton[`label == 'airplay'`]/XCUIElementTypePopover/**/XCUIElementTypeTableRow[`label BEGINSWITH 'Computer , '`][-1]"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     5.78s Get all elements bound by index for: Elements matching predicate 'label BEGINSWITH "Computer , "'
[debug] [WD Proxy] Got response with status 200: {"value":{"ELEMENT":"D398A5DE-65A3-47F7-BC33-0C4F974F8100","element-6066-11e4-a52e-4f735466cecf":"D398A5DE-65A3-47F7-BC33-0C4F974F8100"},"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C"}
[debug] [W3C (09237a47)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":"D398A5DE-65A3-47F7-BC33-0C4F974F8100","ELEMENT":"D398A5DE-65A3-47F7-BC33-0C4F974F8100"}
[HTTP] <-- POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element 200 142 ms - 137
[HTTP]
[HTTP] --> POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click
[HTTP] {"id":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC"}
[W3C (09237a47)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click] to [POST http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click] with body: {"id":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC"}
[debug] [WebDriverAgentMac] [xcodebuild] t =     7.93s Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     8.03s Click "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     8.03s     Wait for com.apple.Music to idle
[debug] [WebDriverAgentMac] [xcodebuild] t =     8.03s     Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =     8.12s     Application is configured to skip UI interruption handling
[debug] [WebDriverAgentMac] [xcodebuild] t =     8.12s     Synthesize event
[debug] [WebDriverAgentMac] [xcodebuild] t =     8.44s     Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C"}
[WD Proxy] Replacing sessionId 58834BB5-6A4A-4029-83BF-FECC885B842C with 09237a47-3d8f-4445-9397-6292b98d4ff7
[HTTP] <-- POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click 200 516 ms - 65
[HTTP]
[HTTP] --> GET /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/D398A5DE-65A3-47F7-BC33-0C4F974F8100/attribute/frame
[HTTP] {}
[W3C (09237a47)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/D398A5DE-65A3-47F7-BC33-0C4F974F8100/attribute/frame' to command name 'getAttribute'
[debug] [WD Proxy] Proxying [GET /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/D398A5DE-65A3-47F7-BC33-0C4F974F8100/attribute/frame] to [GET http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C/element/D398A5DE-65A3-47F7-BC33-0C4F974F8100/attribute/frame] with no body
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:13.928743+0100 WebDriverAgentRunner-Runner[19778:5922234] The data couldn’t be read because it isn’t in the correct format.
[debug] [WebDriverAgentMac] [xcodebuild] t =    11.45s Find the TableRow
[debug] [WebDriverAgentMac] [xcodebuild] t =    11.58s Find the "Computer , unselected" TableRow
[debug] [WD Proxy] Got response with status 200: {"value":{"y":627,"x":1403,"width":380,"height":38},"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C"}
[WD Proxy] Replacing sessionId 58834BB5-6A4A-4029-83BF-FECC885B842C with 09237a47-3d8f-4445-9397-6292b98d4ff7
[HTTP] <-- GET /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/D398A5DE-65A3-47F7-BC33-0C4F974F8100/attribute/frame 200 260 ms - 103
[HTTP]
[HTTP] --> POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click
[HTTP] {"id":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC"}
[W3C (09237a47)] Driver proxy active, passing request on via HTTP proxy
[debug] [WD Proxy] Matched '/wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click' to command name 'click'
[debug] [WD Proxy] Proxying [POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click] to [POST http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click] with body: {"id":"4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC"}
[debug] [WebDriverAgentMac] [xcodebuild] t =    13.72s Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =    13.82s Click "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =    13.82s     Wait for com.apple.Music to idle
[debug] [WebDriverAgentMac] [xcodebuild] t =    13.82s     Find the "ITID:4001" PopUpButton
[debug] [WebDriverAgentMac] [xcodebuild] t =    13.91s     Application is configured to skip UI interruption handling
[debug] [WebDriverAgentMac] [xcodebuild] t =    13.91s     Synthesize event
[debug] [WebDriverAgentMac] [xcodebuild] t =    14.23s     Wait for com.apple.Music to idle
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":"58834BB5-6A4A-4029-83BF-FECC885B842C"}
[WD Proxy] Replacing sessionId 58834BB5-6A4A-4029-83BF-FECC885B842C with 09237a47-3d8f-4445-9397-6292b98d4ff7
[HTTP] <-- POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/element/4C99D6D1-6CD8-4F6B-B22D-8BB60C057DBC/click 200 515 ms - 65
[HTTP]
[HTTP] --> POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/execute/sync
[HTTP] {"script":"macos: click","args":[{"x":1403,"y":627}]}
[debug] [W3C (09237a47)] Calling AppiumDriver.execute() with args: ["macos: click",[{"x":1403,"y":627}],"09237a47-3d8f-4445-9397-6292b98d4ff7"]
[Mac2Driver] Executing native command 'macos: click'
[debug] [WD Proxy] Proxying [POST /wda/click] to [POST http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C/wda/click] with body: {"x":1403,"y":627}
[debug] [WebDriverAgentMac] [xcodebuild] t =    16.24s Click Application 'com.apple.Music'[1403.00, 627.00]
[debug] [WebDriverAgentMac] [xcodebuild] t =    16.24s     Wait for com.apple.Music to idle
[debug] [WebDriverAgentMac] [xcodebuild] t =    16.25s     Find the Application 'com.apple.Music'
[debug] [WebDriverAgentMac] [xcodebuild] t =    16.36s     Application is configured to skip UI interruption handling
[debug] [WebDriverAgentMac] [xcodebuild] t =    16.36s     Synthesize event
[debug] [WebDriverAgentMac] [xcodebuild] t =    16.36s         Find the Application 'com.apple.Music'
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:18.936164+0100 WebDriverAgentRunner-Runner[19778:5922234] *** Assertion failure in -[XCPointerEventPath moveMouseToPoint:atOffset:duration:], XCSynthesizedEventRecord.m:319
[WD Proxy] Got response with status 500: {"value":{"error":"unknown error","message":"Invalid parameter not satisfying: point.x != INFINITY && point.y != INFINITY","traceback":"(\n\t0   CoreFoundation                      0x00007fff2dc7fb57 __exceptionPreprocess + 250\n\t1   libobjc.A.dylib                     0x00007fff66acb5bf objc_exception_throw + 48\n\t2   CoreFoundation                      0x00007fff2dca8d08 +[NSException raise:format:arguments:] + 88\n\t3   Foundation                          0x00007fff3039ae9d -[NSAssertionHandler handleFailureInMethod:object:file:lineNumber:description:] + 191\n\t4   XCTest                              0x0000000108c090b7 -[XCPointerEventPath moveMouseToPoint:atOffset:duration:] + 469\n\t5   XCTest                              0x0000000108bee376 XCUIClickEvent + 135\n\t6   XCTest                              0x0000000108c9b7c9 __50-[XCUICoordinate(XCUICoordinateMouseEvents) click]_block_invoke + 164\n\t7   XCTest                              0x0000000108ccc7b1 __137+[XCUIElement(XCUIElementEventSynthesis...
[debug] [W3C] Matched W3C error code 'unknown error' to UnknownError
[debug] [W3C (09237a47)] Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: Invalid parameter not satisfying: point.x != INFINITY && point.y != INFINITY
[debug] [W3C (09237a47)]     at errorFromW3CJsonCode (/Users/lmikkelsen/dev/appium/node_modules/appium-base-driver/lib/protocol/errors.js:780:25)
[debug] [W3C (09237a47)]     at ProxyRequestError.getActualError (/Users/lmikkelsen/dev/appium/node_modules/appium-base-driver/lib/protocol/errors.js:663:14)
[debug] [W3C (09237a47)]     at WDAMacProxy.command (/Users/lmikkelsen/dev/appium/node_modules/appium-base-driver/lib/jsonwp-proxy/proxy.js:273:19)
[debug] [W3C (09237a47)]     at processTicksAndRejections (node:internal/process/task_queues:93:5)
[debug] [W3C (09237a47)]     at Mac2Driver.macosClick (/Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/lib/commands/gestures.js:54:10)
[debug] [W3C (09237a47)]     at Mac2Driver.executeMacosCommand (/Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/lib/commands/execute.js:43:10)
[debug] [W3C (09237a47)]     at Mac2Driver.execute (/Users/lmikkelsen/dev/appium/node_modules/appium-mac2-driver/lib/commands/execute.js:33:12)
[HTTP] <-- POST /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7/execute/sync 500 258 ms - 1229
[HTTP]
[HTTP] --> DELETE /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7
[HTTP] {}
[debug] [W3C (09237a47)] Calling AppiumDriver.deleteSession() with args: ["09237a47-3d8f-4445-9397-6292b98d4ff7"]
[debug] [BaseDriver] Event 'quitSessionRequested' logged at 1607937738972 (10:22:18 GMT+0100 (Central European Standard Time))
[Appium] Removing session 09237a47-3d8f-4445-9397-6292b98d4ff7 from our master session list
[debug] [WD Proxy] Matched '/session/58834BB5-6A4A-4029-83BF-FECC885B842C' to command name 'deleteSession'
[debug] [WD Proxy] Proxying [DELETE /session/58834BB5-6A4A-4029-83BF-FECC885B842C] to [DELETE http://127.0.0.1:10100/session/58834BB5-6A4A-4029-83BF-FECC885B842C] with no body
[debug] [WebDriverAgentMac] [xcodebuild] 2020-12-14 10:22:18.973639+0100 WebDriverAgentRunner-Runner[19778:5922234] The data couldn’t be read because it isn’t in the correct format.
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":null}
[debug] [BaseDriver] Event 'quitSessionFinished' logged at 1607937738974 (10:22:18 GMT+0100 (Central European Standard Time))
[debug] [W3C (09237a47)] Received response: null
[debug] [W3C (09237a47)] But deleting session, so not returning
[debug] [W3C (09237a47)] Responding to client with driver.deleteSession() result: null
[HTTP] <-- DELETE /wd/hub/session/09237a47-3d8f-4445-9397-6292b98d4ff7 200 4 ms - 14
[HTTP]
mykola-mokhnach commented 3 years ago

https://github.com/appium/appium-mac2-driver/pull/32 should fix clicking by absolute coordinates

lassebm commented 3 years ago

@mykola-mokhnach Thanks for the quick fix! Although the fix seems to work, the popover is dismissed just after the mouse cursor has moved into click position. Can I ask if you're able to replicate this issue with popovers at your end? Your help is appreciated.

mykola-mokhnach commented 3 years ago

Sorry, I don't have time for that

lassebm commented 3 years ago

@mykola-mokhnach No problem. Thanks for your help and fixes. Closing.