I/O Read timed out

[NiGhTTraX]

Meta

Images: (hub + node-chrome + node-firefox) 3.2.0
OS: Ubuntu

Setup

I'm spinning up a hub container and 1 Chrome node and 1 Firefox node and linking them via docker-compose. My tests are running in a nodejs container that has a link to the hub. I'm starting 2 of those containers, one requesting a Chrome session, one requesting a Firefox session.

This is my compose file.

Problem

One of the 2 nodejs containers reports a test timeout at random times. When running the hub container with -debug true I can see a [read] I/O error: Read timed out" error a bunch of times.

12:30:01.104 DEBUG - Connection request: [route: {}->http://172.24.0.4:5555][total kept alive: 1; route allocated: 1 of 2000; total allocated: 2 of 2000]
12:30:01.106 DEBUG - Connection leased: [id: 3][route: {}->http://172.24.0.4:5555][total kept alive: 0; route allocated: 1 of 2000; total allocated: 2 of 2000]
12:30:01.106 DEBUG - Stale connection check
12:30:01.109 DEBUG - http-outgoing-3 << "[read] I/O error: Read timed out"
12:30:01.110 DEBUG - http-outgoing-3: set socket timeout to 0
12:30:01.110 DEBUG - Executing request POST /wd/hub/session/3d09edb1-e6b1-4fa0-8f56-f2d2b0199e18/url HTTP/1.1
12:30:01.110 DEBUG - Target auth state: UNCHALLENGED
12:30:01.110 DEBUG - Proxy auth state: UNCHALLENGED
12:30:01.111 DEBUG - http-outgoing-3 >> POST /wd/hub/session/3d09edb1-e6b1-4fa0-8f56-f2d2b0199e18/url HTTP/1.1
12:30:01.111 DEBUG - http-outgoing-3 >> Connection: keep-alive
12:30:01.111 DEBUG - http-outgoing-3 >> User-Agent: webdriverio/webdriverio/4.6.2
12:30:01.111 DEBUG - http-outgoing-3 >> Host: selenium:4444
12:30:01.111 DEBUG - http-outgoing-3 >> Accept: application/json
12:30:01.111 DEBUG - http-outgoing-3 >> Content-Type: application/json; charset=UTF-8
12:30:01.112 DEBUG - http-outgoing-3 >> Content-Length: 26
12:30:01.112 DEBUG - http-outgoing-3 >> Accept-Encoding: gzip,deflate
12:30:01.112 DEBUG - http-outgoing-3 >> "POST /wd/hub/session/3d09edb1-e6b1-4fa0-8f56-f2d2b0199e18/url HTTP/1.1[\r][\n]"

[testphreak]

@NiGhTTraX I am seeing the issue as well for 3.3.1 where upon turning on debug I see http-outgoing-3 << "[read] I/O error: Read timed out"

I don't see the error with 3.0.1.

[diemol]

@NiGhTTraX,

I used a slightly modified version of your docker-compose file, see here, to check this issue.

I also see in the log when I enable the debug option this:

selenium_1            | 15:00:04.951 DEBUG - Connection request: [route: {}->http://172.18.0.3:5555][total kept alive: 1; route allocated: 1 of 2000; total allocated: 2 of 2000]
selenium_1            | 15:00:04.952 DEBUG - Connection leased: [id: 1][route: {}->http://172.18.0.3:5555][total kept alive: 0; route allocated: 1 of 2000; total allocated: 2 of 2000]
selenium_1            | 15:00:04.953 DEBUG - Stale connection check
selenium_1            | 15:00:04.963 DEBUG - http-outgoing-1 << "[read] I/O error: Read timed out"
selenium_1            | 15:00:04.963 DEBUG - http-outgoing-1: set socket timeout to 0
selenium_1            | 15:00:04.964 DEBUG - Executing request POST /wd/hub/session/a4ea0f4d-4e2e-46b3-86d1-1ef8cf98f637/url HTTP/1.1
selenium_1            | 15:00:04.964 DEBUG - Target auth state: UNCHALLENGED
selenium_1            | 15:00:04.964 DEBUG - Proxy auth state: UNCHALLENGED
selenium_1            | 15:00:04.965 DEBUG - http-outgoing-1 >> POST /wd/hub/session/a4ea0f4d-4e2e-46b3-86d1-1ef8cf98f637/url HTTP/1.1
selenium_1            | 15:00:04.965 DEBUG - http-outgoing-1 >> Connection: keep-alive

See this Stale connection check part, I think this is an internal handling from the HttpClient provided by th Apache libraries and used in Selenium, I think here.

I googled and this seems to be normal. What I imagine is that in a newer version of the HttpClient, those "read time out" messages were included and that is why you see them now in the debug log.

So I think that this is not a docker-selenium, and neither a Selenium issue, it is just the handling of connection pooling by the HttpClient in the Apache libraries.

I would suggest to close this issue since it is not related to docker-selenium.

[NiGhTTraX]

@diemol the stack overflow answer you linked says that the debug message can be ignored as they're not causing any problems. I'm seeing the message in the logs whenever my Selenium init times out. I'm not sure if there's a connection between them, but I'd sure like to get to the bottom of it.

[diemol]

@NiGhTTraX
I see, so it is affecting your tests then?
To be honest, this sounds more like a Selenium issue than a docker-selenium one. I would post it over there and they could give us more insights, I would be interested as well if this is affecting your tests.

[diemol]

Hi @NiGhTTraX,

Just to follow up on this, what do you mean by "my Selenium init times out". Can you please explain?

[NiGhTTraX]

When I ask the Selenium hub for a session it takes too long (more than 10s) and my tests time out. I can see in the logs that a request to create a new one has been received and in the debug logs I see the read time out error.

17:32:29.679 INFO - Registered a node http://172.18.0.4:5555
17:32:29.854 INFO - Registered a node http://172.18.0.3:5555
17:32:35.760 INFO - Got a request to create a new session: Capabilities [{rotatable=true, locationContextEnabled=true, loggingPrefs=org.openqa.selenium.logging.LoggingPreferences@2a2a1ebf, browserName=chrome, javascriptEnabled=true, handlesAlerts=true, requestOrigins={name=webdriverio, version=4.6.2, url=http://webdriver.io}}]
17:32:35.762 INFO - Trying to create a new session on test slot {seleniumProtocol=WebDriver, browserName=chrome, maxInstances=1, version=57.0.2987.110, applicationName=, platform=LINUX}
17:32:35.980 INFO - Got a request to create a new session: Capabilities [{rotatable=true, locationContextEnabled=true, loggingPrefs=org.openqa.selenium.logging.LoggingPreferences@ddbf0ca, browserName=firefox, javascriptEnabled=true, handlesAlerts=true, requestOrigins={name=webdriverio, version=4.6.2, url=http://webdriver.io}}]
17:32:35.980 INFO - Trying to create a new session on test slot {seleniumProtocol=WebDriver, browserName=firefox, maxInstances=1, version=52.0, applicationName=, platform=LINUX}

I can't reproduce this consistently, so if you have any ideas on how to provide more info, I'm all ears.

[diemol]

I was trying to find ways to reproduce as well and I was not successful.

I am not sure if the situation improved with the latest release for you @NiGhTTraX, did you find a way to reproduce it?

[NiGhTTraX]

@diemol I haven't had a failure in quite a while, so maybe it was fixed. Closing for now and I'll reopen it if it happens again.

[diemol]

Cool, let us know if you find something again. Thanks for the quick reply.