[🐛 Regression]: Arquillian Drone tests fail with 4.28.0,4.28.1

[lprimak]

What happened?

Starting with 4.28.0, Arquillian Drone test suite started failing in Selenium Server tests due to logging changes.

Regressed by #14754

PR:
arquillian/arquillian-extension-drone#538

CI run:
https://app.circleci.com/pipelines/github/arquillian/arquillian-extension-drone/635/workflows/55677ea2-05a8-4a86-b57a-22a15fd7accb/jobs/2365

I don't really see anything in the Release Notes that would cause this.
Looking for help here to figure what happened and fix this.

How can we reproduce the issue?

Run Arquillian Drone build / test or see the logs above.

Operating System

Any

Selenium version

4.28.0 and ad later

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

Any

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

Any

Are you using Selenium Grid?

Yes

[github-actions]

@lprimak, 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!

[diemol]

4.27.0 works well?

@VietND96 @joerg1985 do you know any changes done to the Grid that could cause this?

[lprimak]

Yes. 4.27.0 works well

[joerg1985]

No, but i have seen this strange error before 4.28.x on slack. E.g. https://seleniumhq.slack.com/archives/C0ABCS03F/p1733385651838249?thread_ts=1733385651.838249&cid=C0ABCS03F

Have to take a closer look at the CI output the next days.

[lprimak]

Thank you Joerg!

[joerg1985]

I had a look at the raw logs from here

When searching for the session id 3277a3d76c517e0a3f254bb5f91ce48a you will find these lines, which i have truncated to make it better readable:

Jan 24, 2025 3:41:40 PM org.openqa.selenium.grid.node.local.LocalNode newSession
INFO: Session created by the Node. Id: 3277a3d76c517e0a3f254bb5f91ce48a, Caps: Capabilities ...

Jan 24, 2025 3:41:40 PM org.openqa.selenium.grid.distributor.local.LocalDistributor newSession
INFO: Session created by the Distributor. Id: 3277a3d76c517e0a3f254bb5f91ce48a Caps: Capabilities ...

Jan 24, 2025 3:41:42 PM org.openqa.selenium.grid.sessionmap.local.LocalSessionMap remove
INFO: Deleted session from local Session Map, Id: 3277a3d76c517e0a3f254bb5f91ce48a

Jan 24, 2025 3:41:42 PM org.openqa.selenium.grid.distributor.GridModel release
INFO: Releasing slot for session id 3277a3d76c517e0a3f254bb5f91ce48a

Jan 24, 2025 3:41:42 PM org.openqa.selenium.grid.node.local.SessionSlot stop
INFO: Stopping session 3277a3d76c517e0a3f254bb5f91ce48a

Jan 24, 2025 3:41:44 PM org.openqa.selenium.remote.tracing.opentelemetry.SeleniumSpanExporter$1 lambda$export$1
WARNING: org.openqa.selenium.NoSuchSessionException: Unable to find session with ID: 3277a3d76c517e0a3f254bb5f91ce48a

Jan 24, 2025 3:41:44 PM org.jboss.arquillian.drone.webdriver.factory.RemoteWebDriverFactory createReusableDriver
WARNING: Unable to reuse session: 3277a3d76c517e0a3f254bb5f91ce48a

So it looks like the session is used after the session has been deleted by the org.jboss.arquillian.drone.webdriver.factory.RemoteWebDriverFactory createReusableDriver
This will make the server log this error, but i don't think the CI failure is related to this error at all.

This is the summary of failures:

[ERROR] Errors: 
[ERROR]   SeleniumServerTestCase.should_start_selenium_server_as_hub:55->verifyLogContainsRegex:68 » ConditionTimeout Condition with alias 'The log should contains part that matches regex: .*\[Hub.execute.*Started Selenium Hub.*' didn't complete within 2 seconds because condition with Lambda expression in org.jboss.arquillian.drone.webdriver.binary.process.SeleniumServerTestCase was not fulfilled.
[ERROR]   SeleniumServerTestCase.should_start_selenium_server_with_no_serverArgs:43->verifyLogContainsRegex:68 » ConditionTimeout Condition with alias 'The log should contains part that matches regex: .*\[Standalone.execute.*Started Selenium Standalone.*' didn't complete within 2 seconds because condition with Lambda expression in org.jboss.arquillian.drone.webdriver.binary.process.SeleniumServerTestCase was not fulfilled.
[ERROR]   SeleniumServerTestCase.should_start_selenium_server_with_serverArgs_node:33->verifyLogContainsRegex:68 » ConditionTimeout Condition with alias 'The log should contains part that matches regex: .*\[NodeServer.execute.*Started Selenium node.*' didn't complete within 2 seconds because condition with Lambda expression in org.jboss.arquillian.drone.webdriver.binary.process.SeleniumServerTestCase was not fulfilled.

I had a look at the related log lines and the log lines show a slightly different pattern than the expected.
e.g. for the HUB, expected pattern: .*\[Hub.execute.*Started Selenium Hub.*

Jan 24, 2025 3:41:34 PM org.openqa.selenium.grid.commands.Hub execute
INFO: Started Selenium Hub 4.28.1 (revision 73f5ad48a2): http://10.89.1.3:5588

@lprimak i think you should update the expected pattern

[lprimak]

Wow Joerg, now that's what I call "above and beyond".
I'll try that, thank you!

[lprimak]

Ok, I was able to modify the test that starts Selenium Server in "Node" mode and fix that,
I also had to change capture from stdout to stderr there.

However, both "Hub" and "Standalone" modes don't work because it doesn't look like stdout nor stderr capture any logs from the server started in that mode.

Has the logging framework changed? It looks like the logs became multi-line instead of single-line.
This indicates a change (maybe from Log4j to java.util.logging?)

I am trying to figure out what would cause such a drastic change in behavior to know where to start debugging.
Can you at least point me to the changeset that modified this behavior?

Once again, thanks for all your help!

[joerg1985]

The check added in 16b0074 does not work as expected, as the default JDK properties file does contain this property, so we always skip the logging settings.

In general checking for handlers here is not correct, someone could have changed the logging e.g. by code and this check will also fail. It might be best to add a new flag here --keep-loggers true (better names are welcome) to skip the code instead of detecting the state.

@diemol what do you think about this?