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

[dmitry-lomakin]

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]

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:

• AWS Console —> EC2 —> Load Balancer —> Select the load balancer —> Action —> Edit attributes
• Update the value of Idle timeout to 4000 (thats the max value).

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):

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

Grid console:

Hope this helps. Thanks

[jonnysmith1981]

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'

[hariohmprasath]

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'

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]

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]

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"],