selenium icon indicating copy to clipboard operation
selenium copied to clipboard
verified publisher icon SeleniumHQ

[🐛 Bug]: Inconsistent IEDriverServer 4.0.0 instance shutdown (using Edge in IEMode + Selenium 4)

Open adhisivanr opened this issue 3 years ago • 19 comments

What happened?

We have been facing an issue (which is inconsistent), the IEDriverServer instance managed by Selenium Grid not shutting down gracefully. Frequently the selenium node instance continue in loop for driver.quit() request, trying to keep sending DELETE request to IEDriverServer, and thru log we could see the IEDriverServer loops waiting for all browser instance to close, however the browser instance is already closed.

What we are using? Selenium 4.1.4 (for hub and node) Selenium Java Client 4.1.2 Internet Explorer - with capability to run on Edge in IE Mode

Hub started with below command line: java -jar "C:\TAAS_AUTOMATION\selenium-server-4.1.4.jar" hub

Node started with below command line: java -Dwebdriver.ie.driver.logfile=driver.log -Dwebdriver.ie.driver.loglevel=DEBUG -jar selenium-server-4.1.4.jar node --detect-drivers true --http-logs true --log-level FINE --log session.log

How can we reproduce the issue?

**What we are using?**
Selenium 4.1.4 (for hub and node)
Selenium Java Client 4.1.2
Internet Explorer - with capability to run on Edge in IE Mode

**Hub started with below command line:**
java -jar "C:\TAAS_AUTOMATION\selenium-server-4.1.4.jar" hub

**Node started with below command line:**
java -Dwebdriver.ie.driver.logfile=driver.log -Dwebdriver.ie.driver.loglevel=DEBUG -jar selenium-server-4.1.4.jar node --detect-drivers true --http-logs true --log-level FINE --log session.log

Relevant log output

T 2022-05-02 12:05:12:818 C:\Projects\selenium\cpp\webdriver-server\server.cc(479) Entering Server::SendResponseToClient
T 2022-05-02 12:05:12:818 C:\Projects\selenium\cpp\webdriver-server\response.cc(30) Entering Response::Deserialize
T 2022-05-02 12:05:12:818 C:\Projects\selenium\cpp\webdriver-server\server.cc(540) Entering Server::SendHttpOk
T 2022-05-02 12:05:13:056 C:\Projects\selenium\cpp\webdriver-server\server.cc(234) Entering Server::ProcessRequest
T 2022-05-02 12:05:13:056 C:\Projects\selenium\cpp\webdriver-server\server.cc(243) Process request with: URI: /session/4e4c2094-0f96-4fa1-a77c-9d2a029ddcdd HTTP verb: DELETE
body: {}
T 2022-05-02 12:05:13:056 C:\Projects\selenium\cpp\webdriver-server\server.cc(334) Entering Server::DispatchCommand
T 2022-05-02 12:05:13:056 C:\Projects\selenium\cpp\webdriver-server\server.cc(687) Entering Server::LookupCommand
D 2022-05-02 12:05:13:056 C:\Projects\selenium\cpp\webdriver-server\server.cc(343) Command: DELETE /session/4e4c2094-0f96-4fa1-a77c-9d2a029ddcdd {}
T 2022-05-02 12:05:13:056 C:\Projects\selenium\cpp\webdriver-server\server.cc(466) Entering Server::LookupSession
T 2022-05-02 12:05:13:056 C:\Projects\selenium\cpp\iedriver\IESession.cpp(198) Entering IESession::ExecuteCommand
T 2022-05-02 12:05:13:056 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(156) Entering IECommandExecutor::OnSetCommand
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\webdriver-server\command.cc(31) Entering Command::Deserialize
D 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\webdriver-server\command.cc(36) Raw JSON command: { "name" : "quit", "locator" : { "sessionid" : "4e4c2094-0f96-4fa1-a77c-9d2a029ddcdd" }, "parameters" : {} }
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\webdriver-server\command.cc(31) Entering Command::Deserialize
D 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\webdriver-server\command.cc(36) Raw JSON command: { "name" : "quit", "locator" : { "sessionid" : "4e4c2094-0f96-4fa1-a77c-9d2a029ddcdd" }, "parameters" : {} }
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(178) Entering IECommandExecutor::OnExecCommand
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(974) Entering IECommandExecutor::DispatchCommand
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1295) Entering IECommandExecutor::GetCurrentBrowser
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1301) Entering IECommandExecutor::GetManagedBrowser
D 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(992) Checking for alert before executing quit command
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
D 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1039) Executing command: quit
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1325) Entering IECommandExecutor::GetManagedBrowserHandles
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\Browser.cpp(571) Entering Browser::IsValidWindow
T 2022-05-02 12:05:13:057 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:058 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
T 2022-05-02 12:05:13:058 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1301) Entering IECommandExecutor::GetManagedBrowser
T 2022-05-02 12:05:13:058 C:\Projects\selenium\cpp\iedriver\Browser.cpp(428) Entering Browser::Close
T 2022-05-02 12:05:13:058 C:\Projects\selenium\cpp\iedriver\Browser.cpp(559) Entering Browser::GetTopLevelWindowHandle
T 2022-05-02 12:05:13:058 C:\Projects\selenium\cpp\iedriver\IESession.cpp(226) Beginning wait for response length to be not zero
T 2022-05-02 12:05:13:058 C:\Projects\selenium\cpp\iedriver\DocumentHost.cpp(149) Entering DocumentHost::SetFocusedFrameByElement
T 2022-05-02 12:05:13:059 C:\Projects\selenium\cpp\webdriver-server\response.cc(81) Entering Response::SetSuccessResponse
T 2022-05-02 12:05:13:059 C:\Projects\selenium\cpp\webdriver-server\response.cc(87) Entering Response::SetResponse
D 2022-05-02 12:05:13:059 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1042) Command execution for quit complete
T 2022-05-02 12:05:13:059 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1295) Entering IECommandExecutor::GetCurrentBrowser
T 2022-05-02 12:05:13:059 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1301) Entering IECommandExecutor::GetManagedBrowser
T 2022-05-02 12:05:13:059 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1304) Current command executor is not valid
T 2022-05-02 12:05:13:121 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:121 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:121 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:121 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:121 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:122 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:122 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:194 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:194 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:194 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:194 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:194 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:194 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:195 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:258 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:258 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:258 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:258 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:258 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:258 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:258 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found

T 2022-05-02 12:05:13:319 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:319 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:319 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:319 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:319 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:319 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:319 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:371 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:372 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:372 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:372 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:372 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:372 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:372 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:443 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:443 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:443 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:443 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:443 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:443 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:443 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:505 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:505 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:505 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:505 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:505 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:505 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:506 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:568 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:568 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:568 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:568 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:568 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:568 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:568 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:639 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:639 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:639 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:639 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:639 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:639 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:639 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:697 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:697 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:697 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:697 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:697 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:697 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:697 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:755 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:755 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:755 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:755 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:755 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:755 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:755 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:818 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:818 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:818 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:818 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:818 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:818 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:818 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:884 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:884 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:884 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:884 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:884 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:884 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:884 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:13:943 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:13:943 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:13:943 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:13:943 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:13:943 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:13:943 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:13:943 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:14:008 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:14:008 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:14:008 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:14:008 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:14:008 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:14:008 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:14:008 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:14:067 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:14:068 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:14:068 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:14:068 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:14:068 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:14:068 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:14:068 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:14:131 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:14:131 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:14:131 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:14:132 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:14:132 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:14:132 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:14:132 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found
T 2022-05-02 12:05:14:194 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(463) Entering IECommandExecutor::OnAllBrowserCloseWait
T 2022-05-02 12:05:14:194 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(465) Still have 1 browsers
T 2022-05-02 12:05:14:194 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(468) Still awaiting close of browser with ID a514800a-286b-490d-81e8-1474cdaba229
T 2022-05-02 12:05:14:194 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1190) Entering IECommandExecutor::IsAlertActive
T 2022-05-02 12:05:14:194 C:\Projects\selenium\cpp\iedriver\Browser.cpp(868) Entering Browser::GetActiveDialogWindowHandle
T 2022-05-02 12:05:14:194 C:\Projects\selenium\cpp\iedriver\Browser.cpp(315) Entering Browser::GetContentWindowHandle
D 2022-05-02 12:05:14:194 C:\Projects\selenium\cpp\iedriver\IECommandExecutor.cpp(1207) No alert handle is found

Operating System

Windows 10

Selenium version

Selenium Java 4.1.2

What are the browser(s) and version(s) where you see this issue?

Edge in IEMode

What are the browser driver(s) and version(s) where you see this issue?

InternetExplorer Driver 4.0.0

Are you using Selenium Grid?

Yes - 4.1.4

adhisivanr avatar May 02 '22 11:05 adhisivanr

@adhisivanr, thank you for creating this issue. We will troubleshoot it as soon as we can.

Info for maintainers

Triage this issue by using labels.

If information is missing, add a helpful comment and then I-issue-template label.

If the issue is a question, add the I-question label.

If the issue is valid but there is no time to troubleshoot it, consider adding the help wanted label.

If the issue requires changes or fixes from an external project (e.g., ChromeDriver, GeckoDriver, MSEdgeDriver, W3C), add the applicable G-* label, and it will provide the correct link and auto-close the issue.

After troubleshooting the issue, please add the R-awaiting answer label.

Thank you!

github-actions[bot] avatar May 02 '22 11:05 github-actions[bot]

Can you please share the Grid logs and a test we can use to reproduce the issue?

diemol avatar May 02 '22 13:05 diemol

The test is simple opening and closing the browser using below capabilities. When driver.quit() is called, it stays there for a very long time.

ie.custom.cap = [{"browserAttachTimeout": "10000"}, {"ie.edgechromium": true},{"ie.edgepath": "C:/Program Files (x86)/Microsoft/Edge/Application/msedge.exe"},{"platform":WINDOWS},{"requireWindowFocus":true},{"ie.ensureCleanSession": true},{"ignoreZoomSetting": true},{"nativeEvents": true},{"ignoreProtectedModeSettings": true},{"disable-popup-blocking": true},{"enablePersistentHover": true}]

Please find the Grid (node) logs below:


04:20:51.106 DEBUG [DefaultChannelPool$IdleChannelDetector.run] - Entry count for : http://localhost:60318 : 1
04:20:51.121 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync HTTP/1.1
User-Agent: selenium/4.1.2 (java windows)
Connection: keep-alive
accept: */*
Cache-Control: no-cache
traceparent: 00-a85c2a68157c3ece0124aa83ae5cd68d-c1900c3f12dc1afe-01
host: 
Content-Type: application/json; charset=utf-8
content-length: 126
04:20:51.121 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync HTTP/1.1
User-Agent: selenium/4.1.2 (java windows)
Connection: keep-alive
accept: */*
Cache-Control: no-cache
traceparent: 00-a85c2a68157c3ece0124aa83ae5cd68d-c1900c3f12dc1afe-01
host: 
Content-Type: application/json; charset=utf-8
content-length: 126
04:20:51.121 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 126, cap: 126/126, unwrapped: PooledUnsafeDirectByteBuf(ridx: 502, widx: 502, cap: 1024)), decoderResult: success)
04:20:51.121 DEBUG [RequestConverter.channelRead0] - Closing input pipe.
04:20:51.121 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6314fb5d, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6314fb5d, context={opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=a85c2a68157c3ece0124aa83ae5cd68d, spanId=39f179d46840a5b9, parentSpanContext=ImmutableSpanContext{traceId=a85c2a68157c3ece0124aa83ae5cd68d, spanId=c1900c3f12dc1afe, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.forward_command, kind=INTERNAL, attributes=AttributesMap{data={random.key=1d0f99f9-e0e8-4050-a39f-5158779795eb}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1651116051121000000, endEpochNanos=0}}, span id=39f179d46840a5b9, trace id=a85c2a68157c3ece0124aa83ae5cd68d}
04:20:51.121 DEBUG [HttpTracing.inject] - Injecting (POST) /session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync into OpenTelemetrySpan{traceId=a85c2a68157c3ece0124aa83ae5cd68d,spanId=39f179d46840a5b9} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:84
04:20:51.121 DEBUG [NettyRequestSender.pollPooledChannel] - Using pooled Channel '[id: 0xaec373db, L:/127.0.0.1:54927 - R:localhost/127.0.0.1:60318]' for 'POST' to 'http://localhost:60318/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync'
04:20:51.121 DEBUG [NettyRequestSender.sendRequestWithOpenChannel] - Using open Channel [id: 0xaec373db, L:/127.0.0.1:54927 - R:localhost/127.0.0.1:60318] for POST '/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync'
04:20:51.246 DEBUG [HttpHandler.handleHttpResponse] - 

Request DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync HTTP/1.1
content-length: 126
User-Agent: selenium/4.1.2 (java windows)
Connection: keep-alive
accept: */*
Cache-Control: no-cache
traceparent: 00-a85c2a68157c3ece0124aa83ae5cd68d-0f9639c93f99c9a0-01
host: localhost:60318
Content-Type: application/json; charset=utf-8

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Cache-Control: no-cache
Vary: Accept-Charset, Accept-Encoding, Accept-Language, Accept
Accept-Ranges: bytes
content-length: 18

04:20:51.246 DEBUG [ChannelManager.tryToOfferChannelToPool] - Adding key: http://localhost:60318 for channel [id: 0xaec373db, L:/127.0.0.1:54927 - R:localhost/127.0.0.1:60318]
04:20:51.246 DEBUG [SeleniumSpanExporter$1.lambda$export$1] - SpanData{spanContext=ImmutableSpanContext{traceId=a85c2a68157c3ece0124aa83ae5cd68d, spanId=0f9639c93f99c9a0, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a85c2a68157c3ece0124aa83ae5cd68d, spanId=39f179d46840a5b9, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.8.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.10.1"}}, instrumentationLibraryInfo=InstrumentationLibraryInfo{name=default, version=null, schemaUrl=null}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1651116051121000000, endEpochNanos=1651116051235143800, attributes=AttributesMap{data={span.kind=client, http.target=/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync, http.method=POST, http.status_code=200}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
04:20:51.246 DEBUG [SeleniumSpanExporter$1.lambda$export$1] - SpanData{spanContext=ImmutableSpanContext{traceId=a85c2a68157c3ece0124aa83ae5cd68d, spanId=9de9660cdc2cf271, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a85c2a68157c3ece0124aa83ae5cd68d, spanId=39f179d46840a5b9, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.8.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.10.1"}}, instrumentationLibraryInfo=InstrumentationLibraryInfo{name=default, version=null, schemaUrl=null}, name=reverse_proxy, kind=INTERNAL, startEpochNanos=1651116051121000000, endEpochNanos=1651116051235581800, attributes=AttributesMap{data={http.target=/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync, http.method=POST, http.status_code=200}, capacity=128, totalAddedValues=3}, totalAttributeCount=3, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
04:20:51.246 DEBUG [SeleniumSpanExporter$1.lambda$export$1] - SpanData{spanContext=ImmutableSpanContext{traceId=a85c2a68157c3ece0124aa83ae5cd68d, spanId=39f179d46840a5b9, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a85c2a68157c3ece0124aa83ae5cd68d, spanId=c1900c3f12dc1afe, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.8.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.10.1"}}, instrumentationLibraryInfo=InstrumentationLibraryInfo{name=default, version=null, schemaUrl=null}, name=node.forward_command, kind=INTERNAL, startEpochNanos=1651116051121000000, endEpochNanos=1651116051236714400, attributes=AttributesMap{data={random.key=1d0f99f9-e0e8-4050-a39f-5158779795eb, span.kind=server, http.target=/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync, http.method=POST, http.status_code=200}, capacity=128, totalAddedValues=5}, totalAttributeCount=5, events=[ImmutableEventData{name=HTTP request execution complete, attributes={http.flavor=1, http.handler_class="org.openqa.selenium.remote.http.Route$PredicatedRoute", http.host="", http.method="POST", http.request_content_length="126", http.scheme="HTTP", http.status_code=200, http.target="/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync", http.user_agent="selenium/4.1.2 (java windows)"}, epochNanos=1651116051236706400, totalAttributeCount=9}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
04:20:51.246 INFO [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "a85c2a68157c3ece0124aa83ae5cd68d","eventTime": 1651116051236706400,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "","http.method": "POST","http.request_content_length": "126","http.scheme": "HTTP","http.status_code": 200,"http.target": "\u002fsession\u002f096b6577-94aa-496f-a9f2-159019fac5e5\u002fexecute\u002fsync","http.user_agent": "selenium\u002f4.1.2 (java windows)"}}

04:20:51.293 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync HTTP/1.1
User-Agent: selenium/4.1.2 (java windows)
Connection: keep-alive
accept: */*
Cache-Control: no-cache
traceparent: 00-ef74cbbcd59d96e24bf7ff4fafc193a4-3304a256b9e8f283-01
host: 
Content-Type: application/json; charset=utf-8
content-length: 124
04:20:51.293 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync HTTP/1.1
User-Agent: selenium/4.1.2 (java windows)
Connection: keep-alive
accept: */*
Cache-Control: no-cache
traceparent: 00-ef74cbbcd59d96e24bf7ff4fafc193a4-3304a256b9e8f283-01
host: 
Content-Type: application/json; charset=utf-8
content-length: 124
04:20:51.293 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 124, cap: 124/124, unwrapped: PooledUnsafeDirectByteBuf(ridx: 500, widx: 500, cap: 1024)), decoderResult: success)
04:20:51.293 DEBUG [RequestConverter.channelRead0] - Closing input pipe.
04:20:51.293 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6314fb5d, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6314fb5d, context={opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=ef74cbbcd59d96e24bf7ff4fafc193a4, spanId=bb93baa2c862f186, parentSpanContext=ImmutableSpanContext{traceId=ef74cbbcd59d96e24bf7ff4fafc193a4, spanId=3304a256b9e8f283, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.forward_command, kind=INTERNAL, attributes=AttributesMap{data={random.key=b5c475ea-d4b0-40d9-84d7-06bb7bb5410a}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1651116051293000000, endEpochNanos=0}}, span id=bb93baa2c862f186, trace id=ef74cbbcd59d96e24bf7ff4fafc193a4}
04:20:51.293 DEBUG [HttpTracing.inject] - Injecting (POST) /session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync into OpenTelemetrySpan{traceId=ef74cbbcd59d96e24bf7ff4fafc193a4,spanId=bb93baa2c862f186} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:84
04:20:51.293 DEBUG [NettyRequestSender.pollPooledChannel] - Using pooled Channel '[id: 0xaec373db, L:/127.0.0.1:54927 - R:localhost/127.0.0.1:60318]' for 'POST' to 'http://localhost:60318/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync'
04:20:51.293 DEBUG [NettyRequestSender.sendRequestWithOpenChannel] - Using open Channel [id: 0xaec373db, L:/127.0.0.1:54927 - R:localhost/127.0.0.1:60318] for POST '/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync'
04:20:51.387 DEBUG [HttpHandler.handleHttpResponse] - 

Request DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync HTTP/1.1
content-length: 124
User-Agent: selenium/4.1.2 (java windows)
Connection: keep-alive
accept: */*
Cache-Control: no-cache
traceparent: 00-ef74cbbcd59d96e24bf7ff4fafc193a4-a929dd97e6281960-01
host: localhost:60318
Content-Type: application/json; charset=utf-8

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Cache-Control: no-cache
Vary: Accept-Charset, Accept-Encoding, Accept-Language, Accept
Accept-Ranges: bytes
content-length: 20

04:20:51.387 DEBUG [ChannelManager.tryToOfferChannelToPool] - Adding key: http://localhost:60318 for channel [id: 0xaec373db, L:/127.0.0.1:54927 - R:localhost/127.0.0.1:60318]
04:20:51.387 DEBUG [SeleniumSpanExporter$1.lambda$export$1] - SpanData{spanContext=ImmutableSpanContext{traceId=ef74cbbcd59d96e24bf7ff4fafc193a4, spanId=a929dd97e6281960, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=ef74cbbcd59d96e24bf7ff4fafc193a4, spanId=bb93baa2c862f186, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.8.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.10.1"}}, instrumentationLibraryInfo=InstrumentationLibraryInfo{name=default, version=null, schemaUrl=null}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1651116051293000000, endEpochNanos=1651116051385341700, attributes=AttributesMap{data={span.kind=client, http.target=/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync, http.method=POST, http.status_code=200}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
04:20:51.387 DEBUG [SeleniumSpanExporter$1.lambda$export$1] - SpanData{spanContext=ImmutableSpanContext{traceId=ef74cbbcd59d96e24bf7ff4fafc193a4, spanId=9ad80bb6d8a5a5d5, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=ef74cbbcd59d96e24bf7ff4fafc193a4, spanId=bb93baa2c862f186, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.8.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.10.1"}}, instrumentationLibraryInfo=InstrumentationLibraryInfo{name=default, version=null, schemaUrl=null}, name=reverse_proxy, kind=INTERNAL, startEpochNanos=1651116051293000000, endEpochNanos=1651116051385693600, attributes=AttributesMap{data={http.target=/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync, http.method=POST, http.status_code=200}, capacity=128, totalAddedValues=3}, totalAttributeCount=3, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
04:20:51.387 DEBUG [SeleniumSpanExporter$1.lambda$export$1] - SpanData{spanContext=ImmutableSpanContext{traceId=ef74cbbcd59d96e24bf7ff4fafc193a4, spanId=bb93baa2c862f186, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=ef74cbbcd59d96e24bf7ff4fafc193a4, spanId=3304a256b9e8f283, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.8.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.10.1"}}, instrumentationLibraryInfo=InstrumentationLibraryInfo{name=default, version=null, schemaUrl=null}, name=node.forward_command, kind=INTERNAL, startEpochNanos=1651116051293000000, endEpochNanos=1651116051386482800, attributes=AttributesMap{data={random.key=b5c475ea-d4b0-40d9-84d7-06bb7bb5410a, span.kind=server, http.target=/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync, http.method=POST, http.status_code=200}, capacity=128, totalAddedValues=5}, totalAttributeCount=5, events=[ImmutableEventData{name=HTTP request execution complete, attributes={http.flavor=1, http.handler_class="org.openqa.selenium.remote.http.Route$PredicatedRoute", http.host="", http.method="POST", http.request_content_length="124", http.scheme="HTTP", http.status_code=200, http.target="/session/096b6577-94aa-496f-a9f2-159019fac5e5/execute/sync", http.user_agent="selenium/4.1.2 (java windows)"}, epochNanos=1651116051386477100, totalAttributeCount=9}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
04:20:51.387 INFO [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "ef74cbbcd59d96e24bf7ff4fafc193a4","eventTime": 1651116051386477100,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "","http.method": "POST","http.request_content_length": "124","http.scheme": "HTTP","http.status_code": 200,"http.target": "\u002fsession\u002f096b6577-94aa-496f-a9f2-159019fac5e5\u002fexecute\u002fsync","http.user_agent": "selenium\u002f4.1.2 (java windows)"}}

04:20:51.693 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
DELETE /session/096b6577-94aa-496f-a9f2-159019fac5e5 HTTP/1.1
User-Agent: selenium/4.1.2 (java windows)
Connection: keep-alive
accept: */*
Cache-Control: no-cache
traceparent: 00-83e72c77e6c8529bcb1084e254578abf-796f9eb8434c252f-01
host: 
Content-Type: application/json; charset=utf-8
04:20:51.693 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
DELETE /session/096b6577-94aa-496f-a9f2-159019fac5e5 HTTP/1.1
User-Agent: selenium/4.1.2 (java windows)
Connection: keep-alive
accept: */*
Cache-Control: no-cache
traceparent: 00-83e72c77e6c8529bcb1084e254578abf-796f9eb8434c252f-01
host: 
Content-Type: application/json; charset=utf-8
04:20:51.693 DEBUG [RequestConverter.channelRead0] - Incoming message: EmptyLastHttpContent
04:20:51.693 DEBUG [RequestConverter.channelRead0] - Closing input pipe.
04:20:51.694 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6314fb5d, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6314fb5d, context={opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=83e72c77e6c8529bcb1084e254578abf, spanId=a2d49e203fb865ea, parentSpanContext=ImmutableSpanContext{traceId=83e72c77e6c8529bcb1084e254578abf, spanId=796f9eb8434c252f, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.forward_command, kind=INTERNAL, attributes=AttributesMap{data={random.key=da879062-fa61-4903-83fe-66c26199cd73}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1651116051694000000, endEpochNanos=0}}, span id=a2d49e203fb865ea, trace id=83e72c77e6c8529bcb1084e254578abf}
04:20:51.694 DEBUG [HttpTracing.inject] - Injecting (DELETE) /session/096b6577-94aa-496f-a9f2-159019fac5e5 into OpenTelemetrySpan{traceId=83e72c77e6c8529bcb1084e254578abf,spanId=a2d49e203fb865ea} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:84
04:20:51.695 DEBUG [NettyRequestSender.pollPooledChannel] - Using pooled Channel '[id: 0xaec373db, L:/127.0.0.1:54927 - R:localhost/127.0.0.1:60318]' for 'DELETE' to 'http://localhost:60318/session/096b6577-94aa-496f-a9f2-159019fac5e5'
04:20:51.695 DEBUG [NettyRequestSender.sendRequestWithOpenChannel] - Using open Channel [id: 0xaec373db, L:/127.0.0.1:54927 - R:localhost/127.0.0.1:60318] for DELETE '/session/096b6577-94aa-496f-a9f2-159019fac5e5'
04:20:58.748 DEBUG [LoggingHandler.channelRead] - [id: 0xc5dc9054, L:/0:0:0:0:0:0:0:0:5555] READ: [id: 0x7717b0db, L:/107.15.184.42:5555 - R:/107.15.184.42:55429]
04:20:58.748 DEBUG [LoggingHandler.channelReadComplete] - [id: 0xc5dc9054, L:/0:0:0:0:0:0:0:0:5555] READ COMPLETE
04:20:58.748 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /status HTTP/1.1
User-Agent: selenium/4.1.2 (java windows)
traceparent: 00-1907d8f4b0558580ede0fa3cfecad7d4-5c7fa92c8779d9f7-01
host: 107.15.184.42:5555
accept: */*
04:20:58.748 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /status HTTP/1.1
User-Agent: selenium/4.1.2 (java windows)
traceparent: 00-1907d8f4b0558580ede0fa3cfecad7d4-5c7fa92c8779d9f7-01
host: 107.15.184.42:5555
accept: */*
04:20:58.748 DEBUG [RequestConverter.channelRead0] - Incoming message: EmptyLastHttpContent
04:20:58.748 DEBUG [RequestConverter.channelRead0] - Closing input pipe.
04:20:58.748 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6314fb5d, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6314fb5d, context={opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=1907d8f4b0558580ede0fa3cfecad7d4, spanId=1ffca1bbec2e09b4, parentSpanContext=ImmutableSpanContext{traceId=1907d8f4b0558580ede0fa3cfecad7d4, spanId=5c7fa92c8779d9f7, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.status, kind=INTERNAL, attributes=AttributesMap{data={random.key=4df2bbc1-3cfb-46be-a878-9c8e271650ac}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1651116058748000000, endEpochNanos=0}}, span id=1ffca1bbec2e09b4, trace id=1907d8f4b0558580ede0fa3cfecad7d4}
04:20:58.748 DEBUG [HttpTracing.inject] - Injecting (GET) /status into OpenTelemetrySpan{traceId=1907d8f4b0558580ede0fa3cfecad7d4,spanId=1ffca1bbec2e09b4} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:84
04:20:58.748 DEBUG [SeleniumSpanExporter$1.lambda$export$1] - SpanData{spanContext=ImmutableSpanContext{traceId=1907d8f4b0558580ede0fa3cfecad7d4, spanId=1ffca1bbec2e09b4, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=1907d8f4b0558580ede0fa3cfecad7d4, spanId=5c7fa92c8779d9f7, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.8.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.10.1"}}, instrumentationLibraryInfo=InstrumentationLibraryInfo{name=default, version=null, schemaUrl=null}, name=node.status, kind=INTERNAL, startEpochNanos=1651116058748000000, endEpochNanos=1651116058750508100, attributes=AttributesMap{data={random.key=4df2bbc1-3cfb-46be-a878-9c8e271650ac, span.kind=server, http.target=/status, http.method=GET, http.status_code=200}, capacity=128, totalAddedValues=5}, totalAttributeCount=5, events=[ImmutableEventData{name=HTTP request execution complete, attributes={http.flavor=1, http.handler_class="org.openqa.selenium.remote.http.Route$TemplatizedRoute", http.host="107.15.184.42:5555", http.method="GET", http.scheme="HTTP", http.status_code=200, http.target="/status", http.user_agent="selenium/4.1.2 (java windows)"}, epochNanos=1651116058750497800, totalAttributeCount=8}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
04:20:58.748 INFO [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "1907d8f4b0558580ede0fa3cfecad7d4","eventTime": 1651116058750497800,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$TemplatizedRoute","http.host": "107.15.184.42:5555","http.method": "GET","http.scheme": "HTTP","http.status_code": 200,"http.target": "\u002fstatus","http.user_agent": "selenium\u002f4.1.2 (java windows)"}}

04:21:45.634 INFO [LocalNode.stopAllSessions] - Trying to stop all running sessions before shutting down...
04:21:45.634 DEBUG [LocalNode.lambda$new$1] - Stopping session 096b6577-94aa-496f-a9f2-159019fac5e5
04:21:45.634 DEBUG [UrlChecker.waitUntilUnavailable] - Waiting for http://localhost:60318/shutdown

adhisivanr avatar May 02 '22 13:05 adhisivanr

Can you please share that simple test you mention? I am not sure how to generate the exact same capabilities.

diemol avatar May 02 '22 15:05 diemol

Also, the log is incomplete, it only shows some requests but it does not show how the session is created. Can you please share the complete log?

diemol avatar May 02 '22 15:05 diemol

Here is the simplified version of what we were trying do, hope this helps.

import org.openqa.selenium.Platform;
import org.openqa.selenium.WebDriver;
import org.openqa.selenium.ie.InternetExplorerOptions;
import org.openqa.selenium.remote.*;

import java.net.MalformedURLException;
import java.net.URL;

public class SimpleTestClass {
    
    private static final String hubUrl = "http://localhost:4444/wd/hub";
    
    public static void main(String... args) throws MalformedURLException {
        WebDriver remoteWebDriver = new RemoteWebDriver(new URL(hubUrl), getIEOptions());
        remoteWebDriver.get("https://google.co.uk");
        remoteWebDriver.quit();
    }


    public static InternetExplorerOptions getIEOptions() {
        InternetExplorerOptions options = new InternetExplorerOptions();
        options.attachToEdgeChrome();
        options.withEdgeExecutablePath("C:/Program Files (x86)/Microsoft/Edge/Application/msedge.exe");
        options.setCapability("browserAttachTimeout", "10000");
        options.setCapability("platform", Platform.WINDOWS);
        options.setCapability("requireWindowFocus", true);
        options.setCapability("ie.ensureCleanSession", true);
        options.setCapability("ignoreZoomSetting", true);
        options.setCapability("nativeEvents", true);
        options.setCapability("ignoreProtectedModeSettings", true);

        return options;
    }
}

full Log:

adhisivanr avatar May 02 '22 15:05 adhisivanr

serverlog-bad.txt

adhisivanr avatar May 02 '22 15:05 adhisivanr

As I compare the logs between good one to bad one, here is the different I could find out.

Following call trace (from IEDriverServer Log) was found when it is properly shutdown, but these calls were not made when it is not closing properly. Browser::OnQuit DocumentHost::PostQuitMessage IECommandExecutor::OnBrowserQuit

adhisivanr avatar May 03 '22 05:05 adhisivanr

Did you finally attach the full log? I only see the bad one.

In any case, I am able to reproduce this, but unfortunately I cannot see why this is happening. As using regular IE works in Grid, and on the other side using IE Mode in Edge locally works as well.

Only different thing the Grid does is to add a host header and to ignore some other ones. So not really sure what the issue might be.

@bwalderman do you know if something additional is needed to run IE Mode in Edge over Grid? Are some specific headers important for execution? I am a bit lost since all commands seem to work fine, except driver.quit().

diemol avatar May 03 '22 13:05 diemol

@diemol Yes, in the previous post I have provided with full log (https://github.com/SeleniumHQ/selenium/files/8604139/serverlog-bad.txt)

"In any case, I am able to reproduce this, but unfortunately I cannot see why this is happening. As using regular IE works in Grid, and on the other side using IE Mode in Edge locally works as well." - Yes, this is really bothering as sessions are not closed cleanly, leaving the node accumulating orphaned browser and driver instances.

adhisivanr avatar May 03 '22 14:05 adhisivanr

After further investigation, I could see that, the below event did not fire when browser_.Quit() called on IWebBrowser2, because of that reason the managed browser handler keeps hanging in driver instance.

void __stdcall Browser::OnQuit()

Any reason why the OnQuit() event not fired sometimes?

adhisivanr avatar May 06 '22 15:05 adhisivanr

@diemol @adhisivanr even we are facing the same exact issue(inconsistent) and adding some wait time before the driver.quit() or condition session != null is doing some help for me

Issue: Like run 30-50 tests on the remote grid and the driver does close like first 20-30tests and next time set of tests I see that still open(driver is not closed gracefully) in the task manager processes and sessions won't get deleted properly.

manu141 avatar May 06 '22 15:05 manu141

@diemol any further update on driver closing and, after I discussed with you over the slack channel we did not see any further update on this from selenium.

manu141 avatar May 31 '22 17:05 manu141

No updates, if something new comes up, we will comment here.

diemol avatar Jun 01 '22 07:06 diemol

@diemol Do you think your changes https://github.com/SeleniumHQ/selenium/commit/9656da70e574a77213cba49ff00e11a2d0f1f393 might help for this issue?

pujagani avatar Aug 23 '22 07:08 pujagani

Maybe, @adhisivanr would you like to try again?

diemol avatar Aug 23 '22 08:08 diemol

We have been trying with most recent release version 4.3.0, but still the issue persist. I hope the commit code shared above already released?

adhisivanr avatar Aug 23 '22 08:08 adhisivanr

🤦 it has not been released. Next week it will be part of 4.5.0

diemol avatar Aug 23 '22 09:08 diemol

Thank you. I will give it a try once it is available.

adhisivanr avatar Aug 23 '22 10:08 adhisivanr

@adhisivanr 4.5 has finally been released, sorry for the delay.

titusfortner avatar Sep 29 '22 00:09 titusfortner

We were having same issue as OP with v4.3. It seems to be still happening in 4.5. DELETE gets stuck periodically and eventually selenium throws TimeoutException when session-timeout timeout is reached.

Here is a log snippet. Session timeout was set to 120 second in this case.

DELETE /wd/hub/session/ccbbf4e1-bcb1-458b-b26f-853d00767af0 HTTP/1.1

user-agent: webdriver/7.24.1

content-type: application/json; charset=utf-8

connection: keep-alive

accept: application/json

accept-encoding: gzip, deflate, br

Host: localhost:4446

15:01:37.545 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)

DELETE /wd/hub/session/ccbbf4e1-bcb1-458b-b26f-853d00767af0 HTTP/1.1

user-agent: webdriver/7.24.1

content-type: application/json; charset=utf-8

connection: keep-alive

accept: application/json

accept-encoding: gzip, deflate, br

Host: localhost:4446
15:01:37.545 DEBUG [RequestConverter.channelRead0] - Incoming message: EmptyLastHttpContent

15:01:37.545 DEBUG [RequestConverter.channelRead0] - Closing input pipe.
15:01:37.547 DEBUG [HttpTracing.inject] - Injecting (DELETE) /session/ccbbf4e1-bcb1-458b-b26f-853d00767af0 into OpenTelemetrySpan{traceId=45bb70dd904dff00a400175b1d69e2fc,spanId=37408738c7415f0a} at org.openqa.selenium.grid.router.HandleSession:121
15:01:37.547 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@40daf16d, context={opentelemetry-trace-span-key=SdkSpan{traceId=45bb70dd904dff00a400175b1d69e2fc, spanId=3c0b27c9d0822490, parentSpanContext=ImmutableSpanContext{traceId=45bb70dd904dff00a400175b1d69e2fc, spanId=37408738c7415f0a, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=reverse_proxy, kind=INTERNAL, attributes=AttributesMap{data={http.method=DELETE, http.target=/session/ccbbf4e1-bcb1-458b-b26f-853d00767af0}, capacity=128, totalAddedValues=2}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1664539297547000000, endEpochNanos=0}}, span id=3c0b27c9d0822490, trace id=45bb70dd904dff00a400175b1d69e2fc} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@40daf16d, context={opentelemetry-trace-span-key=SdkSpan{traceId=45bb70dd904dff00a400175b1d69e2fc, spanId=c6ca42488f3a268b, parentSpanContext=ImmutableSpanContext{traceId=45bb70dd904dff00a400175b1d69e2fc, spanId=37408738c7415f0a, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.forward_command, kind=INTERNAL, attributes=AttributesMap{data={random.key=d246b7c9-c1cc-46e4-bab1-bf789b63632d}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1664539297547000000, endEpochNanos=0}}, span id=c6ca42488f3a268b, trace id=45bb70dd904dff00a400175b1d69e2fc}
15:01:37.547 DEBUG [HttpTracing.inject] - Injecting (DELETE) /session/ccbbf4e1-bcb1-458b-b26f-853d00767af0 into OpenTelemetrySpan{traceId=45bb70dd904dff00a400175b1d69e2fc,spanId=c6ca42488f3a268b} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:84
15:01:37.549 DEBUG [NettyRequestSender.pollPooledChannel] - Using pooled Channel '[id: 0xe8ffdd37, L:/127.0.0.1:64377 - R:localhost/127.0.0.1:63232]' for 'DELETE' to 'http://localhost:63232/session/ccbbf4e1-bcb1-458b-b26f-853d00767af0'
15:01:37.549 DEBUG [NettyRequestSender.sendRequestWithOpenChannel] - Using open Channel [id: 0xe8ffdd37, L:/127.0.0.1:64377 - R:localhost/127.0.0.1:63232] for DELETE '/session/ccbbf4e1-bcb1-458b-b26f-853d00767af0'
15:01:37.549 FINEST [LoggingHandler.write] - [id: 0xe8ffdd37, L:/127.0.0.1:64377 - R:localhost/127.0.0.1:63232] WRITE: 342B

         +-------------------------------------------------+

         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |

+--------+-------------------------------------------------+----------------+

|00000000| 44 45 4c 45 54 45 20 2f 73 65 73 73 69 6f 6e 2f |DELETE /session/|

|00000010| 63 63 62 62 66 34 65 31 2d 62 63 62 31 2d 34 35 |ccbbf4e1-bcb1-45|

|00000020| 38 62 2d 62 32 36 66 2d 38 35 33 64 30 30 37 36 |8b-b26f-853d0076|

|00000030| 37 61 66 30 20 48 54 54 50 2f 31 2e 31 0d 0a 43 |7af0 HTTP/1.1..C|

|00000040| 6f 6e 6e 65 63 74 69 6f 6e 3a 20 6b 65 65 70 2d |onnection: keep-|

|00000050| 61 6c 69 76 65 0d 0a 61 63 63 65 70 74 3a 20 61 |alive..accept: a|

|00000060| 70 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f 6e 0d |pplication/json.|

|00000070| 0a 43 61 63 68 65 2d 43 6f 6e 74 72 6f 6c 3a 20 |.Cache-Control: |

|00000080| 6e 6f 2d 63 61 63 68 65 0d 0a 74 72 61 63 65 70 |no-cache..tracep|

|00000090| 61 72 65 6e 74 3a 20 30 30 2d 34 35 62 62 37 30 |arent: 00-45bb70|

|000000a0| 64 64 39 30 34 64 66 66 30 30 61 34 30 30 31 37 |dd904dff00a40017|

|000000b0| 35 62 31 64 36 39 65 32 66 63 2d 32 38 30 35 64 |5b1d69e2fc-2805d|

|000000c0| 38 39 65 36 32 31 39 65 35 33 38 2d 30 31 0d 0a |89e6219e538-01..|

|000000d0| 68 6f 73 74 3a 20 6c 6f 63 61 6c 68 6f 73 74 3a |host: localhost:|

|000000e0| 36 33 32 33 32 0d 0a 63 6f 6e 74 65 6e 74 2d 74 |63232..content-t|

|000000f0| 79 70 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e |ype: application|

|00000100| 2f 6a 73 6f 6e 3b 20 63 68 61 72 73 65 74 3d 75 |/json; charset=u|

|00000110| 74 66 2d 38 0d 0a 75 73 65 72 2d 61 67 65 6e 74 |tf-8..user-agent|

|00000120| 3a 20 77 65 62 64 72 69 76 65 72 2f 37 2e 32 34 |: webdriver/7.24|

|00000130| 2e 31 0d 0a 61 63 63 65 70 74 2d 65 6e 63 6f 64 |.1..accept-encod|

|00000140| 69 6e 67 3a 20 67 7a 69 70 2c 20 64 65 66 6c 61 |ing: gzip, defla|

|00000150| 74 65 0d 0a 0d 0a                               |te....          |

+--------+-------------------------------------------------+----------------+
15:01:37.549 FINEST [LoggingHandler.flush] - [id: 0xe8ffdd37, L:/127.0.0.1:64377 - R:localhost/127.0.0.1:63232] FLUSH
15:02:54.387 DEBUG [LocalDistributor.lambda$asRunnableHealthCheck$9] - Running healthcheck for Node http://10.0.2.15:4446
15:02:54.388 DEBUG [LocalDistributor.updateNodeAvailability] - Health check result for http://10.0.2.15:4446 was UP
15:03:37.960 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=45bb70dd904dff00a400175b1d69e2fc, spanId=2805d89e6219e538, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=45bb70dd904dff00a400175b1d69e2fc, spanId=c6ca42488f3a268b, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.12.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.17.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1664539297549000000, endEpochNanos=1664539417552560900, attributes=AttributesMap{data={http.method=DELETE, span.kind=client, http.target=/session/ccbbf4e1-bcb1-458b-b26f-853d00767af0}, capacity=128, totalAddedValues=3}, totalAttributeCount=3, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}

15:03:37.961 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=45bb70dd904dff00a400175b1d69e2fc, spanId=0da7096a1b74d08e, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=45bb70dd904dff00a400175b1d69e2fc, spanId=c6ca42488f3a268b, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.12.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.17.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null}, name=reverse_proxy, kind=INTERNAL, startEpochNanos=1664539297549000000, endEpochNanos=1664539417553150500, attributes=AttributesMap{data={http.method=DELETE, http.target=/session/ccbbf4e1-bcb1-458b-b26f-853d00767af0}, capacity=128, totalAddedValues=2}, totalAttributeCount=2, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}
15:03:37.964 WARN [SpanWrappedHttpHandler.execute] - Unable to execute request: java.util.concurrent.TimeoutException
Build info: version: '4.5.0', revision: 'fe167b119a'
System info: os.name: 'Windows 10', os.arch: 'amd64', os.version: '10.0', java.version: '1.8.0_281'
Driver info: driver.version: unknown

org.openqa.selenium.TimeoutException: java.util.concurrent.TimeoutException
Build info: version: '4.5.0', revision: 'fe167b119a'
System info: os.name: 'Windows 10', os.arch: 'amd64', os.version: '10.0', java.version: '1.8.0_281'
Driver info: driver.version: unknown

    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:65)

    at org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)

    at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)

    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.execute(NettyHttpHandler.java:49)

    at org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)

    at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)

    at org.openqa.selenium.remote.http.netty.NettyClient.execute(NettyClient.java:99)

    at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55)

    at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)

    at org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75)

    at org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:125)

    at org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:454)

    at org.openqa.selenium.grid.node.ForwardWebDriverCommand.execute(ForwardWebDriverCommand.java:35)

    at org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:373)

    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)

    at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:86)

    at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)

    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)

    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)

    at org.openqa.selenium.grid.node.Node.execute(Node.java:240)

    at org.openqa.selenium.grid.web.CombinedHandler.execute(CombinedHandler.java:59)

    at org.openqa.selenium.grid.web.RoutableHttpClientFactory$1.execute(RoutableHttpClientFactory.java:72)

    at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)

    at org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:122)

    at org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:373)

    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)

    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)

    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)

    at org.openqa.selenium.grid.router.Router.execute(Router.java:91)

    at org.openqa.selenium.grid.web.CheckOriginHeader.lambda$apply$0(CheckOriginHeader.java:66)

    at org.openqa.selenium.grid.web.CheckContentTypeHeader.lambda$apply$0(CheckContentTypeHeader.java:70)

    at org.openqa.selenium.grid.web.EnsureSpecCompliantResponseHeaders.lambda$apply$0(EnsureSpecCompliantResponseHeaders.java:34)

    at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)

    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)

    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)

    at org.openqa.selenium.remote.http.Route$NestedRoute.handle(Route.java:270)

    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)

    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)

    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)

    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)

    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)

    at org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)

    at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)

    at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)

    at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)

    at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)

    at org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)

    at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

    at java.util.concurrent.FutureTask.run(Unknown Source)

    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

    at java.lang.Thread.run(Unknown Source)

Caused by: java.util.concurrent.TimeoutException

    at java.util.concurrent.CompletableFuture.timedGet(Unknown Source)

    at java.util.concurrent.CompletableFuture.get(Unknown Source)

    at org.asynchttpclient.netty.NettyResponseFuture.get(NettyResponseFuture.java:206)

    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:59)

    ... 51 more```

romovs avatar Sep 30 '22 12:09 romovs

Seems like #11079 has fixed the problem. We are not experiencing the issue anymore after upgrade to v4.6.

romovs avatar Nov 04 '22 13:11 romovs

Great, thanks for the feedback, @romovs. I will close this for now, if someone still has the issue, please let us know.

diemol avatar Nov 07 '22 11:11 diemol

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

github-actions[bot] avatar Dec 08 '22 01:12 github-actions[bot]