search

aws-samples / run-selenium-tests-at-scale-using-ecs-fargate

This article talks about an approach that can help customers run integration and regression tests quicker and cheaper to improve the CI/CD process.
MIT License
32 stars 25 forks source link

webdriver: Request failed due to Error forwarding the new session Error forwarding the request null #1

Open dmitry-lomakin opened 3 years ago

dmitry-lomakin commented 3 years ago

Running tests doesn't seem to work at my machine:

dmitry.lomakin@dlomakin-mb sample-test-function % npm run test

> example@1.0.0 test /Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function
> wdio

Execution of 1 spec files started at 2021-06-30T18:30:45.095Z

2021-06-30T18:30:45.097Z INFO @wdio/cli:launcher: Run onPrepare hook
2021-06-30T18:30:45.099Z INFO @wdio/local-runner: Start worker 0-0 with arg:
[0-0] 2021-06-30T18:30:45.369Z INFO @wdio/local-runner: Run worker command: run
[0-0] RUNNING in chrome - /src/google.specs.js
[0-0] 2021-06-30T18:30:45.579Z INFO webdriverio: Initiate new session using the webdriver protocol
[0-0] 2021-06-30T18:30:45.581Z INFO webdriver: [POST] http://testi-selen-*******.eu-central-1.elb.amazonaws.com:4444/wd/hub/session
[0-0] 2021-06-30T18:30:45.581Z INFO webdriver: DATA {
  capabilities: {
    alwaysMatch: {
      browserName: 'chrome',
      'goog:loggingPrefs': [Object],
      'goog:chromeOptions': [Object]
    },
    firstMatch: [ {} ]
  },
  desiredCapabilities: {
    browserName: 'chrome',
    'goog:loggingPrefs': { browser: 'ALL' },
    'goog:chromeOptions': { args: [Array] }
  }
}
[0-0] 2021-06-30T18:31:04.160Z WARN webdriver: Request failed due to Error forwarding the new session Error forwarding the request null
[0-0] 2021-06-30T18:31:04.160Z INFO webdriver: Retrying 1/3
2021-06-30T18:31:04.161Z INFO webdriver: [POST] http://testi-selen-*******.eu-central-1.elb.amazonaws.com:4444/wd/hub/session
[0-0] 2021-06-30T18:31:04.161Z INFO webdriver: DATA {
  capabilities: {
    alwaysMatch: {
      browserName: 'chrome',
      'goog:loggingPrefs': [Object],
      'goog:chromeOptions': [Object]
    },
    firstMatch: [ {} ]
  },
  desiredCapabilities: {
    browserName: 'chrome',
    'goog:loggingPrefs': { browser: 'ALL' },
    'goog:chromeOptions': { args: [Array] }
  }
}
[0-0] 2021-06-30T18:31:04.223Z WARN webdriver: Request failed due to Error forwarding the new session Error forwarding the request null
[0-0] 2021-06-30T18:31:04.223Z INFO webdriver: Retrying 2/3
2021-06-30T18:31:04.223Z INFO webdriver: [POST] http://testi-selen-*******.eu-central-1.elb.amazonaws.com:4444/wd/hub/session
[0-0] 2021-06-30T18:31:04.223Z INFO webdriver: DATA {
  capabilities: {
    alwaysMatch: {
      browserName: 'chrome',
      'goog:loggingPrefs': [Object],
      'goog:chromeOptions': [Object]
    },
    firstMatch: [ {} ]
  },
  desiredCapabilities: {
    browserName: 'chrome',
    'goog:loggingPrefs': { browser: 'ALL' },
    'goog:chromeOptions': { args: [Array] }
  }
}
[0-0] 2021-06-30T18:31:04.285Z WARN webdriver: Request failed due to Error forwarding the new session Error forwarding the request null
[0-0] 2021-06-30T18:31:04.286Z INFO webdriver: Retrying 3/3
2021-06-30T18:31:04.286Z INFO webdriver: [POST] http://testi-selen-*******.eu-central-1.elb.amazonaws.com:4444/wd/hub/session
[0-0] 2021-06-30T18:31:04.286Z INFO webdriver: DATA {
  capabilities: {
    alwaysMatch: {
      browserName: 'chrome',
      'goog:loggingPrefs': [Object],
      'goog:chromeOptions': [Object]
    },
    firstMatch: [ {} ]
  },
  desiredCapabilities: {
    browserName: 'chrome',
    'goog:loggingPrefs': { browser: 'ALL' },
    'goog:chromeOptions': { args: [Array] }
  }
}
[0-0] 2021-06-30T18:31:04.349Z ERROR webdriver: Request failed due to unknown error: Error forwarding the new session Error forwarding the request null
    at getErrorFromResponseBody (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/webdriver/build/utils.js:121:10)
    at Request._callback (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/webdriver/build/request.js:121:64)
    at Request.self.callback (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/request/request.js:185:22)
    at Request.emit (events.js:314:20)
    at Request.EventEmitter.emit (domain.js:483:12)
    at Request.<anonymous> (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/request/request.js:1154:10)
    at Request.emit (events.js:314:20)
    at Request.EventEmitter.emit (domain.js:483:12)
    at IncomingMessage.<anonymous> (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/request/request.js:1076:12)
    at Object.onceWrapper (events.js:420:28)
[0-0] 2021-06-30T18:31:04.350Z ERROR webdriver: unknown error: Error forwarding the new session Error forwarding the request null
    at getErrorFromResponseBody (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/webdriver/build/utils.js:121:10)
    at Request._callback (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/webdriver/build/request.js:121:64)
    at Request.self.callback (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/request/request.js:185:22)
    at Request.emit (events.js:314:20)
    at Request.EventEmitter.emit (domain.js:483:12)
    at Request.<anonymous> (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/request/request.js:1154:10)
    at Request.emit (events.js:314:20)
    at Request.EventEmitter.emit (domain.js:483:12)
    at IncomingMessage.<anonymous> (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/request/request.js:1076:12)
    at Object.onceWrapper (events.js:420:28)
[0-0] 2021-06-30T18:31:04.351Z ERROR @wdio/runner: Error: Failed to create session.
Error forwarding the new session Error forwarding the request null
    at startWebDriverSession (/Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/node_modules/webdriver/build/utils.js:45:11)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
[0-0] Error: Failed to create session.
Error forwarding the new session Error forwarding the request null
[0-0] FAILED in chrome - /src/google.specs.js
2021-06-30T18:31:04.469Z INFO @wdio/cli:launcher: Run onComplete hook

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

2021-06-30T18:31:04.469Z INFO @wdio/local-runner: Shutting down spawned worker
2021-06-30T18:31:04.722Z INFO @wdio/local-runner: Waiting for 0 to shut down gracefully
2021-06-30T18:31:04.723Z INFO @wdio/local-runner: shutting down
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! example@1.0.0 test: `wdio`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the example@1.0.0 test script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /Users/dmitry.lomakin/Sources/scaling-test-execution/run-selenium-tests-at-scale-using-ecs-fargate/sample-test-function/.npm/_logs/2021-06-30T18_31_04_738Z-debug.log
dmitry.lomakin@dlomakin-mb sample-test-function %

Any clue on what could break?

hariohmprasath commented 3 years ago

Hi @dmitry-lomakin, I am glad you are trying this out, here are my suggestions:

S1: Are you in VPN? Sometimes I have seen this happening when using it with VPN, try disconnecting from VPN. S2: Try increasing the value of timeout_seconds attribute in AWS ALB. I modified timeout_seconds attribute in my load balancer and you can do the same by following the below steps:

After the updates, I ran 40 concurrent session of sample test case that's checked in part of the GitHub repo, in a loop and I could see at-least one session running in each of these nodes.

Test batch 1 (20 concurrent run - in view): Screen Shot 2021-06-25 at 4 34 13 PM

Test batch 2 (20 concurrent run - in view):

Screen Shot 2021-06-25 at 4 33 49 PM (2)

Grid console: PastedGraphic-1

Hope this helps. Thanks

jonnysmith1981 commented 3 years ago

This same error occurs for me too.

Not using a VPN

ALB timeout is 60 seconds. Error occurs within 5 or 6 seconds of running the test.

Using this project gives a remoteHost of 'null' image

hariohmprasath commented 3 years ago

This same error occurs for me too.

Not using a VPN

ALB timeout is 60 seconds. Error occurs within 5 or 6 seconds of running the test.

Using this project gives a remoteHost of 'null' image

Looks like the data nodes are not getting registered to master node. Ideally, when the data node starts up, it will use the below environment properties and startup commands to register itself to the master node:

env: {
      HUB_PORT_4444_TCP_ADDR: options.loadBalancer.loadBalancerDnsName,
      HUB_PORT_4444_TCP_PORT: '4444',
      NODE_MAX_INSTANCES: this.seleniumNodeMaxInstances.toString(),
      NODE_MAX_SESSION: this.seleniumNodeMaxSessions.toString(),
      SE_OPTS: '-debug',
      shm_size: '512',
  },
PRIVATE=$(curl -s http://169.254.170.2/v2/metadata | jq -r '.Containers[1].Networks[0].IPv4Addresses[0]') ; export REMOTE_HOST=\"http://$PRIVATE:5555\" ; /opt/bin/entry_point.sh

Can you check the logs of the data nodes to see for any errors?

uorbe001 commented 6 months ago

I'm getting the same errors, but seeing nothing on the logs other than the fact that the remoteHost url is null:

12:45:25.230 DEBUG [RegistrationServlet.process] - getting the following registration request  : {
  "class": "org.openqa.grid.common.RegistrationRequest",
  "configuration": {
    "browserTimeout": 200000,
    "capabilities": [
      {
        "applicationName": "",
        "browserName": "chrome",
        "maxInstances": 500,
        "platform": "LINUX",
        "platformName": "LINUX",
        "seleniumProtocol": "WebDriver",
        "server:CONFIG_UUID": "fee0fc50-c652-4615-be0e-9159f3d6199e",
        "version": "94.0.4606.61"
      }
    ],
    "custom": {
    },
    "debug": true,
    "downPollingLimit": 2,
    "enablePlatformVerification": true,
    "host": "10.0.165.168",
    "hub": "http:\u002f\u002ftestin-Selen-qidwISh9glTz-1519287742.eu-west-2.elb.amazonaws.com:4444\u002fgrid\u002fregister",
    "id": "http:\u002f\u002fnull:5555",
    "maxSession": 500,
    "nodePolling": 5000,
    "nodeStatusCheckTimeout": 5000,
    "port": 5555,
    "proxy": "org.openqa.grid.selenium.proxy.DefaultRemoteProxy",
    "register": true,
    "registerCycle": 5000,
    "remoteHost": "http:\u002f\u002fnull:5555",
    "role": "node",
    "servlets": [
    ],
    "timeout": 180,
    "unregisterIfStillDownAfter": 60000,
    "withoutServlets": [
    ]
  },
  "description": null,
  "name": null
}
12:45:25.231 DEBUG [BaseRemoteProxy.getNewInstance] - Using class org.openqa.grid.selenium.proxy.DefaultRemoteProxy
12:45:25.232 DEBUG [BaseRemoteProxy.setupTimeoutListener] - starting cleanup thread
12:45:25.233 DEBUG [BaseRemoteProxy$CleanUpThread.run] - cleanup thread starting...
12:45:25.233 INFO [DefaultGridRegistry.add] - Registered a node http://null:5555
12:45:25.233 DEBUG [RegistrationServlet.lambda$process$0] - proxy added http://null:5555
12:45:30.235 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null: Name or service not known
12:45:35.235 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null
12:45:35.235 INFO [DefaultRemoteProxy.onEvent] - Marking the node http://null:5555 as down: cannot reach the node for 2 tries
12:45:40.237 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null: Name or service not known
12:45:45.238 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null
12:45:50.240 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null: Name or service not known
12:45:55.241 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null
12:46:00.242 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null: Name or service not known
12:46:05.243 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null
12:46:10.244 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null: Name or service not known
12:46:15.245 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null
12:46:20.247 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null: Name or service not known
12:46:25.247 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null
12:46:30.249 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null: Name or service not known
12:46:35.249 DEBUG [DefaultRemoteProxy.isAlive] - Failed to check status of node: null
12:46:35.249 INFO [DefaultRemoteProxy.onEvent] - Unregistering the node http://null:5555 because it's been down for 60014 milliseconds
12:33:44.476 DEBUG [SelfRegisteringRemote.registerToHub] - Updated node configuration: {
  "browserTimeout": 200000,
  "capabilities": [
    {
      "applicationName": "",
      "browserName": "chrome",
      "maxInstances": 500,
      "platform": "LINUX",
      "platformName": "LINUX",
      "seleniumProtocol": "WebDriver",
      "server:CONFIG_UUID": "fee0fc50-c652-4615-be0e-9159f3d6199e",
      "version": "94.0.4606.61"
    }
  ],
  "custom": {
  },
  "debug": true,
  "downPollingLimit": 2,
  "enablePlatformVerification": true,
  "host": "10.0.165.168",
  "hub": "http:\u002f\u002ftestin-Selen-qidwISh9glTz-1519287742.eu-west-2.elb.amazonaws.com:4444\u002fgrid\u002fregister",
  "id": "http:\u002f\u002fnull:5555",
  "maxSession": 500,
  "nodePolling": 5000,
  "nodeStatusCheckTimeout": 5000,
  "port": 5555,
  "proxy": "org.openqa.grid.selenium.proxy.DefaultRemoteProxy",
  "register": true,
  "registerCycle": 5000,
  "remoteHost": "http:\u002f\u002fnull:5555",
  "role": "node",
  "servlets": [
  ],
  "timeout": 180,
  "unregisterIfStillDownAfter": 60000,
  "withoutServlets": [
  ]
}
12:33:44.476 INFO [SelfRegisteringRemote.registerToHub] - Registering the node to the hub: http://testin-Selen-qidwISh9glTz-1519287742.eu-west-2.elb.amazonaws.com:4444/grid/register
12:33:44.486 INFO [SelfRegisteringRemote.registerToHub] - The node is registered to the hub and ready to use
12:34:54.550 DEBUG [SelfRegisteringRemote.registerToHub] - Fetching browserTimeout and timeout values from the hub before sending registration request

  To me, this suggests this line https://github.com/aws-samples/run-selenium-tests-at-scale-using-ecs-fargate/blob/main/lib/index.js#L135 is failing to read the ip address correctly and thus returning a broken host. But I haven't been able to debug it yet, I'll try to figure it out tomorrow, but if someone already knows the answer (or I'm totally misled), I'd appreciate them sharing it.

uorbe001 commented 6 months ago

Forgot to update this, but I managed to get this working by replacing the aforementioned line of code with: command: ["PRIVATE=$(curl -s $ECS_CONTAINER_METADATA_URI_V4 | jq -r '.Networks[0].IPv4Addresses[0]') ; export REMOTE_HOST=\"http://$PRIVATE:5555\" ; /opt/bin/entry_point.sh"],