{"action":"created","issue":{"url":"https://api.github.com/repos/SeleniumHQ/docker-selenium/issues/695","repository_url":"https://api.github.com/repos/SeleniumHQ/docker-selenium","labels_url":"https://api.github.com/repos/SeleniumHQ/docker-selenium/issues/695/labels{/name}","comments_url":"https://api.github.com/repos/SeleniumHQ/docker-selenium/issues/695/comments","events_url":"https://api.github.com/repos/SeleniumHQ/docker-selenium/issues/695/events","html_url":"https://github.com/SeleniumHQ/docker-selenium/issues/695","id":304387373,"number":695,"title":"Session [....] not available and is not among the last 1000 terminated sessions","user":{"login":"eyalzek","id":6243438,"avatar_url":"https://avatars2.githubusercontent.com/u/6243438?v=4","gravatar_id":"","url":"https://api.github.com/users/eyalzek","html_url":"https://github.com/eyalzek","followers_url":"https://api.github.com/users/eyalzek/followers","following_url":"https://api.github.com/users/eyalzek/following{/other_user}","gists_url":"https://api.github.com/users/eyalzek/gists{/gist_id}","starred_url":"https://api.github.com/users/eyalzek/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/eyalzek/subscriptions","organizations_url":"https://api.github.com/users/eyalzek/orgs","repos_url":"https://api.github.com/users/eyalzek/repos","events_url":"https://api.github.com/users/eyalzek/events{/privacy}","received_events_url":"https://api.github.com/users/eyalzek/received_events","type":"User","site_admin":false},"labels":[{"id":454441189,"url":"https://api.github.com/repos/SeleniumHQ/docker-selenium/labels/R-awaiting-answer","name":"R-awaiting-answer","color":"fbca04","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":14,"created_at":"2018-03-12T14:11:51Z","updated_at":"2018-03-16T18:59:08Z","closed_at":null,"author_association":"NONE","body":"## Meta -\r\nImage(s):  \r\nhub/node-chrome\r\nDocker-Selenium Image Version(s):  \r\n3.5.3-boron, 3.9.1-actinium\r\nDocker Version:  \r\n17.09.1-ce\r\n\r\nI've been seeing this issue for a while now, happening randomly. I'm testing with webdriverio + mocha, running in docker. I've seen this happen when running 2 chrome nodes, but I think the problem occurs more often (but not reproducible) when I run 5 chrome nodes.\r\n\r\nExample of the error that I'm seeing:\r\n```\r\nSession [95635190928628f91d62dab7595e271d] not available and is not among the last 1000 terminated sessions. Active sessions are[ext. key 4304cbbbd14fcb10fd6a6866baaf22c6, ext. key 6e5afdf576a0249056ad69d89e7ad154, ext. key e2260047ddd1461aec6c3f7986eda7b3, 85a10aad-9e02-4bcf-a567-59817ccb0865 (int. key, remote not contacted yet.)]\r\n```\r\n\r\nI've noticed that every time this error happens, the following message is logged by the hub:\r\n`INFO - Removed a session that had not yet assigned an external key b9dba954-9635-4bff-b338-655f727baffc, indicates failure in session creation BROWSER_TIMEOUT`\r\n\r\nI've tried setting `BROWSER_TIMEOUT` to 0/-1/30000, I don't think it's actually related to it. After setting the hub's log level to `DEBUG` I managed to get a bit more insight, but I'm still unsure what's exactly happening. The following gist contains part of that log, I only left the thread that failed and another thread that I think is related to the issue. If any other information is required please let me know and I will supply it:\r\nhttps://gist.github.com/anonymous/d570b0eb57143c03d9f8256eeb2865bb\r\n\r\nFrom my limited understanding of how the hub works, I think this is timeline of what happens:\r\n-  session requested by 75: `10:38:20.286 DEBUG - http-outgoing-75 >> POST /wd/hub/session HTTP/1.1`\r\n- 86 is requesting a connection but not creating a new one?:\r\n```10:38:25.949 DEBUG - Connection request: [route: {}->http://172.18.0.7:5555][total kept alive: 0; route allocated: 1 of 2000; total allocated: 5 of 2000]\r\n10:38:25.949 DEBUG - Connection leased: [id: 86][route: {}->http://172.18.0.7:5555][total kept alive: 0; route allocated: 2 of 2000; total allocated: 6 of 2000]\r\n```\r\n- 75 times out and deletes the session for some reason:\r\n```10:38:25.956 DEBUG - http-outgoing-75 << \"[read] I/O error: Read timed out\"\r\n10:38:25.956 DEBUG - http-outgoing-75: set socket timeout to 0\r\n10:38:25.956 DEBUG - Executing request DELETE /wd/hub/session/7e54a0292efc104182ab778f2fa4e7cc HTTP/1.1\r\n```\r\n- at the same time 86 is trying to get that session: `10:38:25.962 DEBUG - http-outgoing-86 >> GET /wd/hub/session/7e54a0292efc104182ab778f2fa4e7cc/window/current/size HTTP/1.1`\r\n- which is returning 200 for the first 2 requests, but in the middle is actually getting deleted by 75: `10:38:25.963 DEBUG - http-outgoing-75 >> \"DELETE /wd/hub/session/7e54a0292efc104182ab778f2fa4e7cc HTTP/1.1[\\r][\\n]\"`\r\n- 86 at some point times out and retries the requests:\r\n```10:38:26.003 DEBUG - http-outgoing-86 << \"[read] I/O error: Read timed out\"\r\n10:38:26.003 DEBUG - http-outgoing-86: set socket timeout to 0\r\n10:38:26.003 DEBUG - Executing request POST /wd/hub/session/7e54a0292efc104182ab778f2fa4e7cc/execute HTTP/1.1\r\n```\r\n- this returns the following message: `10:38:26.202 DEBUG - http-outgoing-86 << \"{\"sessionId\":\"\",\"status\":6,\"value\":{\"message\":\"no such session\\n  (Driver info: chromedriver=2.35.528139 (47ead77cb35ad2a9a83248b292151462a66cd881),platform=Linux 3.13.0-143-generic x86_64)\"}}\"`\r\n- next it seems like 86 tries to initialize a new sessions: `10:38:26.257 DEBUG - http-outgoing-86 >> POST /wd/hub/session HTTP/1.1`\r\n- and it looks like the hub is giving it a new session: `10:38:33.513 DEBUG - http-outgoing-86 << \"{\"status\":0,\"sessionId\":\"95635190928628f91d62dab7595e271d\",\"value\":{\"applicationCacheEnabled\":false,\"rotatable\":false,\"mobileEmulationEnabled\":false,\"networkConnectionEnabled\":false,\"chrome\":{\"chromedriverVersion\":\"2.35.528139 `\r\n- and then fails:\r\n```10:38:33.514 DEBUG - Connection [id: 86][route: {}->http://172.18.0.7:5555] can be kept alive indefinitely\r\n10:38:33.514 DEBUG - Connection released: [id: 86][route: {}->http://172.18.0.7:5555][total kept alive: 1; route allocated: 1 of 2000; total allocated: 5 of 2000]\r\n10:38:33.593 DEBUG - Session [95635190928628f91d62dab7595e271d] not available and is not among the last 1000 terminated sessions.\r\nActive sessions are[ext. key 4304cbbbd14fcb10fd6a6866baaf22c6, ext. key 6e5afdf576a0249056ad69d89e7ad154, ext. key e2260047ddd1461aec6c3f7986eda7b3, 85a10aad-9e02-4bcf-a567-59817ccb0865 (int. key, remote not contacted yet.)]\r\n10:38:33.710 DEBUG - Session [95635190928628f91d62dab7595e271d] not available and is not among the last 1000 terminated sessions.\r\nActive sessions are[ext. key 4304cbbbd14fcb10fd6a6866baaf22c6, ext. key 6e5afdf576a0249056ad69d89e7ad154, ext. key e2260047ddd1461aec6c3f7986eda7b3, 85a10aad-9e02-4bcf-a567-59817ccb0865 (int. key, remote not contacted yet.)]\r\n10:38:33.725 DEBUG - Session [95635190928628f91d62dab7595e271d] not available and is not among the last 1000 terminated sessions.\r\nActive sessions are[ext. key 4304cbbbd14fcb10fd6a6866baaf22c6, ext. key 6e5afdf576a0249056ad69d89e7ad154, ext. key e2260047ddd1461aec6c3f7986eda7b3, 85a10aad-9e02-4bcf-a567-59817ccb0865 (int. key, remote not contacted yet.)]\r\n10:38:33.750 DEBUG - Session [95635190928628f91d62dab7595e271d] not available and is not among the last 1000 terminated sessions.\r\nActive sessions are[ext. key 4304cbbbd14fcb10fd6a6866baaf22c6, ext. key 6e5afdf576a0249056ad69d89e7ad154, ext. key e2260047ddd1461aec6c3f7986eda7b3, 85a10aad-9e02-4bcf-a567-59817ccb0865 (int. key, remote not contacted yet.)]\r\n```\r\n\r\n\r\nAny information/suggestions on how to debug this further would be appreciated !\r\n"},"comment":{"url":"https://api.github.com/repos/SeleniumHQ/docker-selenium/issues/comments/373813123","html_url":"https://github.com/SeleniumHQ/docker-selenium/issues/695#issuecomment-373813123","issue_url":"https://api.github.com/repos/SeleniumHQ/docker-selenium/issues/695","id":373813123,"user":{"login":"diemol","id":5992658,"avatar_url":"https://avatars1.githubusercontent.com/u/5992658?v=4","gravatar_id":"","url":"https://api.github.com/users/diemol","html_url":"https://github.com/diemol","followers_url":"https://api.github.com/users/diemol/followers","following_url":"https://api.github.com/users/diemol/following{/other_user}","gists_url":"https://api.github.com/users/diemol/gists{/gist_id}","starred_url":"https://api.github.com/users/diemol/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/diemol/subscriptions","organizations_url":"https://api.github.com/users/diemol/orgs","repos_url":"https://api.github.com/users/diemol/repos","events_url":"https://api.github.com/users/diemol/events{/privacy}","received_events_url":"https://api.github.com/users/diemol/received_events","type":"User","site_admin":false},"created_at":"2018-03-16T18:59:08Z","updated_at":"2018-03-16T18:59:08Z","author_association":"MEMBER","body":"Hi @eyalzek @loghen41,\r\n\r\nThanks for your effort in debugging the issue! Have you guys found anything related to the images? Seems that it is more related to the available resources, right?\r\n\r\nPlease let us know if there is something specific that can be improved, or a reproducible issue.\r\n\r\nI'll leave this issue open for a few days more in case there are more findings that can help the community. "}}
{"actor":{"display_login":"diemol"}}