appium / appium-mac2-driver

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

POST /wda/apps/activate' cannot be proxied to Mac2 Driver #172

Open phanzy opened 1 year ago

phanzy commented 1 year ago

Getting the following on about 75% of my test runs. Let me just break down the process. 1) Start mac2 session 2) activateApp: App1 3) Do some stuff with App1 4) terminateApp: App1 5) activateApp: App2 Immediately get the following error.

[Mac2Driver] Executing extension command 'macos: activateApp' [debug] [Mac2Driver@5deb (73824429)] Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: 'POST /wda/apps/activate' cannot be proxied to Mac2 Driver server because its process is not running (probably crashed). Check the Appium log for more details [debug] [Mac2Driver@5deb (73824429)] at WDAMacProxy.command (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/node_modules/@appium/base-driver/lib/jsonwp-proxy/proxy.js:342:13) [debug] [Mac2Driver@5deb (73824429)] at processTicksAndRejections (node:internal/process/task_queues:95:5) [debug] [Mac2Driver@5deb (73824429)] at Mac2Driver.macosActivateApp (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/lib/commands/app-management.js:43:10) [debug] [Mac2Driver@5deb (73824429)] at Mac2Driver.executeMacosCommand (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/lib/commands/execute.js:54:10) [debug] [Mac2Driver@5deb (73824429)] at Mac2Driver.execute (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/lib/commands/execute.js:44:12) [HTTP] <-- POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync 500 3 ms - 1166

What else should I be doing to avoid this error?

MacOS 12.4 Appium 2.0.0-beta.43 Xcode Version 13.4.1 (13F100) Node v18.4.0

phanzy commented 1 year ago

Formatting error:

'[Mac2Driver] Executing extension command 'macos: activateApp' [debug] [Mac2Driver@5deb (73824429)] Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: 'POST /wda/apps/activate' cannot be proxied to Mac2 Driver server because its process is not running (probably crashed). Check the Appium log for more details [debug] [Mac2Driver@5deb (73824429)] at WDAMacProxy.command (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/node_modules/@appium/base-driver/lib/jsonwp-proxy/proxy.js:342:13) [debug] [Mac2Driver@5deb (73824429)] at processTicksAndRejections (node:internal/process/task_queues:95:5) [debug] [Mac2Driver@5deb (73824429)] at Mac2Driver.macosActivateApp (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/lib/commands/app-management.js:43:10) [debug] [Mac2Driver@5deb (73824429)] at Mac2Driver.executeMacosCommand (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/lib/commands/execute.js:54:10) [debug] [Mac2Driver@5deb (73824429)] at Mac2Driver.execute (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/lib/commands/execute.js:44:12) [HTTP] <-- POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync 500 3 ms - 1166'

mykola-mokhnach commented 1 year ago

Please provide logs with server logging enabled (showServerLogs cap)

phanzy commented 1 year ago

'[Mac2Driver] Executing extension command 'macos: terminateApp' [debug] [WD Proxy] Proxying [POST /wda/apps/terminate] to [POST http://127.0.0.1:10100/session/B977B737-9780-414F-88A2-4D8CE3204F64/wda/apps/terminate] with body: {"bundleId":"com.apple.systempreferences"} [debug] [WebDriverAgentMac] [xcodebuild] t = 36346.61s Terminate com.apple.systempreferences:4174 [debug] [WD Proxy] Got response with status 200: {"value":true,"sessionId":"B977B737-9780-414F-88A2-4D8CE3204F64"} [debug] [Mac2Driver@5deb (73824429)] Responding to client with driver.execute() result: true [HTTP] <-- POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync 200 1021 ms - 14 [HTTP] [debug] [WebDriverAgentMac] [xcodebuild] Test Case '-[UITestingUITests testRunner]' passed (36349.566 seconds). [debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'UITestingUITests' passed at 2022-11-17 10:18:45.331. [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 36349.566 (36349.572) seconds [debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'WebDriverAgentRunner.xctest' passed at 2022-11-17 10:18:45.331. [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 36349.566 (36349.574) seconds [debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'All tests' passed at 2022-11-17 10:18:45.333. [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 36349.566 (36349.577) seconds [debug] [WebDriverAgentMac] [xcodebuild] 2022-11-17 10:18:45.616 xcodebuild[1151:76606] [MT] IDETestOperationsObserverDebug: 36351.349 elapsed -- Testing started completed. [debug] [WebDriverAgentMac] 2022-11-17 10:18:45.616 xcodebuild[1151:76606] [MT] IDETestOperationsObserverDebug: 0.000 sec, +0.000 sec -- start [debug] [WebDriverAgentMac] 2022-11-17 10:18:45.616 xcodebuild[1151:76606] [MT] IDETestOperationsObserverDebug: 36351.349 sec, +36351.349 sec -- end [debug] [WebDriverAgentMac] [xcodebuild] Test session results, code coverage, and logs: [debug] [WebDriverAgentMac] /Users/gandalfqe/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-alwntjwlfesusudtbkocdirftdkk/Logs/Test/Test-WebDriverAgentRunner-2022.11.17_00-12-52--0500.xcresult [debug] [WebDriverAgentMac] [debug] [WebDriverAgentMac] TEST EXECUTE SUCCEEDED [debug] [WebDriverAgentMac] [xcodebuild] Testing started [WebDriverAgentMac] Mac2Driver host process has exited with code 0, signal null [HTTP] --> POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync [HTTP] {"script":"macos: appleScript","args":[{"command":"do shell script \"system_profiler SPHardwareDataType | awk '/Serial/ {print $4}'\""}]} [debug] [Mac2Driver@5deb (73824429)] Calling AppiumDriver.execute() with args: ["macos: appleScript",[{"command":"do shell script \"system_profiler SPHardwareDataType | awk '/Serial/ {print $4}'\""}],"73824429-f03b-4e97-ba83-c957b85bbfd9"] [Mac2Driver] Executing extension command 'macos: appleScript' [Mac2Driver] Running osascript with arguments: -e "do shell script \"system_profiler SPHardwareDataType | awk '/Serial/ {print \$4}'\"" [debug] [Mac2Driver@5deb (73824429)] Responding to client with driver.execute() result: "C07WG0A8G1J2\n" [HTTP] <-- POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync 200 383 ms - 26 [HTTP] [HTTP] --> POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync [HTTP] {"script":"macos: appleScript","args":[{"command":"do shell script \"system_profiler SPHardwareDataType | awk '/Serial/ {print $4}'\""}]} [debug] [Mac2Driver@5deb (73824429)] Calling AppiumDriver.execute() with args: ["macos: appleScript",[{"command":"do shell script \"system_profiler SPHardwareDataType | awk '/Serial/ {print $4}'\""}],"73824429-f03b-4e97-ba83-c957b85bbfd9"] [Mac2Driver] Executing extension command 'macos: appleScript' [Mac2Driver] Running osascript with arguments: -e "do shell script \"system_profiler SPHardwareDataType | awk '/Serial/ {print \$4}'\"" [debug] [Mac2Driver@5deb (73824429)] Responding to client with driver.execute() result: "C07WG0A8G1J2\n" [HTTP] <-- POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync 200 325 ms - 26 [HTTP] [HTTP] --> POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync [HTTP] {"script":"macos: appleScript","args":[{"command":"do shell script \"system_profiler SPHardwareDataType | awk '/Serial/ {print $4}'\""}]} [debug] [Mac2Driver@5deb (73824429)] Calling AppiumDriver.execute() with args: ["macos: appleScript",[{"command":"do shell script \"system_profiler SPHardwareDataType | awk '/Serial/ {print $4}'\""}],"73824429-f03b-4e97-ba83-c957b85bbfd9"] [Mac2Driver] Executing extension command 'macos: appleScript' [Mac2Driver] Running osascript with arguments: -e "do shell script \"system_profiler SPHardwareDataType | awk '/Serial/ {print \$4}'\"" [debug] [Mac2Driver@5deb (73824429)] Responding to client with driver.execute() result: "C07WG0A8G1J2\n" [HTTP] <-- POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync 200 434 ms - 26 [HTTP] [HTTP] --> POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync [HTTP] {"script":"macos: activateApp","args":[{"bundleId":"com.App2.mac"}]} [debug] [Mac2Driver@5deb (73824429)] Calling AppiumDriver.execute() with args: ["macos: activateApp",[{"bundleId":"com.App2.mac"}],"73824429-f03b-4e97-ba83-c957b85bbfd9"] [Mac2Driver] Executing extension command 'macos: activateApp' [debug] [Mac2Driver@5deb (73824429)] Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: 'POST /wda/apps/activate' cannot be proxied to Mac2 Driver server because its process is not running (probably crashed). Check the Appium log for more details [debug] [Mac2Driver@5deb (73824429)] at WDAMacProxy.command (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/node_modules/@appium/base-driver/lib/jsonwp-proxy/proxy.js:342:13) [debug] [Mac2Driver@5deb (73824429)] at processTicksAndRejections (node:internal/process/task_queues:95:5) [debug] [Mac2Driver@5deb (73824429)] at Mac2Driver.macosActivateApp (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/lib/commands/app-management.js:43:10) [debug] [Mac2Driver@5deb (73824429)] at Mac2Driver.executeMacosCommand (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/lib/commands/execute.js:54:10) [debug] [Mac2Driver@5deb (73824429)] at Mac2Driver.execute (/Users/gandalfqe/.appium/node_modules/appium-mac2-driver/lib/commands/execute.js:44:12) [HTTP] <-- POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync 500 3 ms - 1166'

mykola-mokhnach commented 1 year ago

'[Mac2Driver] Executing extension command 'macos: terminateApp' [debug] [WD Proxy] Proxying [POST /wda/apps/terminate] to [POST http://127.0.0.1:10100/session/B977B737-9780-414F-88A2-4D8CE3204F64/wda/apps/terminate] with body: {"bundleId":"com.apple.systempreferences"} [debug] [WebDriverAgentMac] [xcodebuild] t = 36346.61s Terminate com.apple.systempreferences:4174 [debug] [WD Proxy] Got response with status 200: {"value":true,"sessionId":"B977B737-9780-414F-88A2-4D8CE3204F64"} [debug] [Mac2Driver@5deb (73824429)] Responding to client with driver.execute() result: true [HTTP] <-- POST /session/73824429-f03b-4e97-ba83-c957b85bbfd9/execute/sync 200 1021 ms - 14 [HTTP] [debug] [WebDriverAgentMac] [xcodebuild] Test Case '-[UITestingUITests testRunner]' passed (36349.566 seconds). [debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'UITestingUITests' passed at 2022-11-17 10:18:45.331. [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 36349.566 (36349.572) seconds [debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'WebDriverAgentRunner.xctest' passed at 2022-11-17 10:18:45.331. [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 36349.566 (36349.574) seconds [debug] [WebDriverAgentMac] [xcodebuild] Test Suite 'All tests' passed at 2022-11-17 10:18:45.333. [debug] [WebDriverAgentMac] Executed 1 test, with 0 failures (0 unexpected) in 36349.566 (36349.577) seconds [debug] [WebDriverAgentMac] [xcodebuild] 2022-11-17 10:18:45.616 xcodebuild[1151:76606] [MT] IDETestOperationsObserverDebug: 36351.349 elapsed -- Testing started completed. [debug] [WebDriverAgentMac] 2022-11-17 10:18:45.616 xcodebuild[1151:76606] [MT] IDETestOperationsObserverDebug: 0.000 sec, +0.000 sec -- start [debug] [WebDriverAgentMac] 2022-11-17 10:18:45.616 xcodebuild[1151:76606] [MT] IDETestOperationsObserverDebug: 36351.349 sec, +36351.349 sec -- end [debug] [WebDriverAgentMac] [xcodebuild] Test session results, code coverage, and logs: [debug] [WebDriverAgentMac] /Users/gandalfqe/Library/Developer/Xcode/DerivedData/WebDriverAgentMac-alwntjwlfesusudtbkocdirftdkk/Logs/Test/Test-WebDriverAgentRunner-2022.11.17_00-12-52--0500.xcresult [debug] [WebDriverAgentMac] [debug] [WebDriverAgentMac] TEST EXECUTE SUCCEEDED [debug] [WebDriverAgentMac] [xcodebuild] Testing started [WebDriverAgentMac] Mac2Driver host process has exited with code 0, signal null

It seems like the test session has been terminated by xcodebuild. Try to start a new session with noReset=true as a possible workaround

phanzy commented 1 year ago

Enabling noReset doesn't seem to alleviate the issue. Getting the same Mac2Driver host process has exited with code 0, signal null

castlez commented 1 year ago

Any update on this? I'm running into it too

castlez commented 1 year ago

at least having a way of knowing that the webdriver server is dead would be good, since checking appium server status still returns a 200 even if the webdriver died

mykola-mokhnach commented 1 year ago

at least having a way of knowing that the webdriver server is dead would be good, since checking appium server status still returns a 200 even if the webdriver died

https://github.com/appium/appium-mac2-driver/pull/182 should do the trick

phanzy commented 1 year ago

@mykola-mokhnach I'm a little confused here. Would I get the status via api or appium command? If api, what would the request look like?

castlez commented 1 year ago

might be a dumb question, but , like @phanzy , am not sure how to reach this status. I tried curl http://<ip>:<port>/wd/hub/status

but i get the same response as i did before running appium driver update mac2 to update. @mykola-mokhnach did i miss a step?

thank you for helping us at least get more info via the api btw!