[🐛 Bug]: [GRID] logging.properties is ignored when trying to remove stack trace errors from Logs

KrzysztofC commented 5 months ago

What happened?

When using: -Djava.util.logging.config.file=/opt/logging.properties which contains: handlers=java.util.logging.ConsoleHandler java.util.logging.ConsoleHandler.level=INFO java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter java.util.logging.SimpleFormatter.format=%1$tF %1$tT.%1$tL %4$s: %3$s %5$s %n

this works in other Java app that uses java.util.logging for logging, but it has zero effect on Grid Logs.

How can we reproduce the issue?

Create logging.properties file with below contents:
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=INFO
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format=%1$tF %1$tT.%1$tL %4$s: %3$s %5$s %n

start Grid Hub or Node with -Djava.util.logging.config.file=/your_path/logging.properties

Relevant log output

Expecting to NOT see stack trace in Logs such as these:
10:46:37.229 WARN [SeleniumSpanExporter$1.lambda$export$1] - org.openqa.selenium.SessionNotCreatedException: Could not start a new session. Response code 500. Message: session not created: DevToolsActivePort file doesn't exist
Host info: host: 'selenium-grid-4-node-72-2prgt', ip: 'x.x.x.x'
Build info: version: '4.21.0', revision: '79ed462ef4'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '4.18.0-372.71.1.el8_6.x86_64', java.version: '17.0.11'
Driver info: driver.version: unknown
                at org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:114)
                at org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:75)
                at org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:61)
                at org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:161)
                at org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:71)
                at org.openqa.selenium.grid.node.local.SessionSlot.apply(SessionSlot.java:147)
                at org.openqa.selenium.grid.node.local.LocalNode.newSession(LocalNode.java:469)
                at org.openqa.selenium.grid.node.NewNodeSession.execute(NewNodeSession.java:50)
                at org.openqa.selenium.remote.http.Route$TemplatizedRoute.handle(Route.java:192)
                at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
                at org.openqa.selenium.grid.security.RequiresSecretFilter.lambda$apply$0(RequiresSecretFilter.java:62)
                at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:87)
                at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
                at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
                at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
                at org.openqa.selenium.grid.node.Node.execute(Node.java:270)
                at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
                at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
                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:63)
                at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
                at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
                at org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)
                at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
                at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
                at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
                at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
                at java.base/java.lang.Thread.run(Thread.java:842)

Operating System

RH8 and Win10

Selenium version

4.21.0

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

N/A

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

N/A

Are you using Selenium Grid?

4.21.0

github-actions[bot] commented 5 months ago

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

JHeflinger commented 2 weeks ago

I'm noticing that this issue stems from the fact that any logging configuration with a logging.properties file is overwritten and replaced with the custom Selenium formatters and handlers (See configureLogging() function on line 96 of selenium/java/src/org/openqa/selenium/grid/log/LoggingOptions.java). This can be fixed by simply checking if the handlers property if the LogManager is null or not, but is it an intention of selenium to not allow custom configured logging?

SeleniumHQ / selenium