WDA session stuck 20s at first try and fails, then, after retry it works #15101

uterator · 2021-02-10T21:54:28Z

The problem

At running a test, the WDA is being installed and run, the app is open on the iPhone but nothing happens about 20s.
Then, after auto-restart of the WDA session, everything works fine.

When the WDA session is stuck, I do request to the WDA using Postman, postman shows pending response until the 20s is reached, then it returns correct data.

Seems WDA is busy for 20s at first try, then, after that busy session is terminated and the new one is started as wdaStartupRetries=3, that second session works normal.

Same happens at Appium Desktop run, first time opening a connection, the Inspector is unable to load the content and the screenshot, but when I kill the session and start again, it works normally.

Environment

Appium version (or git revision) that exhibits the issue: v1.20.0
Last Appium version that did not exhibit the issue (if applicable): -
Desktop OS/version used to run Appium: Mac, iOS-14.3
Node.js version (unless using Appium.app|exe): v15.5.1
Npm or Yarn package manager: npm -v = 7.3.0
Mobile platform/version under test: iOS
Real device or emulator/simulator: device
Appium CLI or Appium.app|exe: CLI an Desktop

Details

First session logs which show the WDA stuck moment

2021-02-10 20:38:35:966 - [debug] [WD Proxy] Proxying [GET /wda/screen] to [GET http://127.0.0.1:8106/session/0E449474-55C0-42B8-BFE6-850C87F52221/wda/screen] with no body
2021-02-10 20:38:35:974 - [Xcode] 2021-02-10 20:38:35.891890+0400 WebDriverAgentRunner-Runner[9972:7631066] Getting the most recent active application (out of 1 total items)
2021-02-10 20:38:35:974 - [Xcode]
2021-02-10 20:38:35:985 - [Xcode]     t =     8.10s Get all elements bound by accessibility element for: Descendants matching type StatusBar
2021-02-10 20:38:35:985 - [Xcode]
2021-02-10 20:38:59:011 - [HTTP] --> GET /wd/hub/status
2021-02-10 20:38:59:012 - [HTTP] {}

You see time jump from 20:38:35 to 20:38:59
During that 24 seconds the app did nothing, it was on the first page.

WDA could not response to GET http://127.0.0.1:8106/session/0E449474-55C0-42B8-BFE6-850C87F52221/wda/screen

The next line was

[HTTP] --> GET /wd/hub/status

Second session logs which show the WDA responded correcly

2021-02-10 20:40:57:523 - [Xcode]
2021-02-10 20:40:57:593 - [debug] [WD Proxy] Got response with status 200: {"value":{"sessionId":"E4066E22-82A9-4EF1-963C-A5A81D19D400","capabilities":{"device":"iphone","browserName":"app","sdkVersion":"14.3","CFBundleIdentifier":"bundleId"}},"sessionId":"E4066E22-82A9-4EF1-963C-A5A81D19D400"}
2021-02-10 20:40:57:605 - [debug] [WD Proxy] Proxying [GET /wda/screen] to [GET http://127.0.0.1:8106/session/E4066E22-82A9-4EF1-963C-A5A81D19D400/wda/screen] with no body
2021-02-10 20:40:57:617 - [Xcode] 2021-02-10 20:40:57.533889+0400 WebDriverAgentRunner-Runner[9972:7631066] Getting the most recent active application (out of 1 total items)
2021-02-10 20:40:57:617 - [Xcode]
2021-02-10 20:40:57:619 - [Xcode]     t =   149.73s Get all elements bound by accessibility element for: Descendants matching type StatusBar
2021-02-10 20:40:57:619 - [Xcode]     t =   149.74s     Requesting snapshot of accessibility hierarchy for app with pid 59
2021-02-10 20:40:57:619 - [Xcode]
2021-02-10 20:40:57:653 - [Xcode]     t =   149.77s     Find: Descendants matching type StatusBar
2021-02-10 20:40:57:653 - [Xcode]
2021-02-10 20:40:57:667 - [Xcode]     t =   149.78s Checking existence of `StatusBar`
2021-02-10 20:40:57:667 - [Xcode]

You see there is no time jump
the WDA was able to response to GET http://127.0.0.1:8106/session/E4066E22-82A9-4EF1-963C-A5A81D19D400/wda/screen

The return was

[Xcode] t = 149.74s Requesting snapshot of accessibility hierarchy for app with pid 59

UPDATE
When the WDA is stuck at the first run, the app isn't hang, I can click and work on it.

Links to Appium logs

first_WDA_stuck.log
fist_page_ios_stuck_SHOW_IOS_LOG
fist_page_ios_stuck_SHOW_IOS_LOG__SHOW_XCODE_LOG

The text was updated successfully, but these errors were encountered:

KazuCocoa · 2021-02-10T23:44:18Z

Could you give us with showIOSLog capability log?

If the first /screen command had something error, probably https://github.com/appium/WebDriverAgent/blob/a1824895274c60798b506f31054e4ce1e0400c71/WebDriverAgentLib/Utilities/FBScreen.m#L23-L41 had an issue.

uterator · 2021-02-11T06:58:18Z

Thank you for the quick response @KazuCocoa

Please find the logs with showIOSLog and logs with showIOSLog+showXcodeLog added into the "Links to Appium logs" section of the description.

KazuCocoa · 2021-02-11T07:49:23Z

Thanks.
Hm... like below logs were there. I just picked some timeout or waiting for stuff by testmanagerd

2021-02-11 09:39:19:419 - [IOSDeviceLog] Feb 11 09:39:19 my-iPhone testmanagerd[7009] <Notice>: <XCTestSession: 0x101089450> pid 10075 com.apple.springbrd 59 8
2021-02-11 09:39:19:419 - [IOSDeviceLog] Feb 11 09:39:19 my-iPhone testmanagerd[7009] <Notice>: <private> delegate handled application update
2021-02-11 09:39:19:419 - [IOSDeviceLog] Feb 11 09:39:19 my-iPhone testmanagerd[7009] <Notice>: Test session <XCTestSession: 0x101089450> pid 10075 requested endpoint for process with pid 59, preferredBackendPath /Developer/Library/PrivateFrameworks/XCTAutomationSupport.framework
2021-02-11 09:39:19:419 - [IOSDeviceLog] Feb 11 09:39:19 my-iPhone testmanagerd[7009] <Notice>: Recorded pending request for target session with pid 59, timeout 60.0.

...

2021-02-11 09:40:19:456 - [IOSDeviceLog] Feb 11 09:40:19 my-iPhone testmanagerd(XCTAutomationSupport)[7009] <Notice>: XCTPerformOnMainRunLoop[not MT]: about to CFRunLoopPerform
2021-02-11 09:40:19:456 - [IOSDeviceLog] Feb 11 09:40:19 my-iPhone testmanagerd(XCTAutomationSupport)[7009] <Notice>: XCTPerformOnMainRunLoop[not MT]: waiting with 30.00s responsiveness timeout
2021-02-11 09:40:19:457 - [IOSDeviceLog] Feb 11 09:40:19 my-iPhone testmanagerd(XCTAutomationSupport)[7009] <Notice>: XCTPerformOnMainRunLoop[MT]: inside CFRunLoopPerform

Could you try to call /screen like below?

Checkout the https://github.com/KazuCocoa/WebDriverAgent/tree/screen or apply https://github.com/appium/WebDriverAgent/compare/master...KazuCocoa:screen?expand=1 in your local
Build your WDA on the device under test
- Once your WDA runs, please open 'http://your-device-ip:8100' on a browser
Open http://your-device-ip:8100/wda/screen

Then, the URL returns the result of screen size against springboard (default home app).
I wonder if some cases like clean installing WDA has a slow response.

As a note, my devices (iPhone SE, SE 2nd x iOS 14.3 and 14.4) has no such delay so far.

mykola-mokhnach · 2021-02-11T08:15:49Z

@KazuCocoa I saw such delays when WDA was trying to access elements of FBSpringboardApplication.fb_springboard application. Not sure what exactly could cause them.

mykola-mokhnach · 2021-02-11T10:36:44Z

appium/WebDriverAgent#467 might help there

uterator · 2021-02-11T11:31:40Z

Hi @mykola-mokhnach
sorry but that change didn't help

it was tested on commit f8b2aaee362fda7959a0f7812838211d8dc3217c (HEAD -> system_app, origin/system_app)

please results here system_app_f8b2aaee36.log

Hi @KazuCocoa, thanks for the suggestion, unfortunately I am getting trouble with building
after building with this command

/Applications/Xcode.app/Contents/Developer/usr/bin/xcodebuild -project WebDriverAgent.xcodeproj -scheme WebDriverAgentRunner -destination id= test

the result is


Testing failed:
	Building for iOS, but the linked framework 'CocoaAsyncSocket.framework' was built for tvOS + tvOS Simulator.
	Building for iOS, but the embedded framework 'CocoaAsyncSocket.framework' was built for iOS + iOS Simulator.
	Building for iOS, but the embedded framework 'CocoaAsyncSocket.framework' was built for iOS + iOS Simulator.
	Testing cancelled because the build failed.

The phone is iphone7, XCode 12.4 (12D4e)

mykola-mokhnach · 2021-02-11T12:30:29Z

it was tested on commit f8b2aaee362fda7959a0f7812838211d8dc3217c (HEAD -> system_app, origin/system_app)

please results here system_app_f8b2aaee36.log

Could you please say at which line in that log the delay happens? I only see two calls to /wda/screen there and they were pretty fast

mykola-mokhnach · 2021-02-11T13:17:07Z

Actually, found it. I assume the delay is caused by the test daemon, which is unable to get the snapshot of the system app and performs multiple retries to mitigate that:

2021-02-11 15:04:30:536 - [IOSDeviceLog] Feb 11 15:04:30 myphone testmanagerd(XCTAutomationSupport)[7009] : Found main window:
2021-02-11 15:04:30:536 - [IOSDeviceLog] Feb 11 15:04:30 myphone testmanagerd(XCTAutomationSupport)[7009] : XCTAS Error: Error Domain=com.apple.dt.xctest.automation-support.error Code=5 UserInfo={NSLocalizedDescription=}
2021-02-11 15:04:30:548 - [IOSDeviceLog] Feb 11 15:04:30 myphone testmanagerd(XCTAutomationSupport)[7009] : Fetching AX attributes for

I'm afraid only Apple could fix that. Also, I'm unable to reproduce the issue locally, which means it may only happen under particular circumstances.

uterator · 2021-02-11T16:02:04Z

Is there a test scenario which can help to isolate the case?
I will try to test the steps what @KazuCocoa after I fix the mentioned errors.

Is there a way to delay the "getting the snapshot of the system app", maybe that can help?

An additional information:

the first page is not big, page source xml is less than 100 lines, it loads quickly when it works.
this is the output from the Appium desktop, it if may help

[HTTP] {}
[debug] [MJSONWP (7ccf3da0)] Calling AppiumDriver.getSession() with args: ["7ccf3da0-42ab-42d9-beb3-e154ea88ed13"]
[debug] [XCUITest] Executing command 'getSession'
[HTTP] --> GET /wd/hub/session/7ccf3da0-42ab-42d9-beb3-e154ea88ed13
[HTTP] {}
[debug] [MJSONWP (7ccf3da0)] Calling AppiumDriver.getSession() with args: ["7ccf3da0-42ab-42d9-beb3-e154ea88ed13"]
[debug] [XCUITest] Executing command 'getSession'
[WD Proxy] Error: timeout of 240000ms exceeded
[WD Proxy]     at createError (/Users/user/.npm-global/lib/node_modules/appium/node_modules/axios/lib/core/createError.js:16:15)
[WD Proxy]     at RedirectableRequest.handleRequestTimeout (/Users/user/.npm-global/lib/node_modules/appium/node_modules/axios/lib/adapters/http.js:280:16)
[WD Proxy]     at Object.onceWrapper (node:events:483:26)
[WD Proxy]     at RedirectableRequest.emit (node:events:376:20)
[WD Proxy]     at ClientRequest.eventHandlers.<computed> (/Users/user/.npm-global/lib/node_modules/appium/node_modules/follow-redirects/index.js:13:24)
[WD Proxy]     at ClientRequest.emit (node:events:376:20)
[WD Proxy]     at Socket.emitRequestTimeout (node:_http_client:787:9)
[WD Proxy]     at Object.onceWrapper (node:events:482:28)
[WD Proxy]     at Socket.emit (node:events:388:22)
[WD Proxy]     at Socket._onTimeout (node:net:481:8)
[WD Proxy]     at listOnTimeout (node:internal/timers:556:17)
[WD Proxy]     at processTimers (node:internal/timers:499:7)
[debug] [MJSONWP (7ccf3da0)] Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: Could not proxy command to the remote server. Original error: timeout of 240000ms exceeded
[debug] [MJSONWP (7ccf3da0)]     at JWProxy.command (/Users/user/.npm-global/lib/node_modules/appium/node_modules/appium-base-driver/lib/jsonwp-proxy/proxy.js:275:13)
[debug] [MJSONWP (7ccf3da0)]     at runMicrotasks (<anonymous>)
[debug] [MJSONWP (7ccf3da0)]     at processTicksAndRejections (node:internal/process/task_queues:93:5)
[debug] [MJSONWP (7ccf3da0)]     at XCUITestDriver.proxyCommand (/Users/user/.npm-global/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/proxy-helper.js:96:12)
[debug] [MJSONWP (7ccf3da0)]     at XCUITestDriver.getScreenInfo (/Users/user/.npm-global/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/general.js:240:10)
[debug] [MJSONWP (7ccf3da0)]     at XCUITestDriver.getSession (/Users/user/.npm-global/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/driver.js:1226:38)
[HTTP] <-- GET /wd/hub/session/7ccf3da0-42ab-42d9-beb3-e154ea88ed13 500 60116 ms - 261
[HTTP]

the moment when Postman receives data from this request http://127.0.0.1:8100/session/F40EC766-1C89-4365-A094-E20033988869/wda/screen

on Appium desktop case, the spinner rotates endless, and server prints this output continuously one after another until I manually stop the session.

[HTTP] --> GET /wd/hub/session/7ccf3da0-42ab-42d9-beb3-e154ea88ed13
[HTTP] {}
[debug] [MJSONWP (7ccf3da0)] Calling AppiumDriver.getSession() with args: ["7ccf3da0-42ab-42d9-beb3-e154ea88ed13"]
[debug] [XCUITest] Executing command 'getSession'
[debug] [MJSONWP (7ccf3da0)] Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: Could not proxy command to the remote server. Original error: timeout of 240000ms exceeded
[debug] [MJSONWP (7ccf3da0)]     at JWProxy.command (/Users/qazone/.npm-global/lib/node_modules/appium/node_modules/appium-base-driver/lib/jsonwp-proxy/proxy.js:275:13)
[debug] [MJSONWP (7ccf3da0)]     at runMicrotasks (<anonymous>)
[debug] [MJSONWP (7ccf3da0)]     at processTicksAndRejections (node:internal/process/task_queues:93:5)
[debug] [MJSONWP (7ccf3da0)]     at XCUITestDriver.proxyCommand (/Users/qazone/.npm-global/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/proxy-helper.js:96:12)
[debug] [MJSONWP (7ccf3da0)]     at XCUITestDriver.getScreenInfo (/Users/qazone/.npm-global/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/commands/general.js:240:10)
[debug] [MJSONWP (7ccf3da0)]     at XCUITestDriver.getSession (/Users/qazone/.npm-global/lib/node_modules/appium/node_modules/appium-xcuitest-driver/lib/driver.js:1226:38)
[HTTP] <-- GET /wd/hub/session/7ccf3da0-42ab-42d9-beb3-e154ea88ed13 500 1 ms - 261

mykola-mokhnach · 2021-02-11T16:21:59Z

On top of the fact that XCTest fails to fetch the status bar data it would be interesting to know why:

GET /wd/hub/session/7ccf3da0-42ab-42d9-beb3-e154ea88ed13 endpoint is called. This endpoint is not a part of W3C protocol and should not normally be used. Something to consider for AD?
The fact that getSession endpoint also must call /wda/screen one. Yes, I understand this is used by some visual stuff, since it also requests the display scale factor and the viewport rect. But why this must be a part of getSession API and not represented as a separate extension, which could be called independently when needed?

@KazuCocoa @jlipps Maybe you have some answers?

KazuCocoa · 2021-02-11T18:41:39Z

oh, the screen branch had an old master. I've updated.

KazuCocoa · 2021-02-11T18:47:45Z

The fact that getSession endpoint also must call /wda/screen one. Yes, I understand this is used by some visual stuff, since it also requests the display scale factor and the viewport rect. But why this must be a part of getSession API and not represented as a separate extension, which could be called independently when needed?

Probably to behave as same as Android? I forget (or I do not know) about the discussion in a PR or somewhere, but probably Android also returns the same viewpoint in the session endpoint.

I agree with which could be called independently when needed?. We know have mobile context, so we can define an extension. For backward compatibility, we may add a new capability to keep viewpoint for a while. (with something error message to drop it?)

uterator · 2021-02-11T20:05:30Z

Hi @KazuCocoa,
thank for the branch fix. I was able to build the app and execute your described flow.

Result is the same, the request freezes exactly 1 minute, then returns the content.

Please see also the video recording - https://github.com/uterator/Q4erqFMx3n/blob/master/issues_15101_480.mov
It has small resolution, if enlarge you may see what is happening.

KazuCocoa · 2021-02-11T23:45:21Z

Thanks.

Hm, it seems the root cause is inside XCTest framework... The code just gets an element via it...

As #15101 (comment) , the only thing we can do in Appium side is remove /screen call from the get session info command.
For backward compatibility, we probably should consider #15101 (comment) tho.

KazuCocoa · 2021-02-12T01:39:50Z

how about appium/appium-xcuitest-driver#1278 ?
As a workaround in Appium layer, you can set includeScreenInfoInSession: false in your capabilities to avoid the /screen call. @uterator

uterator · 2021-02-12T11:41:02Z

Thanks @KazuCocoa for the commit, the results are good.

My setup is

appium-webdriveragent:master 4eed2c857b276c1667839b3afd8ca63cf58a6f46
appium-xcuitest-driver:ignore-screen e51c8d1dbe450bc1a185254468c5245050b2a2da

With includeScreenInfoInSession = false.
There is no restart of the WDA session to access elements.
The app is able to pass the first screen at the very beginning and continue the test.
The session starts, the test continues and doesn't interrupt, which is very good.
output_with_includeScreenInfoInSession_false_set.log

Without setting "includeScreenInfoInSession".
The app behaves as before, with delay and with WDA session restart before the test is able to continue.
output_without_includeScreenInfoInSession_false_set.log

Thank you very much!

KazuCocoa · 2021-02-12T23:28:49Z

The name was changed to appium:includeDeviceCapsToSessionInfo, but you can try it out with current appium@beta (as xcuitest-driver 3.37.0).
We'd like to work to the false behaviour by default, but thanks for letting us this issue.

uterator changed the title ~~WDA session stucks 20s at first try an fails, then, after retry it works~~ WDA session stucks 20s at first try and fails, then, after retry it works Feb 10, 2021

uterator changed the title ~~WDA session stucks 20s at first try and fails, then, after retry it works~~ WDA session stuck 20s at first try and fails, then, after retry it works Feb 10, 2021

KazuCocoa added the Needs Info typically non-actionable; needs author to respond label Feb 10, 2021

mykola-mokhnach added ThirdParty upstream problems XCUITest regarding xcuitest driver and removed Needs Info typically non-actionable; needs author to respond labels Feb 11, 2021

KazuCocoa mentioned this issue Feb 12, 2021

feat: add appium:includeDeviceCapsToSessionInfo to be able to ignore /screen call to WDA appium/appium-xcuitest-driver#1278

Merged

KazuCocoa closed this as completed Feb 12, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

WDA session stuck 20s at first try and fails, then, after retry it works #15101

WDA session stuck 20s at first try and fails, then, after retry it works #15101

uterator commented Feb 10, 2021 •

edited

Loading

KazuCocoa commented Feb 10, 2021

uterator commented Feb 11, 2021

KazuCocoa commented Feb 11, 2021

mykola-mokhnach commented Feb 11, 2021

mykola-mokhnach commented Feb 11, 2021

uterator commented Feb 11, 2021

mykola-mokhnach commented Feb 11, 2021 •

edited

Loading

mykola-mokhnach commented Feb 11, 2021

uterator commented Feb 11, 2021

mykola-mokhnach commented Feb 11, 2021

KazuCocoa commented Feb 11, 2021

KazuCocoa commented Feb 11, 2021

uterator commented Feb 11, 2021 •

edited

Loading

KazuCocoa commented Feb 11, 2021 •

edited

Loading

KazuCocoa commented Feb 12, 2021 •

edited

Loading

uterator commented Feb 12, 2021

KazuCocoa commented Feb 12, 2021

WDA session stuck 20s at first try and fails, then, after retry it works #15101

WDA session stuck 20s at first try and fails, then, after retry it works #15101

Comments

uterator commented Feb 10, 2021 • edited Loading

The problem

Environment

Details

First session logs which show the WDA stuck moment

Second session logs which show the WDA responded correcly

Links to Appium logs

KazuCocoa commented Feb 10, 2021

uterator commented Feb 11, 2021

KazuCocoa commented Feb 11, 2021

mykola-mokhnach commented Feb 11, 2021

mykola-mokhnach commented Feb 11, 2021

uterator commented Feb 11, 2021

mykola-mokhnach commented Feb 11, 2021 • edited Loading

mykola-mokhnach commented Feb 11, 2021

uterator commented Feb 11, 2021

mykola-mokhnach commented Feb 11, 2021

KazuCocoa commented Feb 11, 2021

KazuCocoa commented Feb 11, 2021

uterator commented Feb 11, 2021 • edited Loading

KazuCocoa commented Feb 11, 2021 • edited Loading

KazuCocoa commented Feb 12, 2021 • edited Loading

uterator commented Feb 12, 2021

KazuCocoa commented Feb 12, 2021

uterator commented Feb 10, 2021 •

edited

Loading

mykola-mokhnach commented Feb 11, 2021 •

edited

Loading

uterator commented Feb 11, 2021 •

edited

Loading

KazuCocoa commented Feb 11, 2021 •

edited

Loading

KazuCocoa commented Feb 12, 2021 •

edited

Loading