feat: add retry once with reconnection to the remote debugger to reduce no response condtion error #2334

KazuCocoa · 2024-02-28T09:27:22Z

I observed that a remote debugger session could have no response situation by the web inspector. I assumed re-connection and retry again could help for this since the condition did not keep to the next session.

This PR confirmed that when driver.find_element :xpath, "//*" got a timeout in the atom execution, reconnected, and re-sent the same request again to the same WebView context; it returned the expected response. My test was a real device. For the simulator, maybe it won't reach this retrial. I haven't observed this case in simulators so far.

This behavior is kind of frequently occurs in iOS 17 x Safari 17. Thus, I wondered if we could do this trick as a workaround. Hopefully, Apple will improve this case, but for now, this retrial at least helps our mobile safari/webview automation for iOS 17.

Technically, maybe this can be only for iOS 17/safari 17. iOS 16/Safari 16 is stabler than this iOS/safari 17 case, so the current expectation is iOS 16/safari 16 may not reach the retrial. (No issues exist even iOS 16 and lower reach this retry, so I haven't added version check)

Log with this retrial example. This logs is a recovery case by this PR change.

HTTP] --> POST /session/c5300bd3-0b8c-462c-8905-a030ee1d7928/element
[HTTP] {"using":"xpath","value":"//*"}
[XCUITestDriver@fe18 (c5300bd3)] Calling AppiumDriver.findElement() with args: ["xpath","//*","c5300bd3-0b8c-462c-8905-a030ee1d7928"]
[XCUITestDriver@fe18 (c5300bd3)] Executing command 'findElement'
[XCUITestDriver@fe18 (c5300bd3)] Valid locator strategies for this request: xpath, id, name, class name, -ios predicate string, -ios class chain, accessibility id, css selector
[XCUITestDriver@fe18 (c5300bd3)] Waiting up to 0 ms for condition
[RemoteDebugger] Executing atom 'find_element_fragment' with 'args=["xpath","//*",null]; frames='
[RemoteDebugger] Executing 'find_element_fragment' atom in default context
[RemoteDebugger] Sending javascript command: '(function(){return (function(){var ba=this||sel...'
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1', target 'page-45' (id: 90): 'Runtime.evaluate'
[RemoteDebugger] Page changed: {
[RemoteDebugger]   "1": {
[RemoteDebugger]     "WIRTitleKey": "",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "about:blank",
[RemoteDebugger]     "WIRPageIdentifierKey": 1,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022",
[RemoteDebugger]     "WIRConnectionIdentifierKey": "91a8261a-898b-4786-be68-2d31a99b9567"
[RemoteDebugger]   },
[RemoteDebugger]   "2": {
[RemoteDebugger]     "WIRTitleKey": "Grammarly for Safari — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 2,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   },
[RemoteDebugger]   "3": {
[RemoteDebugger]     "WIRTitleKey": "1Password 7 — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 3,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   }
[RemoteDebugger] }
[XCUITestDriver@fe18 (c5300bd3)] Remote debugger notified us of a new page listing: {"appIdKey":"4022","pageArray":[{"id":1,"title":"","url":"about:blank","isKey":true},{"id":2,"title":"Grammarly for Safari — Extension Background Content","url":"safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html","isKey":false},{"id":3,"title":"1Password 7 — Extension Background Content","url":"safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html","isKey":false}]}
[XCUITestDriver@fe18 (c5300bd3)] Checking if page needs to load
[XCUITestDriver@fe18 (c5300bd3)] New page listing is same as old, doing nothing
[XCUITestDriver@fe18 (c5300bd3)] Redirected from 'https://www.rakuten.co.jp/' to 'about:blank'
[RemoteDebugger] Received page change notice for app 'PID:4022' but the listing has not changed. Ignoring.
[RemoteDebugger] Page changed: {
[RemoteDebugger]   "1": {
[RemoteDebugger]     "WIRTitleKey": "",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "about:blank",
[RemoteDebugger]     "WIRPageIdentifierKey": 1,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022",
[RemoteDebugger]     "WIRConnectionIdentifierKey": "91a8261a-898b-4786-be68-2d31a99b9567"
[RemoteDebugger]   },
[RemoteDebugger]   "2": {
[RemoteDebugger]     "WIRTitleKey": "Grammarly for Safari — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 2,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   },
[RemoteDebugger]   "3": {
[RemoteDebugger]     "WIRTitleKey": "1Password 7 — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 3,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   }
[RemoteDebugger] }
[XCUITestDriver@fe18 (c5300bd3)] Remote debugger notified us of a new page listing: {"appIdKey":"4022","pageArray":[{"id":1,"title":"","url":"about:blank","isKey":true},{"id":2,"title":"Grammarly for Safari — Extension Background Content","url":"safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html","isKey":false},{"id":3,"title":"1Password 7 — Extension Background Content","url":"safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html","isKey":false}]}
[XCUITestDriver@fe18 (c5300bd3)] Checking if page needs to load
[XCUITestDriver@fe18 (c5300bd3)] New page listing is same as old, doing nothing
[RemoteDebugger] Page changed: {
[RemoteDebugger]   "1": {
[RemoteDebugger]     "WIRTitleKey": "楽天市場",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "https://www.rakuten.co.jp/",
[RemoteDebugger]     "WIRPageIdentifierKey": 1,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022",
[RemoteDebugger]     "WIRConnectionIdentifierKey": "91a8261a-898b-4786-be68-2d31a99b9567"
[RemoteDebugger]   },
[RemoteDebugger]   "2": {
[RemoteDebugger]     "WIRTitleKey": "Grammarly for Safari — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 2,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   },
[RemoteDebugger]   "3": {
[RemoteDebugger]     "WIRTitleKey": "1Password 7 — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 3,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   }
[RemoteDebugger] }
[XCUITestDriver@fe18 (c5300bd3)] Remote debugger notified us of a new page listing: {"appIdKey":"4022","pageArray":[{"id":1,"title":"楽天市場","url":"https://www.rakuten.co.jp/","isKey":true},{"id":2,"title":"Grammarly for Safari — Extension Background Content","url":"safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html","isKey":false},{"id":3,"title":"1Password 7 — Extension Background Content","url":"safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html","isKey":false}]}
[XCUITestDriver@fe18 (c5300bd3)] Checking if page needs to load
[XCUITestDriver@fe18 (c5300bd3)] New page listing is same as old, doing nothing
[XCUITestDriver@fe18 (c5300bd3)] Redirected from 'about:blank' to 'https://www.rakuten.co.jp/'
[XCUITestDriver@fe18 (c5300bd3)] Matched '/alert/text' to command name 'getAlertText'
[XCUITestDriver@fe18 (c5300bd3)] Proxying [GET /alert/text] to [GET http://192.168.5.3:8100/session/0623AFF5-4B67-489F-B6F8-0ACD98F7DF6C/alert/text] with no body
[XCUITestDriver@fe18 (c5300bd3)] connect ECONNREFUSED 192.168.5.3:8100
[XCUITestDriver@fe18 (c5300bd3)] Matched '/alert/text' to command name 'getAlertText'
[XCUITestDriver@fe18 (c5300bd3)] Proxying [GET /alert/text] to [GET http://192.168.5.3:8100/session/0623AFF5-4B67-489F-B6F8-0ACD98F7DF6C/alert/text] with no body
[XCUITestDriver@fe18 (c5300bd3)] connect ECONNREFUSED 192.168.5.3:8100
[XCUITestDriver@fe18 (c5300bd3)] Matched '/alert/text' to command name 'getAlertText'
[XCUITestDriver@fe18 (c5300bd3)] Proxying [GET /alert/text] to [GET http://192.168.5.3:8100/session/0623AFF5-4B67-489F-B6F8-0ACD98F7DF6C/alert/text] with no body
[XCUITestDriver@fe18 (c5300bd3)] connect ECONNREFUSED 192.168.5.3:8100
[XCUITestDriver@fe18 (c5300bd3)] Matched '/alert/text' to command name 'getAlertText'
[XCUITestDriver@fe18 (c5300bd3)] Proxying [GET /alert/text] to [GET http://192.168.5.3:8100/session/0623AFF5-4B67-489F-B6F8-0ACD98F7DF6C/alert/text] with no body
[XCUITestDriver@fe18 (c5300bd3)] connect ECONNREFUSED 192.168.5.3:8100
[RemoteDebugger] Received page change notice for app 'PID:4022' but the listing has not changed. Ignoring.
[RemoteDebugger] Page changed: {
[RemoteDebugger]   "1": {
[RemoteDebugger]     "WIRTitleKey": "楽天市場",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "https://www.rakuten.co.jp/",
[RemoteDebugger]     "WIRPageIdentifierKey": 1,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022",
[RemoteDebugger]     "WIRConnectionIdentifierKey": "91a8261a-898b-4786-be68-2d31a99b9567"
[RemoteDebugger]   },
[RemoteDebugger]   "2": {
[RemoteDebugger]     "WIRTitleKey": "Grammarly for Safari — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 2,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   },
[RemoteDebugger]   "3": {
[RemoteDebugger]     "WIRTitleKey": "1Password 7 — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 3,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   }
[RemoteDebugger] }
[XCUITestDriver@fe18 (c5300bd3)] Remote debugger notified us of a new page listing: {"appIdKey":"4022","pageArray":[{"id":1,"title":"楽天市場","url":"https://www.rakuten.co.jp/","isKey":true},{"id":2,"title":"Grammarly for Safari — Extension Background Content","url":"safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html","isKey":false},{"id":3,"title":"1Password 7 — Extension Background Content","url":"safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html","isKey":false}]}
[XCUITestDriver@fe18 (c5300bd3)] Checking if page needs to load
...
[XCUITestDriver@fe18 (c5300bd3)] Proxying [GET /alert/text] to [GET http://192.168.5.3:8100/session/0623AFF5-4B67-489F-B6F8-0ACD98F7DF6C/alert/text] with no body
[XCUITestDriver@fe18 (c5300bd3)] connect ECONNREFUSED 192.168.5.3:8100
[XCUITestDriver@fe18 (c5300bd3)] Error received while executing atom: operation timed out
[XCUITestDriver@fe18 (c5300bd3)] Retry to send the same request after re-connecting to the remote debugger.
[RemoteDebugger] Disconnecting from remote debugger
[RemoteDebugger] Cleaning up listeners
[RemoteDebugger] Remote Debugger version 11.0.2
[RemoteDebugger] useNewSafari --> false
[RemoteDebugger] Checking which communication style to use (Safari on platform version '17.0')
[RemoteDebugger] Platform version equal or higher than '12.2': true
[RemoteDebugger] Setting communication protocol: using Target-based communication
[RemoteDebugger] Sending connection key request
[RemoteDebugger] Sending '_rpc_reportIdentifier:' message (id: 0): 'setConnectionKey'
[XCUITestDriver@fe18 (c5300bd3)] Attempting to set context to 'WEBVIEW_4022.1' from 'NATIVE_APP'
[RemoteDebugger] Selecting page '1' on app 'PID:4022' and forwarding socket setup
[RemoteDebugger] Sending '_rpc_forwardIndicateWebView:' message to app 'PID:4022', page '1' (id: 2): 'indicateWebView'
[RemoteDebugger] Sending to Web Inspector took 22ms
[RemoteDebugger] Sending to Web Inspector took 3ms
[RemoteDebugger] Sending '_rpc_forwardIndicateWebView:' message to app 'PID:4022', page '1' (id: 4): 'indicateWebView'
[RemoteDebugger] Sending to Web Inspector took 1ms
[RemoteDebugger] Sending '_rpc_forwardSocketSetup:' message to app 'PID:4022', page '1' (id: 6): 'setSenderKey'
[RemoteDebugger] Sending to Web Inspector took 1ms
[RemoteDebugger] Sender key set
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 8): 'Inspector.enable'
[RemoteDebugger] Sending to Web Inspector took 1ms
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 10): 'Page.enable'
[RemoteDebugger] Sending to Web Inspector took 1ms
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 12): 'Network.enable'
[RemoteDebugger] Sending to Web Inspector took 1ms
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 14): 'Runtime.enable'
[RemoteDebugger] Sending to Web Inspector took 0ms
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 16): 'Heap.enable'
[RemoteDebugger] Sending to Web Inspector took 1ms
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 18): 'Debugger.enable'
[RemoteDebugger] Sending to Web Inspector took 1ms
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 20): 'Console.enable'
[RemoteDebugger] Sending to Web Inspector took 1ms
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 22): 'Inspector.initialized'
[RemoteDebugger] Sending to Web Inspector took 0ms
[RemoteDebugger] Sending javascript command: 'document.readyState;'
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 24): 'Runtime.evaluate'
[RemoteDebugger] Received connected automation availability state: "WIRAutomationAvailabilityAvailable"
[RemoteDebugger] Received connected applications list: PID:4022
[RemoteDebugger] Received connected driver list: {}
[RemoteDebugger] Notified that new application 'PID:4079' has connected
[RemoteDebugger] Page changed: {
[RemoteDebugger]   "1": {
[RemoteDebugger]     "WIRTitleKey": "楽天市場",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "https://www.rakuten.co.jp/",
[RemoteDebugger]     "WIRPageIdentifierKey": 1,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   },
[RemoteDebugger]   "2": {
[RemoteDebugger]     "WIRTitleKey": "Grammarly for Safari — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 2,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   },
[RemoteDebugger]   "3": {
[RemoteDebugger]     "WIRTitleKey": "1Password 7 — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 3,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   }
[RemoteDebugger] }
[XCUITestDriver@fe18 (c5300bd3)] Remote debugger notified us of a new page listing: {"appIdKey":"4022","pageArray":[{"id":1,"title":"楽天市場","url":"https://www.rakuten.co.jp/","isKey":false},{"id":2,"title":"Grammarly for Safari — Extension Background Content","url":"safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html","isKey":false},{"id":3,"title":"1Password 7 — Extension Background Content","url":"safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html","isKey":false}]}
[XCUITestDriver@fe18 (c5300bd3)] We are in the middle of selecting a page, ignoring
[RemoteDebugger] Target created for app 'PID:4022' and page '1': {"targetId":"page-45","type":"page"}
[RemoteDebugger] Page changed: {
[RemoteDebugger]   "1": {
[RemoteDebugger]     "WIRTitleKey": "楽天市場",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "https://www.rakuten.co.jp/",
[RemoteDebugger]     "WIRPageIdentifierKey": 1,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022",
[RemoteDebugger]     "WIRConnectionIdentifierKey": "af6b2c0c-3703-484f-93c6-bf89983412ca"
[RemoteDebugger]   },
[RemoteDebugger]   "2": {
[RemoteDebugger]     "WIRTitleKey": "Grammarly for Safari — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 2,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   },
[RemoteDebugger]   "3": {
[RemoteDebugger]     "WIRTitleKey": "1Password 7 — Extension Background Content",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",
[RemoteDebugger]     "WIRURLKey": "safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html",
[RemoteDebugger]     "WIRPageIdentifierKey": 3,
[RemoteDebugger]     "WIRHostApplicationIdentifierKey": "PID:4022"
[RemoteDebugger]   }
[RemoteDebugger] }
[XCUITestDriver@fe18 (c5300bd3)] Remote debugger notified us of a new page listing: {"appIdKey":"4022","pageArray":[{"id":1,"title":"楽天市場","url":"https://www.rakuten.co.jp/","isKey":true},{"id":2,"title":"Grammarly for Safari — Extension Background Content","url":"safari-web-extension://9DEC5547-BBBF-4DE0-9E21-41CD62B14C23/_generated_background_page.html","isKey":false},{"id":3,"title":"1Password 7 — Extension Background Content","url":"safari-web-extension://4C42F3A6-BDB9-45F5-A91F-47CF43EFA4FD/background/background.html","isKey":false}]}
[XCUITestDriver@fe18 (c5300bd3)] We are in the middle of selecting a page, ignoring
[RemoteDebugger] Page readiness check timed out after 5000ms
[RemoteDebugger] Waiting for page readiness
[RemoteDebugger] Page load timer not a timer. Creating new timer
[RemoteDebugger] Sending javascript command: 'document.readyState;'
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1', target 'page-45' (id: 26): 'Runtime.evaluate'
[RemoteDebugger] Handling message (id: '9')
[RemoteDebugger] Handling message (id: '11')
[RemoteDebugger] Handling message (id: '13')
[RemoteDebugger] Handling message (id: '15')
[RemoteDebugger] Handling message (id: '17')
[RemoteDebugger] Handling message (id: '19')
[RemoteDebugger] Handling message (id: '21')
[RemoteDebugger] Handling message (id: '23')
[RemoteDebugger] Handling message (id: '25')
[RemoteDebugger] Setting communication protocol: using Target-based communication
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1', target 'page-45' (id: 28): 'Runtime.evaluate'
[RemoteDebugger] Received data response from send (id: 26): '"complete"'
[RemoteDebugger] Received data response from send (id: 28): '"complete"'
[RemoteDebugger] Sending to Web Inspector took 91ms
[RemoteDebugger] Sending to Web Inspector took 5150ms
[RemoteDebugger] Document readyState is 'complete'
[RemoteDebugger] Page is ready in 3.08525ms
[RemoteDebugger] Selected page after 5174ms
[RemoteDebugger] Starting to listen for JavaScript console
[RemoteDebugger] Starting to listen for network events
[RemoteDebugger] Executing atom 'find_element_fragment' with 'args=["xpath","//*",null]; frames='
[RemoteDebugger] Executing 'find_element_fragment' atom in default context
[RemoteDebugger] Sending javascript command: '(function(){return (function(){var ba=this||sel...'
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1', target 'page-45' (id: 30): 'Runtime.evaluate'
[RemoteDebugger] Received data response from send (id: 30): '"{\"status\":0,\"value\":{\"ELEMENT\":\":wdc:1709111893015\"}}"'
[RemoteDebugger] Sending to Web Inspector took 188ms
[RemoteDebugger] Received result for atom 'find_element_fragment' execution: {"ELEMENT":":wdc:1709111893015"}
[XCUITestDriver@fe18 (c5300bd3)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":":wdc:1709111893015","ELEMENT":":wdc:1709111893015"}
[HTTP] <-- POST /session/c5300bd3-0b8c-462c-8905-a030ee1d7928/element 200 125641 ms - 101
[HTTP]

mykola-mokhnach · 2024-02-28T13:29:41Z

I believe this approach could be improved.

Obviously the original issue lies somewhere in the remote debugger client implementation, and prevents us from getting a proper response to Runtime.evaluate requests (RD simply does not respond). I believe this might be happening because we don't respect some important event after which such request could be send to a page. Maybe, it is just a classic race condition.

For example:

[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1' (id: 24): 'Runtime.evaluate'
[RemoteDebugger] Page readiness check timed out after 5000ms

and then we never see any response to the request identified by 24, which means it might be just stuck somewhere inside RD internals since we did not send it in time or did not send it with correct arguments.

What we could try now:

Track RD interaction on iOS 17 to make sure we properly mimic what Safari debugger does
Apply a dumb, but still effective technique by sending the page readiness request periodically and monitor when we actually receive a response to it

KazuCocoa · 2024-02-28T17:23:23Z

Let me dig into the response message tonight.

After:

[XCUITestDriver@fe18 (c5300bd3)] Retry to send the same request after re-connecting to the remote debugger.
[RemoteDebugger] Disconnecting from remote debugger
[RemoteDebugger] Cleaning up listeners
[RemoteDebugger] Remote Debugger version 11.0.2

was after re-connected one. So the no response was for

[RemoteDebugger] Executing 'find_element_fragment' atom in default context
[RemoteDebugger] Sending javascript command: '(function(){return (function(){var ba=this||sel...'
[RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:4022', page '1', target 'page-45' (id: 90): 'Runtime.evaluate'
[RemoteDebugger] Page changed: {
[RemoteDebugger]   "1": {
[RemoteDebugger]     "WIRTitleKey": "",
[RemoteDebugger]     "WIRTypeKey": "WIRTypeWebPage",

Before the
https://gist.github.com/KazuCocoa/692859d44d9608f028c6af85eda29636 is the full appium server log. [RemoteDebugger] Disconnecting from remote debugger is by this pr change.

I'll split the timeout change as another pr btw.

debugging : https://github.com/appium/appium-remote-debugger/compare/debug?expand=1

KazuCocoa added 3 commits February 27, 2024 01:28

retry with reconnection

05432f9

recovery with reconnection

398744a

add webviewAtomWaitTimeout

26702b8

KazuCocoa changed the title ~~fix: add retry once with reconnection to the remote debugger for no response condtion~~ feat: add webviewAtomWaitTimeout and retry once with reconnection to the remote debugger for no response condtion Feb 28, 2024

fix lint

9bac2a5

KazuCocoa marked this pull request as ready for review February 28, 2024 09:53

KazuCocoa requested review from mykola-mokhnach and jlipps February 28, 2024 09:54

KazuCocoa added 2 commits February 28, 2024 01:57

>0

77d985e

correct docs

050c5fa

KazuCocoa changed the title ~~feat: add webviewAtomWaitTimeout and retry once with reconnection to the remote debugger for no response condtion~~ feat: add webviewAtomWaitTimeout and retry once with reconnection to the remote debugger to reduce no response condtion error Feb 28, 2024

KazuCocoa marked this pull request as draft February 28, 2024 17:23

KazuCocoa mentioned this pull request Feb 28, 2024

feat: add webviewAtomWaitTimeout to control timeout for the atom execution #2335

Merged

Merge branch 'master' into webview-retry-with-reconnect

10723c2

KazuCocoa changed the title ~~feat: add webviewAtomWaitTimeout and retry once with reconnection to the remote debugger to reduce no response condtion error~~ feat: add retry once with reconnection to the remote debugger to reduce no response condtion error Feb 29, 2024

KazuCocoa added 3 commits March 7, 2024 09:58

Merge branch 'master' into webview-retry-with-reconnect

48f0d58

Merge branch 'master' into webview-retry-with-reconnect

c64d0bd

Merge branch 'master' into webview-retry-with-reconnect

094a1a4

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: add retry once with reconnection to the remote debugger to reduce no response condtion error #2334

feat: add retry once with reconnection to the remote debugger to reduce no response condtion error #2334

KazuCocoa commented Feb 28, 2024 •

edited

mykola-mokhnach commented Feb 28, 2024

KazuCocoa commented Feb 28, 2024 •

edited

feat: add retry once with reconnection to the remote debugger to reduce no response condtion error #2334

Are you sure you want to change the base?

feat: add retry once with reconnection to the remote debugger to reduce no response condtion error #2334

Conversation

KazuCocoa commented Feb 28, 2024 • edited

mykola-mokhnach commented Feb 28, 2024

KazuCocoa commented Feb 28, 2024 • edited

KazuCocoa commented Feb 28, 2024 •

edited

KazuCocoa commented Feb 28, 2024 •

edited