webdriverio icon indicating copy to clipboard operation
webdriverio copied to clipboard

[🐛 Bug]: [appium-service] Running Appium WDIO spec from VS Code debugger is rarely working (extremely flaky)

Open AlexZagriychuk opened this issue 2 years ago • 11 comments

Have you read the Contributing Guidelines on issues?

WebdriverIO Version

8.31.1

Node.js Version

v20.9.0

Mode

WDIO Testrunner

Which capabilities are you using?

No response

What happened?

  • Running the WDIO Appium spec from VS Code debugger is extremely flaky. The majority of times it fails
  • Triggering debugging from the terminal npm run wdio-ios works without issues (tried multiple times in the row)

What is your expected behavior?

When I run WDIO Appium spec from VS Code Run and Debug extension it should work without errors (just like running from the terminal npm run wdio-ios works without errors)

How to reproduce the bug.

Steps to reproduce:

  • Pull the code from: https://github.com/AlexZagriychuk/appium-service-error
  • npm i
  • In VSCode add a breakpoint in the /test/specs/test.e2e.js on the line 5, and keep this file as active
  • Open the VS Code "Run and debug" extension, select "run select spec (iOS)" config (https://webdriver.io/docs/debugging/)
  • Run this spec from VS Code debugger multiple times in the row

There are a few problems:

Problem 1 (the main one). Running the WDIO Appium spec from VS Code debugger is extremely flaky. The majority of times it fails with the following console output:

{USER}@{USER} appium-service-error %  cd /Users/{USER}/dev/appium-service-bug/appium-service-error ; /usr/b
in/env 'NODE_OPTIONS= --require "/Applications/Visual Studio Code.app/Contents/Resources/app/extensions/ms-vscode.js-debug/src/bootloader.js"
--inspect-publish-uid=http' 'VSCODE_INSPECTOR_OPTIONS=:::{"inspectorIpc":"/var/folders/sm/swqb23fd0jv0s33zs257l0sc0000gp/T/node-cdp.22312-7a188
243-1122.sock","deferredMode":false,"waitForDebugger":"","execPath":"/Users/{USER}/.nvm/versions/node/v20.9.0/bin/node","onlyEntryp
oint":false,"autoAttachMode":"always","fileCallback":"/var/folders/sm/swqb23fd0jv0s33zs257l0sc0000gp/T/node-debug-callback-8c5b8ce04287aa37"}'
/Users/{USER}/.nvm/versions/node/v20.9.0/bin/node ./node_modules/@wdio/cli/bin/wdio.js wdio.ios.conf.js --spec /Users/alexzagriychu
k-mbp/dev/appium-service-bug/appium-service-error/test/specs/test.e2e.js
Debugger attached.

Execution of 1 workers started at 2024-02-13T02:54:24.288Z

2024-02-13T02:54:24.321Z INFO @wdio/cli:launcher: Run onPrepare hook
2024-02-13T02:54:24.322Z INFO @wdio/appium-service: Will spawn Appium process: node /Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/appium/index.js --base-path / --relaxed-security --log ./_results_/appium.log --port 4723
2024-02-13T02:54:24.426Z ERROR @wdio/appium-service: Debugger attached.

2024-02-13T02:54:24.427Z ERROR @wdio/cli:utils: A service failed in the 'onPrepare' hook
Error: Debugger attached.

    at Socket.<anonymous> (file:///Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/@wdio/appium-service/build/launcher.js:172:28)
    at Object.onceWrapper (node:events:629:26)
    at Socket.emit (node:events:514:28)
    at Socket.emit (node:domain:488:12)
    at addChunk (node:internal/streams/readable:376:12)
    at readableAddChunk (node:internal/streams/readable:349:9)
    at Readable.push (node:internal/streams/readable:286:10)
    at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)
    at Pipe.callbackTrampoline (node:internal/async_hooks:130:17)

Continue...
2024-02-13T02:54:24.427Z INFO @wdio/cli:launcher: Run onWorkerStart hook
2024-02-13T02:54:24.428Z INFO @wdio/local-runner: Start worker 0-0 with arg: wdio.ios.conf.js,--spec,/Users/{USER}/dev/appium-service-bug/appium-service-error/test/specs/test.e2e.js
[0-0] 2024-02-13T02:54:25.964Z INFO @wdio/local-runner: Run worker command: run
[0-0] RUNNING in Safari - file:///test/specs/test.e2e.js
[0-0] 2024-02-13T02:54:26.149Z INFO webdriver: Initiate new session using the WebDriver protocol
[0-0] 2024-02-13T02:54:26.149Z INFO @wdio/utils: Connecting to existing driver at http://127.0.0.1:4723/
[0-0] 2024-02-13T02:54:26.251Z INFO webdriver: [POST] http://127.0.0.1:4723/session
[0-0] 2024-02-13T02:54:26.252Z INFO webdriver: DATA {
[0-0]   capabilities: {
[0-0]     alwaysMatch: {
[0-0]       platformName: 'iOS',
[0-0]       browserName: 'Safari',
[0-0]       'appium:deviceName': 'iPhone 14 Pro',
[0-0]       'appium:platformVersion': '16.4',
[0-0]       'appium:automationName': 'XCUITest'
[0-0]     },
[0-0]     firstMatch: [ {} ]
[0-0]   },
[0-0]   desiredCapabilities: {
[0-0]     platformName: 'iOS',
[0-0]     browserName: 'Safari',
[0-0]     'appium:deviceName': 'iPhone 14 Pro',
[0-0]     'appium:platformVersion': '16.4',
[0-0]     'appium:automationName': 'XCUITest'
[0-0]   }
[0-0] }
[0-0] 2024-02-13T02:54:26.572Z ERROR webdriver: RequestError: connect ECONNREFUSED 127.0.0.1:4723
[0-0]     at ClientRequest.<anonymous> (file:///Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/got/dist/source/core/index.js:790:107)
[0-0]     at Object.onceWrapper (node:events:629:26)
[0-0]     at ClientRequest.emit (node:events:526:35)
[0-0]     at ClientRequest.emit (node:domain:488:12)
[0-0]     at Socket.socketErrorListener (node:_http_client:495:9)
[0-0]     at Socket.emit (node:events:514:28)
[0-0]     at Socket.emit (node:domain:488:12)
[0-0]     at emitErrorNT (node:internal/streams/destroy:151:8)
[0-0]     at emitErrorCloseNT (node:internal/streams/destroy:116:3)
[0-0]     at process.processTicksAndRejections (node:internal/process/task_queues:82:21)
[0-0]     at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16)
[0-0]     at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17)
[0-0] 2024-02-13T02:54:26.572Z ERROR @wdio/runner: Error: Failed to create session.
[0-0] Unable to connect to "http://127.0.0.1:4723/", make sure browser driver is running on that address.
[0-0] It seems like the service failed to start or is rejecting any connections.
[0-0]     at startWebDriverSession (file:///Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/webdriver/build/utils.js:69:15)
[0-0]     at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[0-0]     at async WebDriver.newSession (file:///Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/webdriver/build/index.js:20:45)
[0-0]     at async remote (file:///Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/webdriverio/build/index.js:45:22)
[0-0]     at async Runner._startSession (file:///Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/@wdio/runner/build/index.js:241:29)
[0-0]     at async Runner._initSession (file:///Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/@wdio/runner/build/index.js:207:25)
[0-0]     at async Runner.run (file:///Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/@wdio/runner/build/index.js:88:19)
[0-0] FAILED in Safari - file:///test/specs/test.e2e.js
2024-02-13T02:54:26.702Z INFO @wdio/cli:launcher: Run onWorkerEnd hook
2024-02-13T02:54:26.705Z INFO @wdio/cli:launcher: Run onComplete hook

Spec Files:      0 passed, 1 failed, 1 total (100% completed) in 00:00:02

2024-02-13T02:54:26.706Z INFO @wdio/local-runner: Shutting down spawned worker
2024-02-13T02:54:26.957Z INFO @wdio/local-runner: Waiting for 0 to shut down gracefully
2024-02-13T02:54:26.958Z INFO @wdio/local-runner: shutting down
Waiting for the debugger to disconnect...

Problem 2. Even if in rare cases it actually starts and we see the debug runner paused at the breakpoint, we still see the console error (which seem to make consecutive successful execution impossible, and overall execution from the VS Code debugger extremely flaky)

Execution of 1 workers started at 2024-02-13T03:00:25.450Z

2024-02-13T03:00:25.479Z INFO @wdio/cli:launcher: Run onPrepare hook
2024-02-13T03:00:25.480Z INFO @wdio/appium-service: Will spawn Appium process: node /Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/appium/index.js --base-path / --relaxed-security --log ./_results_/appium.log --port 4723
2024-02-13T03:00:25.581Z ERROR @wdio/appium-service: Debugger attached.

2024-02-13T03:00:25.581Z ERROR @wdio/cli:utils: A service failed in the 'onPrepare' hook
Error: Debugger attached.

    at Socket.<anonymous> (file:///Users/{USER}/dev/appium-service-bug/appium-service-error/node_modules/@wdio/appium-service/build/launcher.js:172:28)
    at Object.onceWrapper (node:events:629:26)
    at Socket.emit (node:events:514:28)
    at Socket.emit (node:domain:488:12)
    at addChunk (node:internal/streams/readable:376:12)
    at readableAddChunk (node:internal/streams/readable:349:9)
    at Readable.push (node:internal/streams/readable:286:10)
    at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)
    at Pipe.callbackTrampoline (node:internal/async_hooks:130:17)

Continue...

Notes:

  • If I run npm run wdio-ios multiple times in the row I see no 1 nor 2 issue, and successfully stop at the breakpoint every time (sometimes need to execute npm run appium-kill once before running the script). So both 1 and 2 issues seem to only be present when running from the VSCode debugger
  • seems like the 1 problem flakiness rate reduces if I npm uninstall appium-uiautomator2-driver (which is not a fix, just an observation), but 2 still present every time

Relevant log output

Added above (with markdown support)

Code of Conduct

  • [X] I agree to follow this project's Code of Conduct

Is there an existing issue for this?

  • [X] I have searched the existing issues

AlexZagriychuk avatar Feb 13 '24 03:02 AlexZagriychuk

2024-02-13T02:54:24.426Z ERROR @wdio/appium-service: Debugger attached.

It seems like the Appium launcher recognises this as process error somewhere here which causes the process to exit. I think we should filter for this.

christian-bromann avatar Feb 13 '24 04:02 christian-bromann

Thanks for reporting!

We greatly appreciate any contributions that help resolve the bug. While we understand that active contributors have their own priorities, we kindly request your assistance if you rely on this bug being fixed. We encourage you to take a look at our contribution guidelines or join our friendly Discord development server, where you can ask any questions you may have. Thank you for your support, and cheers!

wdio-bot avatar Feb 13 '24 04:02 wdio-bot

I'm getting the same error every second step in my jenkins pipeline. Btw, I've noted that appium stopped to create wdio-appium log in its logpath. Node 16.19.0, wdio 8.32.2 appium 2.0.1 , latest version installed globally `

2024-02-19T15:13:07.183Z ERROR webdriver: RequestError: connect ECONNREFUSED 127.0.0.1:4723 at ClientRequest. (file:///Users/dchuchmai/src/testAutomation/node_modules/webdriver/node_modules/got/dist/source/core/index.js:790:107) at Object.onceWrapper (node:events:628:26) at ClientRequest.emit (node:events:525:35) at ClientRequest.emit (node:domain:489:12) at Socket.socketErrorListener (node:_http_client:494:9) at Socket.emit (node:events:513:28) at Socket.emit (node:domain:489:12) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1278:16) at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17)

appium service config:

.services = [ [ 'appium', { log: buildConfig.tempFolder +buildConfig.stageName+'/', logLevel:'debug', logTimestamp: true, bootstrapPort: 5310, commandTimeout: 240, args: { allowInsecure: ['adb_shell','chromedriver_autodownload'] }, noPermsCheck:true, relaxedSecurity:true, command: 'appium', host: '127.0.0.1', port: 4723, basePath:'/wd/hub', sessionOverride: true }, ], ];

`

DmytroChuchmaiBarges avatar Feb 19 '24 15:02 DmytroChuchmaiBarges

I confirm what Alex reported. Is there an easier workaround then killing appium to start a new debug run

efrenette11 avatar Apr 19 '24 12:04 efrenette11

I'm also having same issue.

vadik24 avatar May 08 '24 02:05 vadik24

Get the same issue, tried on both VScode and WebStorm, I have thought I did wrong somewhere on configurations until getting this ticket, glad to know this is project issue

ductuyen861vn avatar May 23 '24 01:05 ductuyen861vn

@AlexZagriychuk Did you have any idea to work around this or any other debuggers can do ? We want to keep going with wdio but that will be mess if only debug with log/console

TuyenPham-KMS avatar May 24 '24 09:05 TuyenPham-KMS

It seams that appium service fails to start, in the OnPrepare hook, so for the local debug I temporarily don't use it, and just manually start it. @TuyenPham-KMS I'm assuming the port stays busy for some time, after the test run finished, most likely to change some timeout like newCommandTimeout. As I see, appium service launcher uses childProcess, for running appium, though it must be the way to kill it separately or play with keepAliveTimeout

DmytroChuchmaiBarges avatar May 24 '24 09:05 DmytroChuchmaiBarges

@DmytroChuchmaiBarges Thank for help, you save my day, I drop service, start manually and it worked like charm

TuyenPham-KMS avatar May 24 '24 13:05 TuyenPham-KMS

Well, droping the autostart it's not a fix, it's just workaround. Are there any chances to get fix for that ? I'i'm facing the issue after upgrading from 8.24 to 8.38 - so for me it's a big regress.

pawlakmaly avatar May 27 '24 13:05 pawlakmaly

Having the same issue here with VS code JAvascript debug terminal. Works completely fine with zsh or bash terminals. Frustrating because it's making my scripts tough to debug.

edit:

this is a timing issue for me. When I run in debut terminal, if i set a breakpoint at the failed line in /node_modules/@wdio/appium-service/build/launcher.js:174:28 and wait a few seconds and then proceed with the appium launch, everything works. Not elegant, but it works.

bromeooo avatar Jun 04 '24 16:06 bromeooo