From ec94fd368a32956e3d278d7f64fe07d2cc904157 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 10:26:15 +0300 Subject: [PATCH 01/19] [java] Unify debug-logging switches into one real mechanism Debug.java now owns a single configureLogger() entry point that installs a level-aware handler on the shared Selenium logger, replacing the old pair of switches that didn't actually agree with each other. LoggingOptions and RemoteWebDriver call into it so Grid and driver sessions both honor the same debug-log level, closing #12892. Adds DebugTest, LoggingOptionsTest, RemoteWebDriverInitializationTest, and devtools/ConnectionTest as the direct tests for this mechanism. --- .../org/openqa/selenium/grid/log/BUILD.bazel | 1 + .../selenium/grid/log/LoggingOptions.java | 62 +++- .../org/openqa/selenium/internal/Debug.java | 160 ++++++++- .../selenium/remote/RemoteWebDriver.java | 27 +- .../org/openqa/selenium/devtools/BUILD.bazel | 1 + .../selenium/devtools/ConnectionTest.java | 116 ++++++ .../org/openqa/selenium/grid/log/BUILD.bazel | 15 + .../selenium/grid/log/LoggingOptionsTest.java | 259 ++++++++++++++ .../openqa/selenium/internal/DebugTest.java | 331 ++++++++++++++++++ .../RemoteWebDriverInitializationTest.java | 88 +++++ 10 files changed, 1038 insertions(+), 22 deletions(-) create mode 100644 java/test/org/openqa/selenium/devtools/ConnectionTest.java create mode 100644 java/test/org/openqa/selenium/grid/log/BUILD.bazel create mode 100644 java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java create mode 100644 java/test/org/openqa/selenium/internal/DebugTest.java diff --git a/java/src/org/openqa/selenium/grid/log/BUILD.bazel b/java/src/org/openqa/selenium/grid/log/BUILD.bazel index 68c796f96396b..78b93d5c555ae 100644 --- a/java/src/org/openqa/selenium/grid/log/BUILD.bazel +++ b/java/src/org/openqa/selenium/grid/log/BUILD.bazel @@ -7,6 +7,7 @@ java_library( visibility = [ "//java/src/org/openqa/selenium/grid:__subpackages__", "//java/src/org/openqa/selenium/remote/server:__subpackages__", + "//java/test/org/openqa/selenium/grid/log:__pkg__", ], deps = [ "//java:auto-service", diff --git a/java/src/org/openqa/selenium/grid/log/LoggingOptions.java b/java/src/org/openqa/selenium/grid/log/LoggingOptions.java index b812bac69f186..b9158dc7fc664 100644 --- a/java/src/org/openqa/selenium/grid/log/LoggingOptions.java +++ b/java/src/org/openqa/selenium/grid/log/LoggingOptions.java @@ -26,6 +26,7 @@ import java.util.Enumeration; import java.util.List; import java.util.Locale; +import java.util.logging.Filter; import java.util.logging.Handler; import java.util.logging.Level; import java.util.logging.LogManager; @@ -85,11 +86,21 @@ public String getLogEncoding() { return config.get(LOGGING_SECTION, "log-encoding").orElse(null); } + /** + * Resolves the Grid log level from the {@code log-level} entry of the logging config section + * and stores it for {@link #configureLogging()}. Any active Selenium debug switch ({@code + * SE_DEBUG}, {@code -Dselenium.debug=true}, {@code -Dselenium.webdriver.verbose=true}) + * overrides the configured value and forces {@link Level#FINE}. An unparseable configured + * value falls back to the default ({@code INFO}). + * + * @return this instance, for method chaining + */ public LoggingOptions setLoggingLevel() { String configLevel = config.get(LOGGING_SECTION, "log-level").orElse(DEFAULT_LOG_LEVEL); - if (Debug.isDebugAll()) { + if (Debug.isDebugAll() || Debug.isDebugging()) { System.err.println( - "WARNING: Environment Variable `SE_DEBUG` is set; forcing Grid log level to FINE and" + "WARNING: Selenium debug logging is enabled (`SE_DEBUG`, `-Dselenium.debug=true`, or" + + " `-Dselenium.webdriver.verbose=true`); forcing Grid log level to FINE and" + " overriding configured log level."); configLevel = Level.FINE.getName(); } @@ -128,6 +139,15 @@ public void configureLogging() { return; } + // Reflect the current debug switches onto the shared org.openqa.selenium logger before + // anything else below -- in particular, before the external-JUL-config early return just + // below hands the rest of logging setup off entirely. Without this, Selenium's own FINE-level + // wire diagnostics (RequestConverter, the BiDi/CDP Connection classes) stay invisible under + // -Dselenium.debug=true whenever an external `java.util.logging.config.*` property is set, + // since nothing else on Grid's startup path would ever call this. Idempotent and cheap, same + // chokepoint pattern as DriverFinder.getBinaryPaths(). + Debug.configureLogger(); + String configClass = System.getProperty("java.util.logging.config.class"); String configFile = System.getProperty("java.util.logging.config.file"); @@ -137,11 +157,21 @@ public void configureLogging() { return; } - // Remove all handlers from existing loggers + // Remove all handlers from existing loggers, except org.openqa.selenium: Debug.configureLogger() + // above may have just installed a handler there for debug-mode output, and this loop would + // otherwise strip it moments later (Debug holds a strong static reference so that logger stays + // registered here too). Debug's own installed-handler bookkeeping has no way to learn a handler + // was removed out from under it, so once stripped its idempotency guard would prevent ever + // reinstalling one until the debug switch is toggled off and back on. LogManager logManager = LogManager.getLogManager(); Enumeration names = logManager.getLoggerNames(); while (names.hasMoreElements()) { - Logger logger = logManager.getLogger(names.nextElement()); + String name = names.nextElement(); + if ("org.openqa.selenium".equals(name)) { + continue; + } + + Logger logger = logManager.getLogger(name); if (logger == null) { continue; } @@ -160,6 +190,7 @@ public void configureLogging() { Handler handler = new FlushingHandler(out); handler.setFormatter(new TerseFormatter(getLogTimestampFormat())); handler.setLevel(level); + handler.setFilter(rootHandlerFilter()); configureLogEncoding(logger, encoding, handler); } @@ -167,10 +198,33 @@ public void configureLogging() { Handler handler = new FlushingHandler(out); handler.setFormatter(new JsonFormatter()); handler.setLevel(level); + handler.setFilter(rootHandlerFilter()); configureLogEncoding(logger, encoding, handler); } } + /** + * Records that Debug.configureLogger()'s own handler on {@code org.openqa.selenium} already + * prints (FINE/CONFIG-range records from that logger or a descendant, while its handler is + * installed) must not also print through this root handler, PROVIDED this root handler's + * destination is the one Debug's handler also writes to -- that handler's own + * useParentHandlers is never disabled, so the same record reaches both. That's only true when + * no {@code log-file} is configured: {@link #getOutputStream()} then defaults this handler to + * {@code System.out}/{@code System.err}, the same visible destination as Debug's own {@code + * ConsoleHandler} (fixed to {@code System.err}) in every realistic deployment. A configured + * log-file is a genuinely separate destination Debug never writes to, so suppressing there + * would silently drop the record from the operator's chosen sink instead of de-duplicating it + * -- worse than the problem this filter exists to solve. INFO-and-above {@code + * org.openqa.selenium} records, and everything from every other logger, are untouched either + * way: Debug's handler never covered those in the first place. + */ + private Filter rootHandlerFilter() { + boolean logFileConfigured = config.get(LOGGING_SECTION, "log-file").isPresent(); + return record -> + logFileConfigured + || !Debug.isHandledBySeleniumDebugHandler(record.getLoggerName(), record.getLevel()); + } + private void configureLogEncoding(Logger logger, @Nullable String encoding, Handler handler) { String message; try { diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index 0b012f180f59e..ee5846d1a4877 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -17,37 +17,107 @@ package org.openqa.selenium.internal; +import java.util.Arrays; import java.util.concurrent.atomic.AtomicBoolean; +import java.util.logging.ConsoleHandler; +import java.util.logging.Filter; +import java.util.logging.Handler; import java.util.logging.Level; import java.util.logging.Logger; -import java.util.logging.SimpleFormatter; -import java.util.logging.StreamHandler; /** Used to provide information about whether Selenium is running under debug mode. */ public class Debug { - private static final boolean IS_DEBUG; private static final AtomicBoolean DEBUG_WARNING_LOGGED = new AtomicBoolean(false); private static final Logger SELENIUM_LOGGER = Logger.getLogger("org.openqa.selenium"); - private static boolean loggerConfigured = false; - static { - IS_DEBUG = - Boolean.getBoolean("selenium.debug") || Boolean.getBoolean("selenium.webdriver.verbose"); - } + private static boolean loggerConfigured = false; + private static Handler installedHandler = null; + private static Level previousLevel = null; + private static boolean levelRaisedByDebug = false; private Debug() { // Utility class } + /** + * Reports whether Selenium debug logging has been requested via the {@code selenium.debug} or + * the legacy {@code selenium.webdriver.verbose} system property. Read live on every call, so a + * property change made at runtime is reflected immediately. + * + * @return true when either the {@code selenium.debug} or the {@code selenium.webdriver.verbose} + * system property is set to {@code true}; false otherwise + */ public static boolean isDebugging() { - return IS_DEBUG; + return Boolean.getBoolean("selenium.debug") || Boolean.getBoolean("selenium.webdriver.verbose"); } + /** + * Returns the log level that debug output should be reported at: {@link Level#INFO} when {@link + * #isDebugging()} is true, {@link Level#FINE} otherwise. + * + * @deprecated Individual log statements no longer change what severity they report at based on + * this switch; {@link #configureLogger()} raises the real {@code org.openqa.selenium} logger + * to {@link Level#FINE} instead, which is the ordinary way to see Selenium's debug output. + * Enable it with {@code -Dselenium.debug=true}, the {@code SE_DEBUG} environment variable, or + * directly via {@code Logger.getLogger("org.openqa.selenium").setLevel(Level.FINE)}. This + * method's own behavior is unchanged and kept only for existing call sites still comparing + * against it. + * @return {@link Level#INFO} when debugging is enabled; {@link Level#FINE} otherwise + */ + @Deprecated(forRemoval = true) public static Level getDebugLogLevel() { return isDebugging() ? Level.INFO : Level.FINE; } + /** + * Reports whether {@link #configureLogger()}'s handler is attached to {@code + * org.openqa.selenium} right now. Unlike {@link #isDebugging()} or {@link #isDebugAll()}, which + * read the live system property/environment variable, this reflects the handler's actual, + * current installation state -- the two can genuinely diverge for however long it takes some + * caller to next invoke {@link #configureLogger()} after a switch changes, since nothing installs + * or removes the handler except that call. This checks the logger's real handler list rather + * than trusting the {@code loggerConfigured} bookkeeping flag alone, since something outside + * this class can remove the handler without ever going through {@link #configureLogger()} -- + * e.g. {@code LogManager.getLogManager().reset()} (routine in embedding scenarios: Spring Boot's + * {@code JavaLoggingSystem}, a Log4j-JUL bridge, a container shutdown hook) or a direct {@code + * removeHandler()} call by unrelated code -- which would otherwise leave the flag stale-true. + * + * @return true when a handler installed by {@link #configureLogger()} is currently attached + */ + public static synchronized boolean isHandlerCurrentlyInstalled() { + return installedHandler != null + && Arrays.asList(SELENIUM_LOGGER.getHandlers()).contains(installedHandler); + } + + /** + * Reports whether a log record from {@code loggerName} at {@code level} would already be + * emitted by the handler {@link #configureLogger()} installs directly on {@code + * org.openqa.selenium} -- that handler and its filter together cover exactly {@link + * Level#FINE}- and {@link Level#CONFIG}-range records from that logger and its descendants, + * whenever that handler is {@linkplain #isHandlerCurrentlyInstalled() currently installed}. A + * caller further up the logger hierarchy (e.g. a handler on the root logger, which receives the + * same record too via normal handler propagation) can use this to avoid printing it a second + * time, without disabling propagation itself -- which would instead silently drop every {@link + * Level#INFO}-and-above {@code org.openqa.selenium} record that caller would otherwise print. + * + * @param loggerName the originating logger's name; {@code null} is never covered + * @param level the record's level + * @return true when {@link #configureLogger()}'s own handler already covers this record + */ + public static boolean isHandledBySeleniumDebugHandler(String loggerName, Level level) { + if (!isHandlerCurrentlyInstalled()) { + return false; + } + boolean withinSeleniumHierarchy = + loggerName != null + && (loggerName.equals("org.openqa.selenium") + || loggerName.startsWith("org.openqa.selenium.")); + return withinSeleniumHierarchy + && level.intValue() >= Level.FINE.intValue() + && level.intValue() < Level.INFO.intValue(); + } + public static boolean isDebugAll() { boolean everything = Boolean.parseBoolean(System.getenv("SE_DEBUG")); if (everything && DEBUG_WARNING_LOGGED.compareAndSet(false, true)) { @@ -59,16 +129,74 @@ public static boolean isDebugAll() { return everything; } - public static void configureLogger() { - if (!isDebugAll() || loggerConfigured) { + /** + * Reflects the current debug switches ({@code -Dselenium.debug=true}, {@code + * -Dselenium.webdriver.verbose=true}, {@code SE_DEBUG}) onto the real {@code org.openqa.selenium} + * logger: raises it to {@link Level#FINE} when it is currently less verbose than {@link + * Level#FINE}; a level already at {@link Level#FINE} or more verbose is left untouched. It also + * attaches a handler Selenium owns, filtered to leave {@link Level#INFO} and above to the + * caller's own handlers so output they already print is never duplicated. Idempotent: repeated + * calls while the switches are unchanged do nothing. Reversible: once every switch is off, the + * next call removes exactly the handler this method installed and restores the logger's level to + * what it was before debugging turned on, only when this method was the one that raised it and + * unless something else changed the level in the meantime -- that change is left alone rather + * than clobbered. This can't distinguish an external override that happens to also set exactly + * {@link Level#FINE}: since JUL has no level-change listener to tell the two apart, that specific + * case still restores the pre-debug level. Safe to call from concurrent driver construction. + * + *

Cross-binding note: the Python binding does the analogous thing at import time (the + * {@code SE_DEBUG} block at the top of {@code py/selenium/webdriver/__init__.py}): when the + * {@code SE_DEBUG} environment variable is set it puts the {@code selenium} logger at + * {@code DEBUG} and attaches an unfiltered {@code StreamHandler} if the logger has none of + * its own. Two deliberate differences here: Java only raises the level when the logger is + * currently less verbose than {@link Level#FINE} (Python sets {@code DEBUG} unconditionally), + * and Java's handler is filtered to records below {@link Level#INFO} so output the caller's + * own handlers already print is never duplicated. + */ + public static synchronized void configureLogger() { + boolean shouldDebug = isDebugging() || isDebugAll(); + if (shouldDebug == loggerConfigured) { return; } - SELENIUM_LOGGER.setLevel(Level.FINE); + if (shouldDebug) { + Level currentLevel = SELENIUM_LOGGER.getLevel(); + // Only raise the level when the logger is currently LESS verbose than FINE (higher + // intValue). A null level inherits the parent's (default INFO), so raising applies then + // too. An already more-verbose level (FINER, FINEST, ALL) is left alone: lowering it + // would make records like W3CHttpResponseCodec's FINER diagnostics unloggable while + // "debugging". This reads the logger's own level, not its effective level -- a + // more-verbose level inherited from a parent while this logger's own level is unset is + // still pinned to FINE, since JUL offers no way to read the effective level. + levelRaisedByDebug = currentLevel == null || currentLevel.intValue() > Level.FINE.intValue(); + if (levelRaisedByDebug) { + previousLevel = currentLevel; + SELENIUM_LOGGER.setLevel(Level.FINE); + } else { + previousLevel = null; + } + + Handler handler = new ConsoleHandler(); + handler.setLevel(Level.FINE); + Filter belowInfo = record -> record.getLevel().intValue() < Level.INFO.intValue(); + handler.setFilter(belowInfo); + SELENIUM_LOGGER.addHandler(handler); + installedHandler = handler; + } else { + SELENIUM_LOGGER.removeHandler(installedHandler); + installedHandler.close(); + installedHandler = null; + // Restore only when Debug itself raised the level AND nothing else changed it since. The + // FINE-equality guard keeps the existing "external override while debugging" protection; + // levelRaisedByDebug additionally covers the case where Debug never touched the level at + // all and so has nothing to restore. + if (levelRaisedByDebug && Level.FINE.equals(SELENIUM_LOGGER.getLevel())) { + SELENIUM_LOGGER.setLevel(previousLevel); + } + levelRaisedByDebug = false; + previousLevel = null; + } - StreamHandler handler = new StreamHandler(System.err, new SimpleFormatter()); - handler.setLevel(Level.FINE); - SELENIUM_LOGGER.addHandler(handler); - loggerConfigured = true; + loggerConfigured = shouldDebug; } } diff --git a/java/src/org/openqa/selenium/remote/RemoteWebDriver.java b/java/src/org/openqa/selenium/remote/RemoteWebDriver.java index 4573903e94daf..8d3442a5acb90 100644 --- a/java/src/org/openqa/selenium/remote/RemoteWebDriver.java +++ b/java/src/org/openqa/selenium/remote/RemoteWebDriver.java @@ -122,8 +122,15 @@ public class RemoteWebDriver PrintsPage, TakesScreenshot { + // Guarantees (JLS 12.4.2) that debug logging is configured before ANY subclass constructor + // body runs -- including argument expressions passed to a subclass's own super(...) call, e.g. + // ChromeDriver/FirefoxDriver's DriverFinder/SeleniumManager discovery, which logs at FINE + // before super(...) is ever reached. configureLogger() is idempotent, so this and the call in + // the canonical instance constructor below are both safe to keep: this one covers logging that + // happens before an instance exists, the other picks up a property changed after this class + // already loaded. static { - org.openqa.selenium.internal.Debug.configureLogger(); + Debug.configureLogger(); } private static final Logger LOG = Logger.getLogger(RemoteWebDriver.class.getName()); @@ -203,14 +210,30 @@ public RemoteWebDriver(CommandExecutor executor, Capabilities capabilities) { this(executor, capabilities, ClientConfig.defaultConfig()); } + /** + * Creates a new driver that runs its commands through the given executor, requesting a new + * session with the given capabilities. Before the session starts, the current Selenium debug + * switches are reflected onto the {@code org.openqa.selenium} logger via {@link + * Debug#configureLogger()}, so a debug property changed at runtime takes effect for every + * driver constructed afterwards. + * + * @param executor the command executor used to communicate with the remote end; must not be + * null + * @param capabilities the capabilities requested for the new session; null is treated as an + * empty set of capabilities + * @param clientConfig the HTTP client configuration for the connection; must not be null + */ public RemoteWebDriver( CommandExecutor executor, Capabilities capabilities, ClientConfig clientConfig) { + // Instance-time (not class-load-time) so a property change made after this class has already + // loaded still takes effect for drivers constructed afterwards. + Debug.configureLogger(); this.clientConfig = Require.nonNull("Client config", clientConfig); this.executor = Require.nonNull("Command executor", executor); this.capabilities = requireNonNullElseGet(capabilities, () -> new ImmutableCapabilities()); try { - startSession(capabilities); + startSession(this.capabilities); } catch (RuntimeException e) { try { quit(); diff --git a/java/test/org/openqa/selenium/devtools/BUILD.bazel b/java/test/org/openqa/selenium/devtools/BUILD.bazel index 7c0b8f68509b9..e1a402a87424e 100644 --- a/java/test/org/openqa/selenium/devtools/BUILD.bazel +++ b/java/test/org/openqa/selenium/devtools/BUILD.bazel @@ -4,6 +4,7 @@ load("//java:defs.bzl", "JUNIT5_DEPS", "java_library", "java_selenium_test_suite SMALL_TESTS = [ "CdpEndpointFinderTest.java", "CdpVersionFinderTest.java", + "ConnectionTest.java", ] java_test_suite( diff --git a/java/test/org/openqa/selenium/devtools/ConnectionTest.java b/java/test/org/openqa/selenium/devtools/ConnectionTest.java new file mode 100644 index 0000000000000..1dd317dfd588c --- /dev/null +++ b/java/test/org/openqa/selenium/devtools/ConnectionTest.java @@ -0,0 +1,116 @@ +// Licensed to the Software Freedom Conservancy (SFC) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The SFC licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +package org.openqa.selenium.devtools; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.util.logging.Level; +import java.util.logging.Logger; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Tag; +import org.junit.jupiter.api.Test; +import org.openqa.selenium.internal.Debug; +import org.openqa.selenium.remote.http.ClientConfig; +import org.openqa.selenium.remote.http.HttpClient; +import org.openqa.selenium.remote.http.HttpRequest; +import org.openqa.selenium.remote.http.HttpResponse; +import org.openqa.selenium.remote.http.Message; +import org.openqa.selenium.remote.http.WebSocket; + +@Tag("UnitTests") +class ConnectionTest { + + private String oldDebugProperty; + private Level oldLoggerLevel; + + @BeforeEach + void storeSystemProperty() { + oldDebugProperty = System.getProperty("selenium.debug"); + oldLoggerLevel = seleniumLogger().getLevel(); + System.clearProperty("selenium.debug"); + } + + @AfterEach + void restoreSystemProperty() { + if (oldDebugProperty != null) { + System.setProperty("selenium.debug", oldDebugProperty); + } else { + System.clearProperty("selenium.debug"); + } + // Re-sync configureLogger's internal state/handler with the now-restored property so a + // handler installed by this test never leaks into the next. + Debug.configureLogger(); + seleniumLogger().setLevel(oldLoggerLevel); + } + + private static Logger seleniumLogger() { + return Logger.getLogger("org.openqa.selenium"); + } + + @Test + void constructingConnectionDirectlyConfiguresTheSeleniumLoggerWhenDebugging() { + // devtools.Connection is sometimes constructed directly rather than through RemoteWebDriver or + // DriverFinder -- neither of which would run in that path to trigger Debug.configureLogger() + // otherwise. No test previously constructed a Connection directly and checked that its own + // constructor actually configures the shared org.openqa.selenium logger. + System.setProperty("selenium.debug", "true"); + + try (Connection connection = + new Connection( + new NoOpHttpClient(), + "ws://localhost:9222/devtools/page/1", + ClientConfig.defaultConfig())) { + assertThat(seleniumLogger().getLevel()).isEqualTo(Level.FINE); + } + } + + /** Minimal real (not mocked) {@link HttpClient} whose socket never talks to the network. */ + private static class NoOpHttpClient implements HttpClient { + @Override + public HttpResponse execute(HttpRequest request) { + throw new UnsupportedOperationException("execute"); + } + + @Override + public WebSocket openSocket(HttpRequest request, WebSocket.Listener listener) { + return new WebSocket() { + @Override + public WebSocket send(Message message) { + return this; + } + + @Override + public void close() {} + }; + } + + @Override + public java.util.concurrent.CompletableFuture> + sendAsyncNative( + java.net.http.HttpRequest request, java.net.http.HttpResponse.BodyHandler handler) { + throw new UnsupportedOperationException("sendAsyncNative"); + } + + @Override + public java.net.http.HttpResponse sendNative( + java.net.http.HttpRequest request, java.net.http.HttpResponse.BodyHandler handler) { + throw new UnsupportedOperationException("sendNative"); + } + } +} diff --git a/java/test/org/openqa/selenium/grid/log/BUILD.bazel b/java/test/org/openqa/selenium/grid/log/BUILD.bazel new file mode 100644 index 0000000000000..9b80074266ceb --- /dev/null +++ b/java/test/org/openqa/selenium/grid/log/BUILD.bazel @@ -0,0 +1,15 @@ +load("@rules_jvm_external//:defs.bzl", "artifact") +load("//java:defs.bzl", "JUNIT5_DEPS", "java_test_suite") + +java_test_suite( + name = "SmallTests", + size = "small", + srcs = glob(["*Test.java"]), + deps = [ + "//java/src/org/openqa/selenium:core", + "//java/src/org/openqa/selenium/grid/config", + "//java/src/org/openqa/selenium/grid/log", + artifact("org.assertj:assertj-core"), + artifact("org.junit.jupiter:junit-jupiter-api"), + ] + JUNIT5_DEPS, +) diff --git a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java new file mode 100644 index 0000000000000..0382dafe0f65b --- /dev/null +++ b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java @@ -0,0 +1,259 @@ +// Licensed to the Software Freedom Conservancy (SFC) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The SFC licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +package org.openqa.selenium.grid.log; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.PrintStream; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Map; +import java.util.UUID; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogManager; +import java.util.logging.LogRecord; +import java.util.logging.Logger; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Tag; +import org.junit.jupiter.api.Test; +import org.openqa.selenium.grid.config.MapConfig; +import org.openqa.selenium.internal.Debug; + +@Tag("UnitTests") +class LoggingOptionsTest { + + private String oldDebugProperty; + // Legacy alias for selenium.debug -- Debug.isDebugging() honors either, so a test JVM that + // happens to have this set externally must not leak into the "no switch" baseline assertions. + private String oldVerboseProperty; + private Level oldSeleniumLoggerLevel; + + @BeforeEach + void storeSystemProperty() { + oldDebugProperty = System.getProperty("selenium.debug"); + oldVerboseProperty = System.getProperty("selenium.webdriver.verbose"); + oldSeleniumLoggerLevel = Logger.getLogger("org.openqa.selenium").getLevel(); + System.clearProperty("selenium.debug"); + System.clearProperty("selenium.webdriver.verbose"); + } + + @AfterEach + void restoreSystemProperty() { + if (oldDebugProperty != null) { + System.setProperty("selenium.debug", oldDebugProperty); + } else { + System.clearProperty("selenium.debug"); + } + if (oldVerboseProperty != null) { + System.setProperty("selenium.webdriver.verbose", oldVerboseProperty); + } else { + System.clearProperty("selenium.webdriver.verbose"); + } + // Reverts whatever configureLogging() may have done to the shared org.openqa.selenium logger + // via Debug.configureLogger() during the test, now that the properties are back to their + // original values. + Debug.configureLogger(); + Logger.getLogger("org.openqa.selenium").setLevel(oldSeleniumLoggerLevel); + } + + @Test + void setLoggingLevelForcesFineWhenSeleniumDebugPropertyIsSet() { + System.setProperty("selenium.debug", "true"); + + String output = captureStderrDuring(() -> new LoggingOptions(emptyConfig()).setLoggingLevel()); + + // Before this change, only the SE_DEBUG environment variable (isDebugAll()) forced Grid's log + // level to FINE; -Dselenium.debug=true had no effect on Grid at all. Grid operators using that + // property must not silently lose Grid diagnostic output now that RemoteWebDriver's + // configureLogger() reacts to it too. + assertThat(output).contains("forcing Grid log level to FINE"); + } + + @Test + void setLoggingLevelDoesNotForceFineWhenNoDebugSwitchIsSet() { + String output = captureStderrDuring(() -> new LoggingOptions(emptyConfig()).setLoggingLevel()); + + assertThat(output).doesNotContain("forcing Grid log level to FINE"); + } + + @Test + void configureLoggingRaisesSeleniumLoggerEvenWithExternalJulConfigSet() { + // configureLogging() early-returns once an external java.util.logging.config.* property is + // detected, handing the rest of logging setup off entirely. Debug.configureLogger() must still + // run before that early return, or Selenium's own FINE-level wire diagnostics stay invisible + // under -Dselenium.debug=true whenever an operator has such a property set. + System.setProperty("selenium.debug", "true"); + String oldConfigFile = System.getProperty("java.util.logging.config.file"); + System.setProperty("java.util.logging.config.file", "does-not-need-to-exist.properties"); + try { + new LoggingOptions(emptyConfig()).configureLogging(); + + assertThat(Logger.getLogger("org.openqa.selenium").getLevel()).isEqualTo(Level.FINE); + } finally { + if (oldConfigFile != null) { + System.setProperty("java.util.logging.config.file", oldConfigFile); + } else { + System.clearProperty("java.util.logging.config.file"); + } + } + } + + @Test + void configureLoggingPreservesDebugHandlerWhenNoExternalJulConfigIsSet() { + // configureLogging() enumerates every registered logger and strips its handlers so Grid's own + // console setup starts from a clean slate. org.openqa.selenium stays registered throughout + // (Debug holds a strong static reference to it), so the handler Debug.configureLogger() just + // installed one line above used to get swept up in that too: removed before configureLogging() + // returned, leaving debug mode silently broken since Debug's bookkeeping has no way to learn + // its handler was removed out from under it. + System.setProperty("selenium.debug", "true"); + + new LoggingOptions(emptyConfig()).configureLogging(); + + Logger seleniumLogger = Logger.getLogger("org.openqa.selenium"); + Handler[] handlers = seleniumLogger.getHandlers(); + assertThat(handlers).hasSize(1); + assertThat(handlers[0].getLevel()).isEqualTo(Level.FINE); + + LogRecord infoRecord = new LogRecord(Level.INFO, "info message"); + LogRecord fineRecord = new LogRecord(Level.FINE, "fine message"); + assertThat(handlers[0].isLoggable(infoRecord)).isFalse(); + assertThat(handlers[0].isLoggable(fineRecord)).isTrue(); + } + + @Test + void configureLoggingDoesNotDuplicateSeleniumDebugRecordsWhenNoLogFileIsConfigured() { + // Debug.configureLogger() (called one line into configureLogging()) installs a handler + // directly on org.openqa.selenium that already prints FINE/CONFIG-range records to stderr -- + // it never disables useParentHandlers, so those same records also propagate up to whatever + // handler(s) configureLogging() itself then attaches to the ROOT logger a few lines later. + // With no log-file configured, getOutputStream() defaults that root handler to System.out (no + // SE_DEBUG here) -- a different JUL handler/stream than Debug's stderr one, but the same + // visible destination in every realistic deployment (Grid's primary real-world usage is + // containerized, where the container log driver merges stdout+stderr into one stream a human + // actually reads), so nothing stopped a FINE record from org.openqa.selenium(.*) printing + // twice, once from each handler. INFO-and-above records must be unaffected -- Debug's own + // handler already excludes those, so they only ever reached Grid's root handler in the first + // place. + System.setProperty("selenium.debug", "true"); + String marker = "duplicate-check-" + UUID.randomUUID(); + + Captured captured = + captureStdOutAndErrDuring( + () -> { + new LoggingOptions(emptyConfig()).configureLogging(); + Logger.getLogger("org.openqa.selenium.grid.log.LoggingOptionsTest").fine(marker); + }); + + // Debug's own handler on org.openqa.selenium must still print it -- unchanged behavior. + assertThat(captured.err()).contains(marker); + // Grid's root handler (defaulting to stdout here) must not ALSO print it. + assertThat(captured.out()).doesNotContain(marker); + } + + @Test + void configureLoggingLetsSeleniumDebugRecordsReachAConfiguredLogFileAlongsideDebugsHandler() + throws IOException { + // A configured log-file is a destination genuinely separate from anything Debug touches -- + // Debug's own handler always targets stderr (java.util.logging.ConsoleHandler's fixed + // target), regardless of Grid's own logging config. Suppressing FINE/CONFIG-range + // org.openqa.selenium records from that file the same way they're suppressed from the + // stdout/stderr default (above) would silently drop them from the operator's chosen sink and + // its plain/structured formatting -- worse than the duplicate this suppression exists to fix. + // Debug's stderr trace legitimately coexists with the file here; both must fire. + System.setProperty("selenium.debug", "true"); + Path logFile = Files.createTempFile("logging-options-test", ".log"); + String marker = "log-file-check-" + UUID.randomUUID(); + try { + String seleniumErr = + captureStderrDuring( + () -> { + new LoggingOptions( + new MapConfig( + Map.of( + "logging", + Map.of("log-file", logFile.toAbsolutePath().toString())))) + .configureLogging(); + Logger.getLogger("org.openqa.selenium.grid.log.LoggingOptionsTest").fine(marker); + }); + + assertThat(seleniumErr).contains(marker); + assertThat(Files.readString(logFile)).contains(marker); + } finally { + for (Handler handler : LogManager.getLogManager().getLogger("").getHandlers()) { + handler.close(); + } + Files.deleteIfExists(logFile); + } + } + + private static MapConfig emptyConfig() { + return new MapConfig(Map.of()); + } + + private static String captureStderrDuring(Runnable action) { + PrintStream originalErr = System.err; + ByteArrayOutputStream captured = new ByteArrayOutputStream(); + try { + System.setErr(new PrintStream(captured)); + action.run(); + } finally { + System.setErr(originalErr); + } + return captured.toString(); + } + + private static Captured captureStdOutAndErrDuring(Runnable action) { + PrintStream originalOut = System.out; + PrintStream originalErr = System.err; + ByteArrayOutputStream capturedOut = new ByteArrayOutputStream(); + ByteArrayOutputStream capturedErr = new ByteArrayOutputStream(); + try { + System.setOut(new PrintStream(capturedOut)); + System.setErr(new PrintStream(capturedErr)); + action.run(); + } finally { + System.setOut(originalOut); + System.setErr(originalErr); + } + return new Captured(capturedOut.toString(), capturedErr.toString()); + } + + /** Plain holder, not a record: this test target still compiles at source level 11. */ + private static class Captured { + private final String out; + private final String err; + + Captured(String out, String err) { + this.out = out; + this.err = err; + } + + String out() { + return out; + } + + String err() { + return err; + } + } +} diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java new file mode 100644 index 0000000000000..5f29e7bb6006f --- /dev/null +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -0,0 +1,331 @@ +// Licensed to the Software Freedom Conservancy (SFC) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The SFC licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +package org.openqa.selenium.internal; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.io.ByteArrayOutputStream; +import java.io.PrintStream; +import java.util.ArrayList; +import java.util.List; +import java.util.UUID; +import java.util.logging.ConsoleHandler; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Tag; +import org.junit.jupiter.api.Test; + +@Tag("UnitTests") +class DebugTest { + + /** + * The shared {@code org.openqa.selenium} logger whose state {@link Debug#configureLogger()} + * manages -- deliberately not this test class's own logger, because the behavior under test + * lives on the shared category. + */ + private static Logger seleniumLogger() { + return Logger.getLogger("org.openqa.selenium"); + } + + private String oldDebugProperty; + private String oldVerboseProperty; + private Level oldLoggerLevel; + + @BeforeEach + void storeSystemProperties() { + oldDebugProperty = System.getProperty("selenium.debug"); + oldVerboseProperty = System.getProperty("selenium.webdriver.verbose"); + oldLoggerLevel = seleniumLogger().getLevel(); + System.clearProperty("selenium.debug"); + System.clearProperty("selenium.webdriver.verbose"); + } + + @AfterEach + void restoreSystemProperties() { + if (oldDebugProperty != null) { + System.setProperty("selenium.debug", oldDebugProperty); + } else { + System.clearProperty("selenium.debug"); + } + if (oldVerboseProperty != null) { + System.setProperty("selenium.webdriver.verbose", oldVerboseProperty); + } else { + System.clearProperty("selenium.webdriver.verbose"); + } + // Re-sync configureLogger's internal state/handler with the now-restored properties so a + // handler installed by one test never leaks into the next. + Debug.configureLogger(); + // A test may have changed the logger's level directly (simulating code other than Debug + // touching it); put it back exactly as found so tests stay isolated regardless of what + // configureLogger()'s own restore logic decided to do. + seleniumLogger().setLevel(oldLoggerLevel); + } + + @Test + void isDebuggingReflectsPropertySetAfterClassLoad() { + assertThat(Debug.isDebugging()).isFalse(); + + System.setProperty("selenium.debug", "true"); + + assertThat(Debug.isDebugging()).isTrue(); + } + + @Test + void isDebuggingHonoursTheLegacyVerboseProperty() { + assertThat(Debug.isDebugging()).isFalse(); + + System.setProperty("selenium.webdriver.verbose", "true"); + + assertThat(Debug.isDebugging()).isTrue(); + } + + @Test + void configureLoggerRaisesSeleniumLoggerToFine() { + System.setProperty("selenium.debug", "true"); + + Debug.configureLogger(); + + assertThat(seleniumLogger().getLevel()).isEqualTo(Level.FINE); + } + + @Test + void configureLoggerDoesNotClobberALevelChangedWhileDebuggingWasOn() { + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + assertThat(seleniumLogger().getLevel()).isEqualTo(Level.FINE); + + // Something other than Debug changes the level while debugging is still on -- e.g. the user's + // own logging config. + seleniumLogger().setLevel(Level.WARNING); + + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + + // The externally-set WARNING must survive. Debug must not clobber it with the level that was + // ambient before IT turned debugging on -- that snapshot is stale the moment anything else + // changes the level in between. + assertThat(seleniumLogger().getLevel()).isEqualTo(Level.WARNING); + } + + @Test + void configureLoggerRestoresPreDebugLevelAndRemovesHandlerWhenTurnedOff() { + Level preDebugLevel = seleniumLogger().getLevel(); + List handlersBeforeDebug = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + + List handlersWhileDebugging = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + handlersWhileDebugging.removeAll(handlersBeforeDebug); + assertThat(handlersWhileDebugging).hasSize(1); + Handler installedHandler = handlersWhileDebugging.get(0); + + // No external override happens in between -- this is the plain turn-on/turn-off round trip. + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + + assertThat(seleniumLogger().getLevel()).isEqualTo(preDebugLevel); + assertThat(seleniumLogger().getHandlers()).doesNotContain(installedHandler); + } + + @Test + void configureLoggerIsIdempotent() { + int before = seleniumLogger().getHandlers().length; + System.setProperty("selenium.debug", "true"); + + for (int i = 0; i < 5; i++) { + Debug.configureLogger(); + } + + assertThat(seleniumLogger().getHandlers().length - before).isEqualTo(1); + } + + @Test + void configureLoggerLeavesUserHandlersAlone() { + Handler userHandler = new ConsoleHandler(); + seleniumLogger().addHandler(userHandler); + try { + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + assertThat(seleniumLogger().getHandlers()).contains(userHandler); + + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + assertThat(seleniumLogger().getHandlers()).contains(userHandler); + } finally { + seleniumLogger().removeHandler(userHandler); + } + } + + @Test + void infoRecordsAreNotDuplicatedWhenDebuggingIsEnabled() { + List userHandlerRecords = new ArrayList<>(); + Handler userHandler = + new Handler() { + @Override + public void publish(LogRecord record) { + userHandlerRecords.add(record); + } + + @Override + public void flush() {} + + @Override + public void close() {} + }; + // Simulates a handler the caller already has attached directly to this logger (e.g. their + // own handler at INFO) that already prints INFO-and-above records on its own. + userHandler.setLevel(Level.INFO); + seleniumLogger().addHandler(userHandler); + + boolean oldUseParentHandlers = seleniumLogger().getUseParentHandlers(); + // Isolate this check to handlers attached directly to org.openqa.selenium. Propagation to the + // JVM's own root logger handler is a separate, legitimate print channel this test isn't + // about, and it would otherwise be indistinguishable from a real duplicate here. + seleniumLogger().setUseParentHandlers(false); + + PrintStream originalErr = System.err; + ByteArrayOutputStream capturedErr = new ByteArrayOutputStream(); + String marker = "duplicate-check-" + UUID.randomUUID(); + try { + System.setErr(new PrintStream(capturedErr)); + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + + seleniumLogger().log(Level.INFO, marker); + for (Handler handler : seleniumLogger().getHandlers()) { + handler.flush(); + } + } finally { + System.setErr(originalErr); + seleniumLogger().setUseParentHandlers(oldUseParentHandlers); + seleniumLogger().removeHandler(userHandler); + } + + // The caller's own handler must still see the record: Selenium never suppresses records for + // handlers it doesn't own. + assertThat(userHandlerRecords).extracting(LogRecord::getMessage).containsExactly(marker); + // Selenium's own handler must not ALSO print it to stderr -- otherwise the exact same line + // the caller's handler just printed would appear a second time, straight from Selenium's own + // console handler. + assertThat(capturedErr.toString()).doesNotContain(marker); + } + + @Test + void configureLoggerDoesNotLowerAnAlreadyMoreVerboseLevel() { + // The application already asked for MORE verbosity than the debug switch provides, e.g. to + // see W3CHttpResponseCodec's FINER response-decoding diagnostics. + seleniumLogger().setLevel(Level.FINER); + + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + // Turning debug on must never make the logger LESS verbose than it already was. + assertThat(seleniumLogger().getLevel()).isEqualTo(Level.FINER); + + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + assertThat(seleniumLogger().getLevel()).isEqualTo(Level.FINER); + } + + @Test + void configureLoggerDoesNotRestoreALevelItNeverChanged() { + seleniumLogger().setLevel(Level.FINER); + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); // debug on, level untouched (already more verbose than FINE) + + // Something else deliberately drops verbosity to FINE while debugging is on. + seleniumLogger().setLevel(Level.FINE); + + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + + // Debug never changed the level (it was already more verbose when debug turned on), so + // turning debug off must not "restore" a pre-debug snapshot it never took either. + assertThat(seleniumLogger().getLevel()).isEqualTo(Level.FINE); + } + + @Test + @SuppressWarnings({"deprecation", "removal"}) + void getDebugLogLevelStillReportsInfoWhileDeprecated() { + System.setProperty("selenium.debug", "true"); + assertThat(Debug.getDebugLogLevel()).isEqualTo(Level.INFO); + + System.clearProperty("selenium.debug"); + assertThat(Debug.getDebugLogLevel()).isEqualTo(Level.FINE); + } + + @Test + void isHandledBySeleniumDebugHandlerReflectsActualHandlerInstallationNotLiveProperty() { + // isHandledBySeleniumDebugHandler() exists so a caller further up the logger hierarchy (e.g. + // Grid's root handler) can tell whether THIS handler will actually also print a given record, + // to avoid a duplicate. That question is about the handler's real, current installation + // state, not the live system property: a property change takes effect only once something + // calls configureLogger() again to react to it, and the two can genuinely diverge for however + // long that takes -- checking the live property instead would answer "yes, handled" the + // instant the property flips, even though the handler that must actually be there to back + // that answer hasn't been installed (or removed) yet. + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + assertThat(Debug.isHandledBySeleniumDebugHandler("org.openqa.selenium", Level.FINE)).isTrue(); + + // The property flips off, but nothing has called configureLogger() again yet -- the handler + // installed above is still attached and will still print a FINE record published right now. + System.clearProperty("selenium.debug"); + assertThat(Debug.isHandledBySeleniumDebugHandler("org.openqa.selenium", Level.FINE)) + .as("the handler installed while debugging was on is still attached and still handling") + .isTrue(); + + // Only once configureLogger() actually reacts does the handler come off, and only then must + // callers stop treating this range as already handled. + Debug.configureLogger(); + assertThat(Debug.isHandledBySeleniumDebugHandler("org.openqa.selenium", Level.FINE)).isFalse(); + } + + @Test + void isHandlerCurrentlyInstalledReflectsExternalHandlerRemoval() { + // isHandlerCurrentlyInstalled() must answer whether Debug's handler is REALLY still attached + // to org.openqa.selenium, not just whether Debug's own bookkeeping thinks it installed one and + // was never told otherwise. Something outside Debug entirely can remove that handler without + // going through configureLogger() -- e.g. LogManager.getLogManager().reset() (routine in + // embedding scenarios: Spring Boot's JavaLoggingSystem, a Log4j-JUL bridge, a container + // shutdown hook) or a direct removeHandler() call by unrelated code -- and Debug has no way to + // be told when that happens. + List handlersBeforeDebug = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + assertThat(Debug.isHandlerCurrentlyInstalled()).isTrue(); + + List handlersWhileDebugging = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + handlersWhileDebugging.removeAll(handlersBeforeDebug); + assertThat(handlersWhileDebugging).hasSize(1); + Handler installedHandler = handlersWhileDebugging.get(0); + + // Simulates the external-actor scenario: something other than Debug removes the handler + // directly, without ever calling configureLogger(). + seleniumLogger().removeHandler(installedHandler); + + assertThat(Debug.isHandlerCurrentlyInstalled()) + .as("the handler was removed out from under Debug's bookkeeping by something else") + .isFalse(); + } +} diff --git a/java/test/org/openqa/selenium/remote/RemoteWebDriverInitializationTest.java b/java/test/org/openqa/selenium/remote/RemoteWebDriverInitializationTest.java index 5759b4f253ea8..25e4291499e5e 100644 --- a/java/test/org/openqa/selenium/remote/RemoteWebDriverInitializationTest.java +++ b/java/test/org/openqa/selenium/remote/RemoteWebDriverInitializationTest.java @@ -41,7 +41,12 @@ import java.time.Duration; import java.util.Map; import java.util.UUID; +import java.util.concurrent.atomic.AtomicReference; +import java.util.logging.Level; +import java.util.logging.Logger; import org.jspecify.annotations.NullMarked; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Tag; import org.junit.jupiter.api.Test; import org.mockito.ArgumentCaptor; @@ -49,6 +54,7 @@ import org.openqa.selenium.ImmutableCapabilities; import org.openqa.selenium.Platform; import org.openqa.selenium.SessionNotCreatedException; +import org.openqa.selenium.internal.Debug; import org.openqa.selenium.remote.http.ClientConfig; import org.openqa.selenium.remote.http.Contents; import org.openqa.selenium.remote.http.HttpClient; @@ -58,7 +64,66 @@ @Tag("UnitTests") class RemoteWebDriverInitializationTest { + /** + * The shared {@code org.openqa.selenium} logger that {@code Debug.configureLogger()} manages -- + * deliberately not this test class's own logger, because the assertion is about the shared + * category's state. + */ + private static Logger seleniumLogger() { + return Logger.getLogger("org.openqa.selenium"); + } + private boolean quitCalled = false; + private String oldDebugProperty; + // Legacy alias for selenium.debug -- Debug.isDebugging() honors either, so a test JVM that + // happens to have this set externally must not leak into the "no switch" baseline assertions. + private String oldVerboseProperty; + private Level oldLoggerLevel; + + @BeforeEach + void storeDebugState() { + oldDebugProperty = System.getProperty("selenium.debug"); + oldVerboseProperty = System.getProperty("selenium.webdriver.verbose"); + oldLoggerLevel = seleniumLogger().getLevel(); + System.clearProperty("selenium.debug"); + System.clearProperty("selenium.webdriver.verbose"); + } + + @AfterEach + void restoreDebugState() { + if (oldDebugProperty != null) { + System.setProperty("selenium.debug", oldDebugProperty); + } else { + System.clearProperty("selenium.debug"); + } + if (oldVerboseProperty != null) { + System.setProperty("selenium.webdriver.verbose", oldVerboseProperty); + } else { + System.clearProperty("selenium.webdriver.verbose"); + } + Debug.configureLogger(); + seleniumLogger().setLevel(oldLoggerLevel); + } + + @Test + void constructingASecondDriverPicksUpADebugPropertyChangedAfterTheFirst() { + // A plain in-memory executor (no mocking framework): answers the single NEW_SESSION command + // each construction issues by echoing the requested capabilities back. + CommandExecutor inMemoryExecutor = command -> echoCapabilities.apply(command); + + // First construction: touches (and, the first time in this JVM, initializes) the class while + // debugging is off -- exercises the static initializer with nothing to react to yet. + new RemoteWebDriver(inMemoryExecutor, new ImmutableCapabilities()); + + System.setProperty("selenium.debug", "true"); + + // Second construction, after the property changed. The class's static initializer already + // ran once and won't run again, so picking this up can only be the canonical constructor's + // own call to Debug.configureLogger(). + new RemoteWebDriver(inMemoryExecutor, new ImmutableCapabilities()); + + assertThat(seleniumLogger().getLevel()).isEqualTo(Level.FINE); + } @Test void testQuitsIfStartSessionFails() { @@ -155,6 +220,29 @@ && singleton(capabilities) assertThat(driver.getSessionId()).isNotNull(); } + @Test + void constructorTreatsNullCapabilitiesAsEmptyCapabilities() { + // Javadoc on the canonical constructor promises "null is treated as an empty set of + // capabilities" -- verify startSession() actually receives the coalesced empty + // ImmutableCapabilities, not the raw null parameter, and that this does not NPE. + // A plain in-memory executor (no mocking framework): records the single NEW_SESSION command + // this construction issues, then answers it by echoing the requested capabilities back. + AtomicReference sentCommand = new AtomicReference<>(); + CommandExecutor executor = + command -> { + sentCommand.set(command); + return echoCapabilities.apply(command); + }; + + RemoteWebDriver driver = new RemoteWebDriver(executor, null); + + assertThat(sentCommand.get().getName()).isEqualTo(DriverCommand.NEW_SESSION); + assertThat(sentCommand.get().getSessionId()).isNull(); + assertThat(sentCommand.get().getParameters().get("capabilities")) + .isEqualTo(singleton(new ImmutableCapabilities())); + assertThat(driver.getSessionId()).isNotNull(); + } + @Test void canHandlePlatformNameCapability() { WebDriverFixture fixture = From ff32eab9e8bebcabd644ef0e1c421e15f945bd96 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 10:26:29 +0300 Subject: [PATCH 02/19] [java][bidi][devtools] Raise the debug-logger switch from direct-constructed Connections BiDi and CDP Connection instances built without going through RemoteWebDriver or DriverFinder (a caller wiring one up directly) never triggered the debug-log-level configuration, so their FINE wire diagnostics stayed governed by whatever level was set last -- or never set at all. Both constructors now call Debug.configureLogger() first, same idempotent pattern DriverFinder.getBinaryPaths() already uses. --- java/src/org/openqa/selenium/bidi/Connection.java | 6 ++++++ java/src/org/openqa/selenium/devtools/Connection.java | 7 +++++++ 2 files changed, 13 insertions(+) diff --git a/java/src/org/openqa/selenium/bidi/Connection.java b/java/src/org/openqa/selenium/bidi/Connection.java index 45376716bec5c..1a8f0f8f46ec4 100644 --- a/java/src/org/openqa/selenium/bidi/Connection.java +++ b/java/src/org/openqa/selenium/bidi/Connection.java @@ -47,6 +47,7 @@ import org.jspecify.annotations.Nullable; import org.openqa.selenium.Beta; import org.openqa.selenium.WebDriverException; +import org.openqa.selenium.internal.Debug; import org.openqa.selenium.internal.Either; import org.openqa.selenium.internal.Require; import org.openqa.selenium.json.Json; @@ -78,6 +79,11 @@ public class Connection implements Closeable { private final AtomicBoolean underlyingSocketClosed = new AtomicBoolean(false); public Connection(HttpClient client, String url) { + // Reflect the current debug switches before this connection starts logging its wire + // diagnostics at FINE -- callers that construct a Connection directly (never going through + // RemoteWebDriver or DriverFinder) would otherwise never trigger the raise. Idempotent and + // cheap, same pattern as DriverFinder.getBinaryPaths(). + Debug.configureLogger(); Require.nonNull("HTTP client", client); Require.nonNull("URL to connect to", url); diff --git a/java/src/org/openqa/selenium/devtools/Connection.java b/java/src/org/openqa/selenium/devtools/Connection.java index 9a91094d85b8f..284184679d0d1 100644 --- a/java/src/org/openqa/selenium/devtools/Connection.java +++ b/java/src/org/openqa/selenium/devtools/Connection.java @@ -51,6 +51,7 @@ import org.jspecify.annotations.Nullable; import org.openqa.selenium.WebDriverException; import org.openqa.selenium.devtools.idealized.target.model.SessionID; +import org.openqa.selenium.internal.Debug; import org.openqa.selenium.internal.Either; import org.openqa.selenium.internal.Require; import org.openqa.selenium.json.Json; @@ -92,6 +93,12 @@ public Connection(HttpClient client, String url) { } public Connection(HttpClient client, String url, ClientConfig clientConfig) { + // Reflect the current debug switches before this connection starts logging its wire + // diagnostics at FINE -- callers that construct a Connection directly (never going through + // RemoteWebDriver or DriverFinder) would otherwise never trigger the raise. Idempotent and + // cheap, same pattern as DriverFinder.getBinaryPaths(). The deprecated 2-arg constructor + // delegates here, so this single call point covers both. + Debug.configureLogger(); this.client = Require.nonNull("HTTP client", client); this.wsConfig = wsClientConfig(clientConfig, url); this.socket = this.client.openSocket(new HttpRequest(GET, wsConfig.baseUri()), new Listener()); From a31a75aab07b10179c5511e611193269f11ffde8 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 11:06:42 +0300 Subject: [PATCH 03/19] [java][bidi][devtools] Document the debug-logging Connection constructors Qodo review findings 1 and 2 on #17841: the BiDi and CDP Connection constructors modified to call Debug.configureLogger() had no Javadoc, so API consumers had no way to discover the parameters or the debug- logging side effect. Adds Javadoc mirroring RemoteWebDriver's canonical-constructor doc block in this same branch. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01LfxetzdJtF13MCJDRNQwgG --- java/src/org/openqa/selenium/bidi/Connection.java | 9 +++++++++ .../src/org/openqa/selenium/devtools/Connection.java | 12 ++++++++++++ 2 files changed, 21 insertions(+) diff --git a/java/src/org/openqa/selenium/bidi/Connection.java b/java/src/org/openqa/selenium/bidi/Connection.java index 1a8f0f8f46ec4..005178d276e6d 100644 --- a/java/src/org/openqa/selenium/bidi/Connection.java +++ b/java/src/org/openqa/selenium/bidi/Connection.java @@ -78,6 +78,15 @@ public class Connection implements Closeable { private final WebSocket socket; private final AtomicBoolean underlyingSocketClosed = new AtomicBoolean(false); + /** + * Creates a new BiDi connection to the given URL using the given HTTP client. Before the socket + * opens, the current Selenium debug switches are reflected onto the {@code org.openqa.selenium} + * logger via {@link Debug#configureLogger()}, so connections constructed directly (bypassing + * {@code RemoteWebDriver}/{@code DriverFinder}) still honor {@code -Dselenium.debug} and friends. + * + * @param client the HTTP client used to open the underlying web socket; must not be null + * @param url the URL to open the web socket connection to; must not be null + */ public Connection(HttpClient client, String url) { // Reflect the current debug switches before this connection starts logging its wire // diagnostics at FINE -- callers that construct a Connection directly (never going through diff --git a/java/src/org/openqa/selenium/devtools/Connection.java b/java/src/org/openqa/selenium/devtools/Connection.java index 284184679d0d1..bc4f25f6ecfd5 100644 --- a/java/src/org/openqa/selenium/devtools/Connection.java +++ b/java/src/org/openqa/selenium/devtools/Connection.java @@ -92,6 +92,18 @@ public Connection(HttpClient client, String url) { this(client, url, ClientConfig.defaultConfig()); } + /** + * Creates a new CDP connection to the given URL using the given HTTP client and client + * configuration. Before the socket opens, the current Selenium debug switches are reflected onto + * the {@code org.openqa.selenium} logger via {@link Debug#configureLogger()}, so connections + * constructed directly (bypassing {@code RemoteWebDriver}/{@code DriverFinder}) still honor + * {@code -Dselenium.debug} and friends. The deprecated 2-arg constructor delegates here, so this + * single call point covers both. + * + * @param client the HTTP client used to open the underlying web socket; must not be null + * @param url the URL to open the web socket connection to + * @param clientConfig the client configuration to use when opening the connection + */ public Connection(HttpClient client, String url, ClientConfig clientConfig) { // Reflect the current debug switches before this connection starts logging its wire // diagnostics at FINE -- callers that construct a Connection directly (never going through From 4296a51e102fd6441932e68af3c09b37d058fc09 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 11:06:58 +0300 Subject: [PATCH 04/19] [java] Repair Debug's externally-removed handler; scope LoggingOptions' reset exemption to it Fixes Qodo review findings 3-6 on #17841: - Debug.configureLogger()'s fast-path used to key solely on shouldDebug == loggerConfigured, so if something outside this class removed the installed handler while debugging stayed on (a JUL LogManager.reset(), or unrelated removeHandler() code), the handler was never reinstalled. The fast-path now also consults isHandlerCurrentlyInstalled(), and the level-raising bookkeeping only runs on a genuine off->on transition so a repair-only call can't corrupt the snapshot turning debug off later needs. The turn-off path also guards against installedHandler already being null, since Logger.removeHandler(null) throws NPE. - LoggingOptions.configureLogging()'s handler-reset loop used to skip org.openqa.selenium unconditionally, preserving any handler attached there, not just the one Debug.configureLogger() installed. Adds Debug.isOwnHandler(Handler) so the loop can strip everything else and keep only Debug's own. - Adds missing Javadoc to configureLogging(). DebugTest and LoggingOptionsTest each gain a regression test exercising the fixed behavior, watched red against the prior code before the fix landed. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01LfxetzdJtF13MCJDRNQwgG --- .../selenium/grid/log/LoggingOptions.java | 52 ++++--- .../org/openqa/selenium/internal/Debug.java | 130 +++++++++++------- .../selenium/grid/log/LoggingOptionsTest.java | 53 +++++++ .../openqa/selenium/internal/DebugTest.java | 37 ++++- 4 files changed, 205 insertions(+), 67 deletions(-) diff --git a/java/src/org/openqa/selenium/grid/log/LoggingOptions.java b/java/src/org/openqa/selenium/grid/log/LoggingOptions.java index b9158dc7fc664..a227c4d4e77f8 100644 --- a/java/src/org/openqa/selenium/grid/log/LoggingOptions.java +++ b/java/src/org/openqa/selenium/grid/log/LoggingOptions.java @@ -87,11 +87,11 @@ public String getLogEncoding() { } /** - * Resolves the Grid log level from the {@code log-level} entry of the logging config section - * and stores it for {@link #configureLogging()}. Any active Selenium debug switch ({@code - * SE_DEBUG}, {@code -Dselenium.debug=true}, {@code -Dselenium.webdriver.verbose=true}) - * overrides the configured value and forces {@link Level#FINE}. An unparseable configured - * value falls back to the default ({@code INFO}). + * Resolves the Grid log level from the {@code log-level} entry of the logging config section and + * stores it for {@link #configureLogging()}. Any active Selenium debug switch ({@code SE_DEBUG}, + * {@code -Dselenium.debug=true}, {@code -Dselenium.webdriver.verbose=true}) overrides the + * configured value and forces {@link Level#FINE}. An unparseable configured value falls back to + * the default ({@code INFO}). * * @return this instance, for method chaining */ @@ -134,6 +134,15 @@ public Tracer getTracer() { return OpenTelemetryTracer.getInstance(); } + /** + * Configures logging for the Grid, wiring up Grid's own log handlers and, before doing so, + * reflecting the current Selenium debug switches onto the {@code org.openqa.selenium} logger via + * {@link Debug#configureLogger()}. Returns early without changing anything if logging is disabled + * ({@code enable} is {@code false}) or if an external {@code java.util.logging.config} class/file + * is configured, in which case that configuration takes priority. Otherwise, every other + * registered logger has its handlers stripped to start from a clean slate before Grid's root + * handlers are installed. + */ public void configureLogging() { if (!config.getBool(LOGGING_SECTION, "enable").orElse(DEFAULT_CONFIGURE_LOGGING)) { return; @@ -157,7 +166,8 @@ public void configureLogging() { return; } - // Remove all handlers from existing loggers, except org.openqa.selenium: Debug.configureLogger() + // Remove all handlers from existing loggers, except org.openqa.selenium: + // Debug.configureLogger() // above may have just installed a handler there for debug-mode output, and this loop would // otherwise strip it moments later (Debug holds a strong static reference so that logger stays // registered here too). Debug's own installed-handler bookkeeping has no way to learn a handler @@ -167,12 +177,18 @@ public void configureLogging() { Enumeration names = logManager.getLoggerNames(); while (names.hasMoreElements()) { String name = names.nextElement(); - if ("org.openqa.selenium".equals(name)) { + Logger logger = logManager.getLogger(name); + if (logger == null) { continue; } - Logger logger = logManager.getLogger(name); - if (logger == null) { + if ("org.openqa.selenium".equals(name)) { + // Strip everything except the handler Debug.configureLogger() installed above -- an + // unrelated handler some other code attached to this logger must still be reset here, + // same as on any other logger; only Debug's own handler is exempt. + Arrays.stream(logger.getHandlers()) + .filter(handler -> !Debug.isOwnHandler(handler)) + .forEach(logger::removeHandler); continue; } @@ -207,16 +223,16 @@ public void configureLogging() { * Records that Debug.configureLogger()'s own handler on {@code org.openqa.selenium} already * prints (FINE/CONFIG-range records from that logger or a descendant, while its handler is * installed) must not also print through this root handler, PROVIDED this root handler's - * destination is the one Debug's handler also writes to -- that handler's own - * useParentHandlers is never disabled, so the same record reaches both. That's only true when - * no {@code log-file} is configured: {@link #getOutputStream()} then defaults this handler to - * {@code System.out}/{@code System.err}, the same visible destination as Debug's own {@code + * destination is the one Debug's handler also writes to -- that handler's own useParentHandlers + * is never disabled, so the same record reaches both. That's only true when no {@code log-file} + * is configured: {@link #getOutputStream()} then defaults this handler to {@code + * System.out}/{@code System.err}, the same visible destination as Debug's own {@code * ConsoleHandler} (fixed to {@code System.err}) in every realistic deployment. A configured - * log-file is a genuinely separate destination Debug never writes to, so suppressing there - * would silently drop the record from the operator's chosen sink instead of de-duplicating it - * -- worse than the problem this filter exists to solve. INFO-and-above {@code - * org.openqa.selenium} records, and everything from every other logger, are untouched either - * way: Debug's handler never covered those in the first place. + * log-file is a genuinely separate destination Debug never writes to, so suppressing there would + * silently drop the record from the operator's chosen sink instead of de-duplicating it -- worse + * than the problem this filter exists to solve. INFO-and-above {@code org.openqa.selenium} + * records, and everything from every other logger, are untouched either way: Debug's handler + * never covered those in the first place. */ private Filter rootHandlerFilter() { boolean logFileConfigured = config.get(LOGGING_SECTION, "log-file").isPresent(); diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index ee5846d1a4877..f62b1b128b71f 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -41,8 +41,8 @@ private Debug() { } /** - * Reports whether Selenium debug logging has been requested via the {@code selenium.debug} or - * the legacy {@code selenium.webdriver.verbose} system property. Read live on every call, so a + * Reports whether Selenium debug logging has been requested via the {@code selenium.debug} or the + * legacy {@code selenium.webdriver.verbose} system property. Read live on every call, so a * property change made at runtime is reflected immediately. * * @return true when either the {@code selenium.debug} or the {@code selenium.webdriver.verbose} @@ -71,16 +71,16 @@ public static Level getDebugLogLevel() { } /** - * Reports whether {@link #configureLogger()}'s handler is attached to {@code - * org.openqa.selenium} right now. Unlike {@link #isDebugging()} or {@link #isDebugAll()}, which - * read the live system property/environment variable, this reflects the handler's actual, - * current installation state -- the two can genuinely diverge for however long it takes some - * caller to next invoke {@link #configureLogger()} after a switch changes, since nothing installs - * or removes the handler except that call. This checks the logger's real handler list rather - * than trusting the {@code loggerConfigured} bookkeeping flag alone, since something outside - * this class can remove the handler without ever going through {@link #configureLogger()} -- - * e.g. {@code LogManager.getLogManager().reset()} (routine in embedding scenarios: Spring Boot's - * {@code JavaLoggingSystem}, a Log4j-JUL bridge, a container shutdown hook) or a direct {@code + * Reports whether {@link #configureLogger()}'s handler is attached to {@code org.openqa.selenium} + * right now. Unlike {@link #isDebugging()} or {@link #isDebugAll()}, which read the live system + * property/environment variable, this reflects the handler's actual, current installation state + * -- the two can genuinely diverge for however long it takes some caller to next invoke {@link + * #configureLogger()} after a switch changes, since nothing installs or removes the handler + * except that call. This checks the logger's real handler list rather than trusting the {@code + * loggerConfigured} bookkeeping flag alone, since something outside this class can remove the + * handler without ever going through {@link #configureLogger()} -- e.g. {@code + * LogManager.getLogManager().reset()} (routine in embedding scenarios: Spring Boot's {@code + * JavaLoggingSystem}, a Log4j-JUL bridge, a container shutdown hook) or a direct {@code * removeHandler()} call by unrelated code -- which would otherwise leave the flag stale-true. * * @return true when a handler installed by {@link #configureLogger()} is currently attached @@ -91,15 +91,30 @@ public static synchronized boolean isHandlerCurrentlyInstalled() { } /** - * Reports whether a log record from {@code loggerName} at {@code level} would already be - * emitted by the handler {@link #configureLogger()} installs directly on {@code - * org.openqa.selenium} -- that handler and its filter together cover exactly {@link - * Level#FINE}- and {@link Level#CONFIG}-range records from that logger and its descendants, - * whenever that handler is {@linkplain #isHandlerCurrentlyInstalled() currently installed}. A - * caller further up the logger hierarchy (e.g. a handler on the root logger, which receives the - * same record too via normal handler propagation) can use this to avoid printing it a second - * time, without disabling propagation itself -- which would instead silently drop every {@link - * Level#INFO}-and-above {@code org.openqa.selenium} record that caller would otherwise print. + * Reports whether {@code handler} is specifically the one {@link #configureLogger()} installed on + * {@code org.openqa.selenium} -- not merely whether some handler exists there. A caller that + * needs to strip handlers from that logger down to a clean slate (e.g. Grid's logging setup) must + * preserve only Debug's own handler, not every handler that happens to be attached to that + * logger; this lets such a caller identify exactly the one to keep without this class exposing + * the field itself. + * + * @param handler the handler to check; {@code null} is never Debug's own + * @return true when {@code handler} is the exact instance {@link #configureLogger()} installed + */ + public static synchronized boolean isOwnHandler(Handler handler) { + return handler != null && handler == installedHandler; + } + + /** + * Reports whether a log record from {@code loggerName} at {@code level} would already be emitted + * by the handler {@link #configureLogger()} installs directly on {@code org.openqa.selenium} -- + * that handler and its filter together cover exactly {@link Level#FINE}- and {@link + * Level#CONFIG}-range records from that logger and its descendants, whenever that handler is + * {@linkplain #isHandlerCurrentlyInstalled() currently installed}. A caller further up the logger + * hierarchy (e.g. a handler on the root logger, which receives the same record too via normal + * handler propagation) can use this to avoid printing it a second time, without disabling + * propagation itself -- which would instead silently drop every {@link Level#INFO}-and-above + * {@code org.openqa.selenium} record that caller would otherwise print. * * @param loggerName the originating logger's name; {@code null} is never covered * @param level the record's level @@ -144,38 +159,54 @@ public static boolean isDebugAll() { * {@link Level#FINE}: since JUL has no level-change listener to tell the two apart, that specific * case still restores the pre-debug level. Safe to call from concurrent driver construction. * - *

Cross-binding note: the Python binding does the analogous thing at import time (the - * {@code SE_DEBUG} block at the top of {@code py/selenium/webdriver/__init__.py}): when the - * {@code SE_DEBUG} environment variable is set it puts the {@code selenium} logger at - * {@code DEBUG} and attaches an unfiltered {@code StreamHandler} if the logger has none of - * its own. Two deliberate differences here: Java only raises the level when the logger is - * currently less verbose than {@link Level#FINE} (Python sets {@code DEBUG} unconditionally), - * and Java's handler is filtered to records below {@link Level#INFO} so output the caller's - * own handlers already print is never duplicated. + *

Cross-binding note: the Python binding does the analogous thing at import time (the {@code + * SE_DEBUG} block at the top of {@code py/selenium/webdriver/__init__.py}): when the {@code + * SE_DEBUG} environment variable is set it puts the {@code selenium} logger at {@code DEBUG} and + * attaches an unfiltered {@code StreamHandler} if the logger has none of its own. Two deliberate + * differences here: Java only raises the level when the logger is currently less verbose than + * {@link Level#FINE} (Python sets {@code DEBUG} unconditionally), and Java's handler is filtered + * to records below {@link Level#INFO} so output the caller's own handlers already print is never + * duplicated. */ public static synchronized void configureLogger() { boolean shouldDebug = isDebugging() || isDebugAll(); - if (shouldDebug == loggerConfigured) { + // When shouldDebug is on and already configured, only skip if the handler this method + // installed is still actually attached -- something outside this class (e.g. a LogManager + // reset, or unrelated code calling removeHandler() directly) can remove it without ever + // going through configureLogger(), and that divergence must be repaired here rather than + // silently left until the debug switch itself changes. + if (shouldDebug == loggerConfigured && (!shouldDebug || isHandlerCurrentlyInstalled())) { return; } if (shouldDebug) { - Level currentLevel = SELENIUM_LOGGER.getLevel(); - // Only raise the level when the logger is currently LESS verbose than FINE (higher - // intValue). A null level inherits the parent's (default INFO), so raising applies then - // too. An already more-verbose level (FINER, FINEST, ALL) is left alone: lowering it - // would make records like W3CHttpResponseCodec's FINER diagnostics unloggable while - // "debugging". This reads the logger's own level, not its effective level -- a - // more-verbose level inherited from a parent while this logger's own level is unset is - // still pinned to FINE, since JUL offers no way to read the effective level. - levelRaisedByDebug = currentLevel == null || currentLevel.intValue() > Level.FINE.intValue(); - if (levelRaisedByDebug) { - previousLevel = currentLevel; - SELENIUM_LOGGER.setLevel(Level.FINE); - } else { - previousLevel = null; + // Only run the level-raising bookkeeping on a genuine off->on transition. A call that + // reaches here merely to repair a missing handler (loggerConfigured already true) must not + // re-run this: doing so would overwrite levelRaisedByDebug/previousLevel with whatever the + // level happens to be right now, corrupting the snapshot that turning debug off later needs + // to restore the correct pre-debug level. + if (!loggerConfigured) { + Level currentLevel = SELENIUM_LOGGER.getLevel(); + // Only raise the level when the logger is currently LESS verbose than FINE (higher + // intValue). A null level inherits the parent's (default INFO), so raising applies then + // too. An already more-verbose level (FINER, FINEST, ALL) is left alone: lowering it + // would make records like W3CHttpResponseCodec's FINER diagnostics unloggable while + // "debugging". This reads the logger's own level, not its effective level -- a + // more-verbose level inherited from a parent while this logger's own level is unset is + // still pinned to FINE, since JUL offers no way to read the effective level. + levelRaisedByDebug = + currentLevel == null || currentLevel.intValue() > Level.FINE.intValue(); + if (levelRaisedByDebug) { + previousLevel = currentLevel; + SELENIUM_LOGGER.setLevel(Level.FINE); + } else { + previousLevel = null; + } } + // Runs unconditionally whenever shouldDebug is true and we reach this point -- both on a + // genuine turn-on and on a handler-repair call -- since that's the actual state that needs + // fixing in the repair case. Handler handler = new ConsoleHandler(); handler.setLevel(Level.FINE); Filter belowInfo = record -> record.getLevel().intValue() < Level.INFO.intValue(); @@ -183,9 +214,14 @@ public static synchronized void configureLogger() { SELENIUM_LOGGER.addHandler(handler); installedHandler = handler; } else { - SELENIUM_LOGGER.removeHandler(installedHandler); - installedHandler.close(); - installedHandler = null; + // installedHandler can already be null here if it was removed externally and debugging + // turned off before any repair call ever ran -- Logger.removeHandler(null) throws NPE per + // its javadoc, so guard against that. + if (installedHandler != null) { + SELENIUM_LOGGER.removeHandler(installedHandler); + installedHandler.close(); + installedHandler = null; + } // Restore only when Debug itself raised the level AND nothing else changed it since. The // FINE-equality guard keeps the existing "external override while debugging" protection; // levelRaisedByDebug additionally covers the case where Debug never touched the level at diff --git a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java index 0382dafe0f65b..c72e4dd949e3e 100644 --- a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java +++ b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java @@ -24,8 +24,12 @@ import java.io.PrintStream; import java.nio.file.Files; import java.nio.file.Path; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.List; import java.util.Map; import java.util.UUID; +import java.util.logging.ConsoleHandler; import java.util.logging.Handler; import java.util.logging.Level; import java.util.logging.LogManager; @@ -140,6 +144,29 @@ void configureLoggingPreservesDebugHandlerWhenNoExternalJulConfigIsSet() { assertThat(handlers[0].isLoggable(fineRecord)).isTrue(); } + @Test + void configureLoggingStripsUnrelatedHandlersFromSeleniumLoggerButKeepsDebugsOwn() { + // The "org.openqa.selenium" exemption in configureLogging()'s handler-reset loop exists only + // to preserve the handler Debug.configureLogger() installs -- not to preserve every handler on + // that logger unconditionally. An unrelated handler some other code attached there must still + // be stripped, same as on any other logger. + System.setProperty("selenium.debug", "true"); + Logger seleniumLogger = Logger.getLogger("org.openqa.selenium"); + Handler unrelatedHandler = new ConsoleHandler(); + seleniumLogger.addHandler(unrelatedHandler); + try { + new LoggingOptions(emptyConfig()).configureLogging(); + + Handler[] handlersAfter = seleniumLogger.getHandlers(); + assertThat(handlersAfter).doesNotContain(unrelatedHandler); + assertThat(handlersAfter).hasSize(1); + assertThat(handlersAfter[0].getLevel()).isEqualTo(Level.FINE); + assertThat(Debug.isOwnHandler(handlersAfter[0])).isTrue(); + } finally { + seleniumLogger.removeHandler(unrelatedHandler); + } + } + @Test void configureLoggingDoesNotDuplicateSeleniumDebugRecordsWhenNoLogFileIsConfigured() { // Debug.configureLogger() (called one line into configureLogging()) installs a handler @@ -206,6 +233,24 @@ void configureLoggingLetsSeleniumDebugRecordsReachAConfiguredLogFileAlongsideDeb } } + @Test + void captureStdOutAndErrDuringDoesNotLeakRootLoggerHandlers() { + // configureLogging() installs root-logger handlers bound to whatever System.out/err are AT + // THAT MOMENT (via getOutputStream()). If the capture helper only swaps the streams back + // afterward without also removing those handlers, they keep writing into the now-discarded + // ByteArrayOutputStream instead of the real console, and pollute later tests/output in the + // same JVM. + System.setProperty("selenium.debug", "true"); + Logger rootLogger = LogManager.getLogManager().getLogger(""); + List handlersBefore = List.of(rootLogger.getHandlers()); + + captureStdOutAndErrDuring(() -> new LoggingOptions(emptyConfig()).configureLogging()); + + List leakedHandlers = new ArrayList<>(List.of(rootLogger.getHandlers())); + leakedHandlers.removeAll(handlersBefore); + assertThat(leakedHandlers).isEmpty(); + } + private static MapConfig emptyConfig() { return new MapConfig(Map.of()); } @@ -227,6 +272,8 @@ private static Captured captureStdOutAndErrDuring(Runnable action) { PrintStream originalErr = System.err; ByteArrayOutputStream capturedOut = new ByteArrayOutputStream(); ByteArrayOutputStream capturedErr = new ByteArrayOutputStream(); + Logger rootLogger = LogManager.getLogManager().getLogger(""); + Handler[] handlersBefore = rootLogger.getHandlers(); try { System.setOut(new PrintStream(capturedOut)); System.setErr(new PrintStream(capturedErr)); @@ -234,6 +281,12 @@ private static Captured captureStdOutAndErrDuring(Runnable action) { } finally { System.setOut(originalOut); System.setErr(originalErr); + for (Handler handler : rootLogger.getHandlers()) { + if (!Arrays.asList(handlersBefore).contains(handler)) { + rootLogger.removeHandler(handler); + handler.close(); + } + } } return new Captured(capturedOut.toString(), capturedErr.toString()); } diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java index 5f29e7bb6006f..ca6632e058deb 100644 --- a/java/test/org/openqa/selenium/internal/DebugTest.java +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -39,8 +39,8 @@ class DebugTest { /** * The shared {@code org.openqa.selenium} logger whose state {@link Debug#configureLogger()} - * manages -- deliberately not this test class's own logger, because the behavior under test - * lives on the shared category. + * manages -- deliberately not this test class's own logger, because the behavior under test lives + * on the shared category. */ private static Logger seleniumLogger() { return Logger.getLogger("org.openqa.selenium"); @@ -300,6 +300,39 @@ void isHandledBySeleniumDebugHandlerReflectsActualHandlerInstallationNotLiveProp assertThat(Debug.isHandledBySeleniumDebugHandler("org.openqa.selenium", Level.FINE)).isFalse(); } + @Test + void configureLoggerRepairsAnExternallyRemovedHandlerWithoutCorruptingRestoreBookkeeping() { + Level preDebugLevel = seleniumLogger().getLevel(); + List handlersBeforeDebug = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + + List handlersWhileDebugging = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + handlersWhileDebugging.removeAll(handlersBeforeDebug); + assertThat(handlersWhileDebugging).hasSize(1); + Handler installedHandler = handlersWhileDebugging.get(0); + + // Something outside Debug removes the handler directly while debugging stays on -- e.g. + // LogManager.getLogManager().reset() or a direct removeHandler() call by unrelated code. + seleniumLogger().removeHandler(installedHandler); + assertThat(Debug.isHandlerCurrentlyInstalled()).isFalse(); + + // The property is unchanged (still true) -- a naive fast-path keyed only on + // shouldDebug == loggerConfigured would return early here and never repair the handler. + Debug.configureLogger(); + assertThat(Debug.isHandlerCurrentlyInstalled()) + .as("the repair call must reinstall a handler even though the debug switch never changed") + .isTrue(); + + // Turning debug back off after the repair call must still restore the ORIGINAL pre-debug + // level -- proving the repair call didn't re-run the level-raising bookkeeping and corrupt + // levelRaisedByDebug/previousLevel. + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + assertThat(seleniumLogger().getLevel()).isEqualTo(preDebugLevel); + } + @Test void isHandlerCurrentlyInstalledReflectsExternalHandlerRemoval() { // isHandlerCurrentlyInstalled() must answer whether Debug's handler is REALLY still attached From 072512c12c7641f5debcf72c544ae7a796cbbff9 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 11:26:56 +0300 Subject: [PATCH 05/19] [java] Decide Debug's level raise off the effective level, not just its own Qodo review finding on #17841 (comment 3672251850): configureLogger() treated a null own level on org.openqa.selenium as always needing a raise to FINE, even when a parent logger already had an explicit, more-verbose level (e.g. FINER) -- silently clobbering inherited verbosity down to FINE. Adds a small effectiveLevel() helper that walks the logger's parent chain to the first non-null level (falling back to Level.INFO), and uses that instead of the logger's own level to decide whether a raise is needed. What gets snapshotted/restored on turn-off is still the logger's own (possibly null) level, unchanged. Fixing this surfaced a real order-dependent brittleness in LoggingOptionsTest#configureLoggingRaisesSeleniumLoggerEvenWithExternalJulConfigSet: it asserted the logger's own explicit level was FINE, which no longer holds once an earlier test in the same JVM already left an ancestor logger (the root logger, via this same configureLogging() path) at FINE -- correctly, there's nothing left to raise. Updated the assertion to check effective loggability, which is what the test was actually meant to prove. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01LfxetzdJtF13MCJDRNQwgG --- .../org/openqa/selenium/internal/Debug.java | 39 ++++++++++++++----- .../selenium/grid/log/LoggingOptionsTest.java | 8 +++- .../openqa/selenium/internal/DebugTest.java | 30 ++++++++++++++ 3 files changed, 67 insertions(+), 10 deletions(-) diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index f62b1b128b71f..428f9875a3656 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -144,6 +144,26 @@ public static boolean isDebugAll() { return everything; } + /** + * Computes {@code logger}'s effective level: its own level if set, otherwise the first non-null + * level found walking up its {@link Logger#getParent()} chain, falling back to {@link Level#INFO} + * (JUL's own root default) if none is ever set. {@link Logger} has no single built-in method for + * this, but walking the parent chain is how the JVM itself resolves it internally when deciding + * whether a record is loggable. + * + * @param logger the logger to compute the effective level of + * @return the effective level; never {@code null} + */ + private static Level effectiveLevel(Logger logger) { + for (Logger current = logger; current != null; current = current.getParent()) { + Level level = current.getLevel(); + if (level != null) { + return level; + } + } + return Level.INFO; + } + /** * Reflects the current debug switches ({@code -Dselenium.debug=true}, {@code * -Dselenium.webdriver.verbose=true}, {@code SE_DEBUG}) onto the real {@code org.openqa.selenium} @@ -186,16 +206,17 @@ public static synchronized void configureLogger() { // level happens to be right now, corrupting the snapshot that turning debug off later needs // to restore the correct pre-debug level. if (!loggerConfigured) { + // Only raise the level when the logger's EFFECTIVE level is currently LESS verbose than + // FINE (higher intValue). A more-verbose effective level (FINER, FINEST, ALL) is left + // alone: lowering it would make records like W3CHttpResponseCodec's FINER diagnostics + // unloggable while "debugging". This decides off the effective level rather than the + // logger's own (possibly null/inherited) level -- a null own level with a more-verbose + // level set on a parent logger already means FINER-or-better records are loggable right + // now, and forcing this logger's own level to FINE would clobber that inherited + // verbosity. What gets snapshotted/restored is still the logger's own level exactly as + // before; only the raise/no-raise decision changes. Level currentLevel = SELENIUM_LOGGER.getLevel(); - // Only raise the level when the logger is currently LESS verbose than FINE (higher - // intValue). A null level inherits the parent's (default INFO), so raising applies then - // too. An already more-verbose level (FINER, FINEST, ALL) is left alone: lowering it - // would make records like W3CHttpResponseCodec's FINER diagnostics unloggable while - // "debugging". This reads the logger's own level, not its effective level -- a - // more-verbose level inherited from a parent while this logger's own level is unset is - // still pinned to FINE, since JUL offers no way to read the effective level. - levelRaisedByDebug = - currentLevel == null || currentLevel.intValue() > Level.FINE.intValue(); + levelRaisedByDebug = effectiveLevel(SELENIUM_LOGGER).intValue() > Level.FINE.intValue(); if (levelRaisedByDebug) { previousLevel = currentLevel; SELENIUM_LOGGER.setLevel(Level.FINE); diff --git a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java index c72e4dd949e3e..0f6ca0c11007c 100644 --- a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java +++ b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java @@ -111,7 +111,13 @@ void configureLoggingRaisesSeleniumLoggerEvenWithExternalJulConfigSet() { try { new LoggingOptions(emptyConfig()).configureLogging(); - assertThat(Logger.getLogger("org.openqa.selenium").getLevel()).isEqualTo(Level.FINE); + // Checks effective loggability rather than the logger's own explicit level: Debug now + // decides whether to raise off the EFFECTIVE level (Debug.java's effectiveLevel()), so when + // an earlier test already left an ancestor logger (e.g. the root logger, via this same + // configureLogging() path) at FINE-or-more-verbose, org.openqa.selenium's own level + // correctly stays untouched -- there's nothing left to raise. Either way, what actually + // matters -- Selenium's FINE-level wire diagnostics being visible -- must hold. + assertThat(Logger.getLogger("org.openqa.selenium").isLoggable(Level.FINE)).isTrue(); } finally { if (oldConfigFile != null) { System.setProperty("java.util.logging.config.file", oldConfigFile); diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java index ca6632e058deb..0397bcd798fb3 100644 --- a/java/test/org/openqa/selenium/internal/DebugTest.java +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -246,6 +246,36 @@ void configureLoggerDoesNotLowerAnAlreadyMoreVerboseLevel() { assertThat(seleniumLogger().getLevel()).isEqualTo(Level.FINER); } + @Test + void configureLoggerDoesNotClampAnInheritedMoreVerboseEffectiveLevel() { + // org.openqa.selenium's OWN level stays null/unset (inheriting), but its parent logger + // (org.openqa) is explicitly more verbose than FINE -- the real EFFECTIVE level right now is + // already FINER, and configureLogger() must not clobber that down to FINE just because the + // child logger's own level happens to be null rather than explicitly set. + Logger parentLogger = Logger.getLogger("org.openqa"); + Level oldParentLevel = parentLogger.getLevel(); + parentLogger.setLevel(Level.FINER); + try { + assertThat(seleniumLogger().getLevel()).isNull(); + + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + + // The logger's OWN level must stay untouched: configureLogger() had nothing to raise since + // the EFFECTIVE level was already more verbose than FINE. + assertThat(seleniumLogger().getLevel()).isNull(); + // The inherited FINER effective level must still be in force. + assertThat(seleniumLogger().isLoggable(Level.FINER)).isTrue(); + + // Nothing was raised, so turning debug back off must be a no-op for the level. + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + assertThat(seleniumLogger().getLevel()).isNull(); + } finally { + parentLogger.setLevel(oldParentLevel); + } + } + @Test void configureLoggerDoesNotRestoreALevelItNeverChanged() { seleniumLogger().setLevel(Level.FINER); From c569d651aeb79aa168ba670bc13a3293b12829d0 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 11:50:52 +0300 Subject: [PATCH 06/19] [java] Enforce, not just assert, the null-own-level precondition in the inherited-level test Qodo review finding on #17841 (comment 3672369609): configureLoggerDoesNotClampAnInheritedMoreVerboseEffectiveLevel asserted org.openqa.selenium's own level was null as a starting-state precondition but never enforced it -- if an earlier test in the same JVM run had left an explicit (non-null) level set, this test would fail on that precondition before ever exercising the behavior under test. @AfterEach already restores the logger's own level after every test, so forcing it to null at the start of this test is safe and cannot leak into others. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01LfxetzdJtF13MCJDRNQwgG --- java/test/org/openqa/selenium/internal/DebugTest.java | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java index 0397bcd798fb3..c603124f9bc29 100644 --- a/java/test/org/openqa/selenium/internal/DebugTest.java +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -256,6 +256,12 @@ void configureLoggerDoesNotClampAnInheritedMoreVerboseEffectiveLevel() { Level oldParentLevel = parentLogger.getLevel(); parentLogger.setLevel(Level.FINER); try { + // Enforce the starting precondition rather than merely asserting it: @AfterEach already + // restores this logger's own level after every test, so forcing it to null here is safe + // and can't leak into other tests -- but without this, a leftover explicit level from + // elsewhere in the same JVM run could fail this precondition before the real behavior under + // test ever runs. + seleniumLogger().setLevel(null); assertThat(seleniumLogger().getLevel()).isNull(); System.setProperty("selenium.debug", "true"); From 325168ccaa16f7f53ea879143308bc63f8c7931c Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 12:04:52 +0300 Subject: [PATCH 07/19] [java] Stop suppressing Selenium debug records from Grid's root handler on distinct destinations Qodo review finding on #17841 (comment 3672531999, "Grid drops debug logs"): rootHandlerFilter() suppressed org.openqa.selenium FINE/CONFIG records from Grid's root handler whenever no log-file was configured, on the assumption that destination always coincides with Debug's own stderr-only ConsoleHandler. That's only true when Debug.isDebugAll() (SE_DEBUG) is set: getOutputStream() only defaults to System.err in that case. With debugging enabled instead via -Dselenium.debug=true/-Dselenium.webdriver.verbose=true (no SE_DEBUG), getOutputStream() defaults to System.out -- a genuinely different destination from Debug's handler -- so the suppression made Selenium's FINE-level wire diagnostics invisible to a Grid operator watching stdout/structured log output, this PR's own advertised primary use case. Narrows the suppression condition to !logFileConfigured && Debug.isDebugAll(), matching getOutputStream()'s own exact condition for routing to stderr. Investigating this surfaced that the existing regression test (configureLoggingDoesNotDuplicateSeleniumDebugRecordsWhenNoLogFileIsConfigured) only ever set the selenium.debug property, never the SE_DEBUG environment variable its own comment claimed to cover -- it was unknowingly exercising the very branch this fix changes, and would have started failing once the production fix landed. Corrected its setup to genuinely exercise Debug.isDebugAll() by setting SE_DEBUG via an environment-variable stub (uk.org.webcompere:system-stubs, following the existing pattern already used in remote/service/DriverFinderTest.java), rather than leaving a now-contradictory assertion in place. Added a new test proving the fixed scenario -- selenium.debug=true without SE_DEBUG, no log-file -- where the record must now reach Grid's root handler (stdout) as well as Debug's own (stderr), since they are genuinely different destinations there. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01LfxetzdJtF13MCJDRNQwgG --- .../selenium/grid/log/LoggingOptions.java | 24 ++++---- .../org/openqa/selenium/grid/log/BUILD.bazel | 2 + .../selenium/grid/log/LoggingOptionsTest.java | 59 +++++++++++++++---- 3 files changed, 65 insertions(+), 20 deletions(-) diff --git a/java/src/org/openqa/selenium/grid/log/LoggingOptions.java b/java/src/org/openqa/selenium/grid/log/LoggingOptions.java index a227c4d4e77f8..fd5c8ab06c9fc 100644 --- a/java/src/org/openqa/selenium/grid/log/LoggingOptions.java +++ b/java/src/org/openqa/selenium/grid/log/LoggingOptions.java @@ -224,20 +224,24 @@ public void configureLogging() { * prints (FINE/CONFIG-range records from that logger or a descendant, while its handler is * installed) must not also print through this root handler, PROVIDED this root handler's * destination is the one Debug's handler also writes to -- that handler's own useParentHandlers - * is never disabled, so the same record reaches both. That's only true when no {@code log-file} - * is configured: {@link #getOutputStream()} then defaults this handler to {@code - * System.out}/{@code System.err}, the same visible destination as Debug's own {@code - * ConsoleHandler} (fixed to {@code System.err}) in every realistic deployment. A configured - * log-file is a genuinely separate destination Debug never writes to, so suppressing there would - * silently drop the record from the operator's chosen sink instead of de-duplicating it -- worse - * than the problem this filter exists to solve. INFO-and-above {@code org.openqa.selenium} - * records, and everything from every other logger, are untouched either way: Debug's handler - * never covered those in the first place. + * is never disabled, so the same record reaches both. Debug's own handler is always a {@code + * ConsoleHandler}, which per its JDK contract always targets {@code System.err}; this root + * handler's destination only coincides with that when {@link Debug#isDebugAll()} ({@code + * SE_DEBUG}) is set AND no {@code log-file} is configured -- {@link #getOutputStream()} then + * defaults this handler to {@code System.err} too. When debugging is instead enabled via {@code + * -Dselenium.debug=true}/{@code -Dselenium.webdriver.verbose=true} without {@code SE_DEBUG}, + * {@link #getOutputStream()} defaults to {@code System.out} -- a genuinely different destination + * from Debug's handler -- so suppressing there would make the record invisible to an operator + * watching Grid's own stdout/structured log output instead of de-duplicating it. A configured + * log-file is a genuinely separate destination Debug never writes to either, for the same reason. + * INFO-and-above {@code org.openqa.selenium} records, and everything from every other logger, are + * untouched either way: Debug's handler never covered those in the first place. */ private Filter rootHandlerFilter() { boolean logFileConfigured = config.get(LOGGING_SECTION, "log-file").isPresent(); + boolean sameDestinationAsDebugHandler = !logFileConfigured && Debug.isDebugAll(); return record -> - logFileConfigured + !sameDestinationAsDebugHandler || !Debug.isHandledBySeleniumDebugHandler(record.getLoggerName(), record.getLevel()); } diff --git a/java/test/org/openqa/selenium/grid/log/BUILD.bazel b/java/test/org/openqa/selenium/grid/log/BUILD.bazel index 9b80074266ceb..709e0dd935562 100644 --- a/java/test/org/openqa/selenium/grid/log/BUILD.bazel +++ b/java/test/org/openqa/selenium/grid/log/BUILD.bazel @@ -11,5 +11,7 @@ java_test_suite( "//java/src/org/openqa/selenium/grid/log", artifact("org.assertj:assertj-core"), artifact("org.junit.jupiter:junit-jupiter-api"), + artifact("uk.org.webcompere:system-stubs-jupiter"), + artifact("uk.org.webcompere:system-stubs-core"), ] + JUNIT5_DEPS, ) diff --git a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java index 0f6ca0c11007c..78af3b91e88ea 100644 --- a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java +++ b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java @@ -39,12 +39,19 @@ import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Tag; import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.ExtendWith; import org.openqa.selenium.grid.config.MapConfig; import org.openqa.selenium.internal.Debug; +import uk.org.webcompere.systemstubs.environment.EnvironmentVariables; +import uk.org.webcompere.systemstubs.jupiter.SystemStub; +import uk.org.webcompere.systemstubs.jupiter.SystemStubsExtension; @Tag("UnitTests") +@ExtendWith(SystemStubsExtension.class) class LoggingOptionsTest { + @SystemStub private EnvironmentVariables environment; + private String oldDebugProperty; // Legacy alias for selenium.debug -- Debug.isDebugging() honors either, so a test JVM that // happens to have this set externally must not leak into the "no switch" baseline assertions. @@ -179,15 +186,17 @@ void configureLoggingDoesNotDuplicateSeleniumDebugRecordsWhenNoLogFileIsConfigur // directly on org.openqa.selenium that already prints FINE/CONFIG-range records to stderr -- // it never disables useParentHandlers, so those same records also propagate up to whatever // handler(s) configureLogging() itself then attaches to the ROOT logger a few lines later. - // With no log-file configured, getOutputStream() defaults that root handler to System.out (no - // SE_DEBUG here) -- a different JUL handler/stream than Debug's stderr one, but the same - // visible destination in every realistic deployment (Grid's primary real-world usage is - // containerized, where the container log driver merges stdout+stderr into one stream a human - // actually reads), so nothing stopped a FINE record from org.openqa.selenium(.*) printing - // twice, once from each handler. INFO-and-above records must be unaffected -- Debug's own - // handler already excludes those, so they only ever reached Grid's root handler in the first - // place. - System.setProperty("selenium.debug", "true"); + // With SE_DEBUG set and no log-file configured, getOutputStream() defaults that root handler + // to System.err too -- the exact same destination Debug's own ConsoleHandler always targets -- + // so nothing stopped a FINE record from org.openqa.selenium(.*) printing twice, once from each + // handler. INFO-and-above records must be unaffected -- Debug's own handler already excludes + // those, so they only ever reached Grid's root handler in the first place. SE_DEBUG is set via + // an environment-variable stub rather than the selenium.debug property: this scenario is + // specifically about Debug.isDebugAll() (SE_DEBUG), which is what makes getOutputStream() + // route to System.err in the first place -- selenium.debug=true alone does not (see + // configureLoggingDoesNotSuppressSeleniumDebugRecordsOnRootHandlerWhenDebugPropertyIsSetWithoutSeDebug + // for that contrasting case). + environment.set("SE_DEBUG", "true"); String marker = "duplicate-check-" + UUID.randomUUID(); Captured captured = @@ -199,10 +208,40 @@ void configureLoggingDoesNotDuplicateSeleniumDebugRecordsWhenNoLogFileIsConfigur // Debug's own handler on org.openqa.selenium must still print it -- unchanged behavior. assertThat(captured.err()).contains(marker); - // Grid's root handler (defaulting to stdout here) must not ALSO print it. + // Grid's root handler (defaulting to stderr here, same as Debug's handler) must not ALSO + // print it. assertThat(captured.out()).doesNotContain(marker); } + @Test + void + configureLoggingDoesNotSuppressSeleniumDebugRecordsOnRootHandlerWhenDebugPropertyIsSetWithoutSeDebug() { + // With selenium.debug=true (property only -- SE_DEBUG is deliberately left unset here) and no + // log-file configured, getOutputStream() defaults Grid's root handler to System.out -- + // Debug.isDebugAll() is false in this scenario, so getOutputStream() never routes to + // System.err. Debug's own handler on org.openqa.selenium is always a ConsoleHandler, which per + // its JDK contract always targets System.err regardless of anything Grid does. Root handler + // (stdout) and Debug's handler (stderr) are therefore genuinely DIFFERENT destinations here -- + // suppressing the record from the root handler on the assumption it's already visible via + // Debug's handler would make it invisible to an operator watching Grid's own stdout/structured + // log output, this PR's own advertised primary use case. + System.setProperty("selenium.debug", "true"); + String marker = "distinct-destination-check-" + UUID.randomUUID(); + + Captured captured = + captureStdOutAndErrDuring( + () -> { + new LoggingOptions(emptyConfig()).configureLogging(); + Logger.getLogger("org.openqa.selenium.grid.log.LoggingOptionsTest").fine(marker); + }); + + // Debug's own handler on org.openqa.selenium must still print it -- unchanged behavior. + assertThat(captured.err()).contains(marker); + // Grid's root handler (stdout here, a genuinely different destination) must ALSO print it -- + // it must not be suppressed as if it were a duplicate of Debug's stderr output. + assertThat(captured.out()).contains(marker); + } + @Test void configureLoggingLetsSeleniumDebugRecordsReachAConfiguredLogFileAlongsideDebugsHandler() throws IOException { From d270074a228028d9fcc3cb5ce61b5e07e5180949 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 12:20:02 +0300 Subject: [PATCH 08/19] [java] Assert the no-duplicate marker appears exactly once on stderr With SE_DEBUG stubbed on and no log-file, BOTH Grid's root handler and Debug's own ConsoleHandler target System.err -- nothing goes to stdout in this scenario at all, so the old `captured.out()` doesNotContain assertion was vacuously true and a real duplication regression (the marker printed twice to stderr, once per handler) would have passed unnoticed. Verified by mutation: with rootHandlerFilter()'s suppression temporarily disabled, the old assertions still passed while containsOnlyOnce correctly failed with "appeared 2 times". The stdout check stays as a secondary sanity check. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01LfxetzdJtF13MCJDRNQwgG --- .../openqa/selenium/grid/log/LoggingOptionsTest.java | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java index 78af3b91e88ea..1e46fc7294755 100644 --- a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java +++ b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java @@ -206,10 +206,12 @@ void configureLoggingDoesNotDuplicateSeleniumDebugRecordsWhenNoLogFileIsConfigur Logger.getLogger("org.openqa.selenium.grid.log.LoggingOptionsTest").fine(marker); }); - // Debug's own handler on org.openqa.selenium must still print it -- unchanged behavior. - assertThat(captured.err()).contains(marker); - // Grid's root handler (defaulting to stderr here, same as Debug's handler) must not ALSO - // print it. + // Debug's own handler must print it, and Grid's root handler -- defaulting to stderr here, + // the SAME destination as Debug's handler -- must not ALSO print it. Both handlers write to + // stderr in this scenario, so a duplication regression shows up as the marker appearing TWICE + // in the captured stderr; exactly-once is the whole assertion. + assertThat(captured.err()).containsOnlyOnce(marker); + // Secondary sanity check: with SE_DEBUG set and no log-file, nothing routes to stdout at all. assertThat(captured.out()).doesNotContain(marker); } From 59383f6ed06b697f3ce463813a3418b56c2799a0 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 12:21:11 +0300 Subject: [PATCH 09/19] [java] Force the stubbed SE_DEBUG off before re-syncing Debug in cleanup The @AfterEach cleanup calls Debug.configureLogger() to re-sync Debug with the restored switch state, but that only works for switches restored synchronously inside the method itself (the plain system properties). The stubbed SE_DEBUG is restored by SystemStubsExtension's own lifecycle callback, which runs AFTER user @AfterEach methods complete -- so the re-sync still saw SE_DEBUG=true, kept Debug's handler installed, and the stub's later restoration went unnoticed, leaking the handler (and Debug's loggerConfigured bookkeeping) into later tests in the same JVM. Explicitly setting the stub to "false" first makes configureLogger() see the correct final state and tear the handler down deterministically. Regression test invokes the real cleanup method and was watched fail (handler still installed) before the fix, pass after. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01LfxetzdJtF13MCJDRNQwgG --- .../selenium/grid/log/LoggingOptionsTest.java | 27 +++++++++++++++++++ 1 file changed, 27 insertions(+) diff --git a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java index 1e46fc7294755..cddcb53e8d45c 100644 --- a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java +++ b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java @@ -79,6 +79,13 @@ void restoreSystemProperty() { } else { System.clearProperty("selenium.webdriver.verbose"); } + // Force the stubbed SE_DEBUG off BEFORE re-syncing Debug below: SystemStubsExtension only + // restores the real environment after this whole method returns (extension callbacks wrap + // user @AfterEach methods), so without this a test that stubbed SE_DEBUG=true would have + // configureLogger() still see debugging "on" here, keep its handler installed, and leak it + // -- with nothing ever re-syncing after the stub's later restoration. Unconditional: safe + // for tests that never touched the stub. + environment.set("SE_DEBUG", "false"); // Reverts whatever configureLogging() may have done to the shared org.openqa.selenium logger // via Debug.configureLogger() during the test, now that the properties are back to their // original values. @@ -298,6 +305,26 @@ void captureStdOutAndErrDuringDoesNotLeakRootLoggerHandlers() { assertThat(leakedHandlers).isEmpty(); } + @Test + void afterEachCleanupTearsDownDebugHandlerInstalledUnderStubbedSeDebug() { + // The @AfterEach cleanup re-syncs Debug via Debug.configureLogger(), which only works if that + // call sees the FINAL switch state. The plain selenium.debug/selenium.webdriver.verbose + // properties are restored synchronously inside that same method, but the stubbed SE_DEBUG is + // only restored by SystemStubsExtension's own lifecycle callback, which runs AFTER user + // @AfterEach methods complete. A cleanup that merely calls configureLogger() therefore still + // sees SE_DEBUG=true, leaves Debug's handler installed, and nothing re-syncs after the stub's + // later restoration -- the handler (and Debug's loggerConfigured bookkeeping) silently leaks + // into every later test in this JVM. Invoking the REAL cleanup method here proves it tears + // the handler down deterministically instead of depending on extension-restoration timing. + environment.set("SE_DEBUG", "true"); + captureStdOutAndErrDuring(() -> new LoggingOptions(emptyConfig()).configureLogging()); + assertThat(Debug.isHandlerCurrentlyInstalled()).isTrue(); + + restoreSystemProperty(); + + assertThat(Debug.isHandlerCurrentlyInstalled()).isFalse(); + } + private static MapConfig emptyConfig() { return new MapConfig(Map.of()); } From 96ec9cf2ddd4231ba0014e330d1df48fe8cc435b Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 22:05:02 +0300 Subject: [PATCH 10/19] Fix logging snapshot in RetryRequest: use live Debug.getDebugLogLevel() instead of static LOG_LEVEL Avoids snapshotting the debug log level at class-init time so runtime switches (SE_DEBUG, -Dselenium.debug) are respected. /act-as-mohab /test-driven-development Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- java/src/org/openqa/selenium/remote/http/RetryRequest.java | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/java/src/org/openqa/selenium/remote/http/RetryRequest.java b/java/src/org/openqa/selenium/remote/http/RetryRequest.java index 17a3f7e0ed25c..70ee39708073e 100644 --- a/java/src/org/openqa/selenium/remote/http/RetryRequest.java +++ b/java/src/org/openqa/selenium/remote/http/RetryRequest.java @@ -28,7 +28,6 @@ public class RetryRequest implements Filter { private static final Logger LOG = Logger.getLogger(RetryRequest.class.getName()); - private static final Level LOG_LEVEL = Debug.getDebugLogLevel(); private static final int RETRIES_ON_CONNECTION_FAILURE = 3; private static final int RETRIES_ON_SERVER_ERROR = 2; @@ -50,7 +49,7 @@ public HttpHandler apply(HttpHandler next) { // must be a connection failure and check whether we have retries left for this if (isConnectionFailure && i < RETRIES_ON_CONNECTION_FAILURE) { - LOG.log(LOG_LEVEL, "Retry #" + (i + 1) + " on ConnectException", ex); + LOG.log(Debug.getDebugLogLevel(), "Retry #" + (i + 1) + " on ConnectException", ex); continue; } @@ -65,7 +64,7 @@ public HttpHandler apply(HttpHandler next) { // must be a server error and check whether we have retries left for this if (isServerError && i < RETRIES_ON_SERVER_ERROR) { - LOG.log(LOG_LEVEL, "Retry #" + (i + 1) + " on ServerError: " + response.getStatus()); + LOG.log(Debug.getDebugLogLevel(), "Retry #" + (i + 1) + " on ServerError: " + response.getStatus()); continue; } @@ -79,3 +78,4 @@ public HttpHandler apply(HttpHandler next) { }; } } + From ae54eb04fd2a5c5b9b1a9733e3c2d087f2292134 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Wed, 29 Jul 2026 22:15:27 +0300 Subject: [PATCH 11/19] Move Debug.configureLogger() out of constructors' pre-validation path to avoid installing handlers when construction fails - Bidi Connection: call configureLogger() after argument checks - DevTools Connection: validate and compute wsClientConfig before configureLogger() - RemoteWebDriver: call configureLogger() after non-null checks /act-as-mohab /test-driven-development --- java/src/org/openqa/selenium/bidi/Connection.java | 7 +++---- java/src/org/openqa/selenium/devtools/Connection.java | 5 ++--- java/src/org/openqa/selenium/remote/RemoteWebDriver.java | 5 ++--- 3 files changed, 7 insertions(+), 10 deletions(-) diff --git a/java/src/org/openqa/selenium/bidi/Connection.java b/java/src/org/openqa/selenium/bidi/Connection.java index 005178d276e6d..c0c0bd681b045 100644 --- a/java/src/org/openqa/selenium/bidi/Connection.java +++ b/java/src/org/openqa/selenium/bidi/Connection.java @@ -87,14 +87,12 @@ public class Connection implements Closeable { * @param client the HTTP client used to open the underlying web socket; must not be null * @param url the URL to open the web socket connection to; must not be null */ - public Connection(HttpClient client, String url) { + public Connection(HttpClient client, String url) {`n // Reflect the current debug switches before this connection starts logging its wire // diagnostics at FINE -- callers that construct a Connection directly (never going through // RemoteWebDriver or DriverFinder) would otherwise never trigger the raise. Idempotent and // cheap, same pattern as DriverFinder.getBinaryPaths(). - Debug.configureLogger(); - Require.nonNull("HTTP client", client); - Require.nonNull("URL to connect to", url); + Require.nonNull("HTTP client", client);`n Require.nonNull("URL to connect to", url);`n Debug.configureLogger(); this.client = client; this.socket = this.client.openSocket(new HttpRequest(GET, url), new Listener()); @@ -413,3 +411,4 @@ private void handleEventResponse(Map rawDataMap) { } } } + diff --git a/java/src/org/openqa/selenium/devtools/Connection.java b/java/src/org/openqa/selenium/devtools/Connection.java index bc4f25f6ecfd5..99a35bd44f694 100644 --- a/java/src/org/openqa/selenium/devtools/Connection.java +++ b/java/src/org/openqa/selenium/devtools/Connection.java @@ -110,9 +110,7 @@ public Connection(HttpClient client, String url, ClientConfig clientConfig) { // RemoteWebDriver or DriverFinder) would otherwise never trigger the raise. Idempotent and // cheap, same pattern as DriverFinder.getBinaryPaths(). The deprecated 2-arg constructor // delegates here, so this single call point covers both. - Debug.configureLogger(); - this.client = Require.nonNull("HTTP client", client); - this.wsConfig = wsClientConfig(clientConfig, url); + this.client = Require.nonNull("HTTP client", client);`n this.wsConfig = wsClientConfig(clientConfig, url);`n Debug.configureLogger(); this.socket = this.client.openSocket(new HttpRequest(GET, wsConfig.baseUri()), new Listener()); this.isClosed = new AtomicBoolean(); } @@ -392,3 +390,4 @@ private void handle(long sequence, CharSequence data) { } } } + diff --git a/java/src/org/openqa/selenium/remote/RemoteWebDriver.java b/java/src/org/openqa/selenium/remote/RemoteWebDriver.java index 8d3442a5acb90..5c557a7392fd1 100644 --- a/java/src/org/openqa/selenium/remote/RemoteWebDriver.java +++ b/java/src/org/openqa/selenium/remote/RemoteWebDriver.java @@ -227,9 +227,7 @@ public RemoteWebDriver( CommandExecutor executor, Capabilities capabilities, ClientConfig clientConfig) { // Instance-time (not class-load-time) so a property change made after this class has already // loaded still takes effect for drivers constructed afterwards. - Debug.configureLogger(); - this.clientConfig = Require.nonNull("Client config", clientConfig); - this.executor = Require.nonNull("Command executor", executor); + this.clientConfig = Require.nonNull("Client config", clientConfig);`n this.executor = Require.nonNull("Command executor", executor);`n Debug.configureLogger(); this.capabilities = requireNonNullElseGet(capabilities, () -> new ImmutableCapabilities()); try { @@ -1472,3 +1470,4 @@ public void setUserVerified(boolean verified) { } } } + From 2f5c1015abb24511b29fd4f2efe6d3b22fa391a2 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Sat, 1 Aug 2026 17:27:08 +0300 Subject: [PATCH 12/19] [java] Scope debug property to JUL diagnostics --- .../org/openqa/selenium/bidi/Connection.java | 7 +- .../openqa/selenium/devtools/Connection.java | 5 +- .../selenium/grid/log/LoggingOptions.java | 82 +--- .../org/openqa/selenium/internal/Debug.java | 64 +-- .../selenium/remote/RemoteWebDriver.java | 5 +- .../selenium/remote/http/RetryRequest.java | 6 +- .../org/openqa/selenium/grid/log/BUILD.bazel | 17 - .../selenium/grid/log/LoggingOptionsTest.java | 386 ------------------ .../openqa/selenium/internal/DebugTest.java | 76 ++++ .../remote/http/RetryRequestTest.java | 39 ++ 10 files changed, 151 insertions(+), 536 deletions(-) delete mode 100644 java/test/org/openqa/selenium/grid/log/BUILD.bazel delete mode 100644 java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java diff --git a/java/src/org/openqa/selenium/bidi/Connection.java b/java/src/org/openqa/selenium/bidi/Connection.java index c0c0bd681b045..29b661ad05fb3 100644 --- a/java/src/org/openqa/selenium/bidi/Connection.java +++ b/java/src/org/openqa/selenium/bidi/Connection.java @@ -87,12 +87,14 @@ public class Connection implements Closeable { * @param client the HTTP client used to open the underlying web socket; must not be null * @param url the URL to open the web socket connection to; must not be null */ - public Connection(HttpClient client, String url) {`n + public Connection(HttpClient client, String url) { // Reflect the current debug switches before this connection starts logging its wire // diagnostics at FINE -- callers that construct a Connection directly (never going through // RemoteWebDriver or DriverFinder) would otherwise never trigger the raise. Idempotent and // cheap, same pattern as DriverFinder.getBinaryPaths(). - Require.nonNull("HTTP client", client);`n Require.nonNull("URL to connect to", url);`n Debug.configureLogger(); + Require.nonNull("HTTP client", client); + Require.nonNull("URL to connect to", url); + Debug.configureLogger(); this.client = client; this.socket = this.client.openSocket(new HttpRequest(GET, url), new Listener()); @@ -411,4 +413,3 @@ private void handleEventResponse(Map rawDataMap) { } } } - diff --git a/java/src/org/openqa/selenium/devtools/Connection.java b/java/src/org/openqa/selenium/devtools/Connection.java index 99a35bd44f694..cd7387314bc87 100644 --- a/java/src/org/openqa/selenium/devtools/Connection.java +++ b/java/src/org/openqa/selenium/devtools/Connection.java @@ -110,7 +110,9 @@ public Connection(HttpClient client, String url, ClientConfig clientConfig) { // RemoteWebDriver or DriverFinder) would otherwise never trigger the raise. Idempotent and // cheap, same pattern as DriverFinder.getBinaryPaths(). The deprecated 2-arg constructor // delegates here, so this single call point covers both. - this.client = Require.nonNull("HTTP client", client);`n this.wsConfig = wsClientConfig(clientConfig, url);`n Debug.configureLogger(); + this.client = Require.nonNull("HTTP client", client); + this.wsConfig = wsClientConfig(clientConfig, url); + Debug.configureLogger(); this.socket = this.client.openSocket(new HttpRequest(GET, wsConfig.baseUri()), new Listener()); this.isClosed = new AtomicBoolean(); } @@ -390,4 +392,3 @@ private void handle(long sequence, CharSequence data) { } } } - diff --git a/java/src/org/openqa/selenium/grid/log/LoggingOptions.java b/java/src/org/openqa/selenium/grid/log/LoggingOptions.java index fd5c8ab06c9fc..b812bac69f186 100644 --- a/java/src/org/openqa/selenium/grid/log/LoggingOptions.java +++ b/java/src/org/openqa/selenium/grid/log/LoggingOptions.java @@ -26,7 +26,6 @@ import java.util.Enumeration; import java.util.List; import java.util.Locale; -import java.util.logging.Filter; import java.util.logging.Handler; import java.util.logging.Level; import java.util.logging.LogManager; @@ -86,21 +85,11 @@ public String getLogEncoding() { return config.get(LOGGING_SECTION, "log-encoding").orElse(null); } - /** - * Resolves the Grid log level from the {@code log-level} entry of the logging config section and - * stores it for {@link #configureLogging()}. Any active Selenium debug switch ({@code SE_DEBUG}, - * {@code -Dselenium.debug=true}, {@code -Dselenium.webdriver.verbose=true}) overrides the - * configured value and forces {@link Level#FINE}. An unparseable configured value falls back to - * the default ({@code INFO}). - * - * @return this instance, for method chaining - */ public LoggingOptions setLoggingLevel() { String configLevel = config.get(LOGGING_SECTION, "log-level").orElse(DEFAULT_LOG_LEVEL); - if (Debug.isDebugAll() || Debug.isDebugging()) { + if (Debug.isDebugAll()) { System.err.println( - "WARNING: Selenium debug logging is enabled (`SE_DEBUG`, `-Dselenium.debug=true`, or" - + " `-Dselenium.webdriver.verbose=true`); forcing Grid log level to FINE and" + "WARNING: Environment Variable `SE_DEBUG` is set; forcing Grid log level to FINE and" + " overriding configured log level."); configLevel = Level.FINE.getName(); } @@ -134,29 +123,11 @@ public Tracer getTracer() { return OpenTelemetryTracer.getInstance(); } - /** - * Configures logging for the Grid, wiring up Grid's own log handlers and, before doing so, - * reflecting the current Selenium debug switches onto the {@code org.openqa.selenium} logger via - * {@link Debug#configureLogger()}. Returns early without changing anything if logging is disabled - * ({@code enable} is {@code false}) or if an external {@code java.util.logging.config} class/file - * is configured, in which case that configuration takes priority. Otherwise, every other - * registered logger has its handlers stripped to start from a clean slate before Grid's root - * handlers are installed. - */ public void configureLogging() { if (!config.getBool(LOGGING_SECTION, "enable").orElse(DEFAULT_CONFIGURE_LOGGING)) { return; } - // Reflect the current debug switches onto the shared org.openqa.selenium logger before - // anything else below -- in particular, before the external-JUL-config early return just - // below hands the rest of logging setup off entirely. Without this, Selenium's own FINE-level - // wire diagnostics (RequestConverter, the BiDi/CDP Connection classes) stay invisible under - // -Dselenium.debug=true whenever an external `java.util.logging.config.*` property is set, - // since nothing else on Grid's startup path would ever call this. Idempotent and cheap, same - // chokepoint pattern as DriverFinder.getBinaryPaths(). - Debug.configureLogger(); - String configClass = System.getProperty("java.util.logging.config.class"); String configFile = System.getProperty("java.util.logging.config.file"); @@ -166,32 +137,15 @@ public void configureLogging() { return; } - // Remove all handlers from existing loggers, except org.openqa.selenium: - // Debug.configureLogger() - // above may have just installed a handler there for debug-mode output, and this loop would - // otherwise strip it moments later (Debug holds a strong static reference so that logger stays - // registered here too). Debug's own installed-handler bookkeeping has no way to learn a handler - // was removed out from under it, so once stripped its idempotency guard would prevent ever - // reinstalling one until the debug switch is toggled off and back on. + // Remove all handlers from existing loggers LogManager logManager = LogManager.getLogManager(); Enumeration names = logManager.getLoggerNames(); while (names.hasMoreElements()) { - String name = names.nextElement(); - Logger logger = logManager.getLogger(name); + Logger logger = logManager.getLogger(names.nextElement()); if (logger == null) { continue; } - if ("org.openqa.selenium".equals(name)) { - // Strip everything except the handler Debug.configureLogger() installed above -- an - // unrelated handler some other code attached to this logger must still be reset here, - // same as on any other logger; only Debug's own handler is exempt. - Arrays.stream(logger.getHandlers()) - .filter(handler -> !Debug.isOwnHandler(handler)) - .forEach(logger::removeHandler); - continue; - } - Arrays.stream(logger.getHandlers()).forEach(logger::removeHandler); } @@ -206,7 +160,6 @@ public void configureLogging() { Handler handler = new FlushingHandler(out); handler.setFormatter(new TerseFormatter(getLogTimestampFormat())); handler.setLevel(level); - handler.setFilter(rootHandlerFilter()); configureLogEncoding(logger, encoding, handler); } @@ -214,37 +167,10 @@ public void configureLogging() { Handler handler = new FlushingHandler(out); handler.setFormatter(new JsonFormatter()); handler.setLevel(level); - handler.setFilter(rootHandlerFilter()); configureLogEncoding(logger, encoding, handler); } } - /** - * Records that Debug.configureLogger()'s own handler on {@code org.openqa.selenium} already - * prints (FINE/CONFIG-range records from that logger or a descendant, while its handler is - * installed) must not also print through this root handler, PROVIDED this root handler's - * destination is the one Debug's handler also writes to -- that handler's own useParentHandlers - * is never disabled, so the same record reaches both. Debug's own handler is always a {@code - * ConsoleHandler}, which per its JDK contract always targets {@code System.err}; this root - * handler's destination only coincides with that when {@link Debug#isDebugAll()} ({@code - * SE_DEBUG}) is set AND no {@code log-file} is configured -- {@link #getOutputStream()} then - * defaults this handler to {@code System.err} too. When debugging is instead enabled via {@code - * -Dselenium.debug=true}/{@code -Dselenium.webdriver.verbose=true} without {@code SE_DEBUG}, - * {@link #getOutputStream()} defaults to {@code System.out} -- a genuinely different destination - * from Debug's handler -- so suppressing there would make the record invisible to an operator - * watching Grid's own stdout/structured log output instead of de-duplicating it. A configured - * log-file is a genuinely separate destination Debug never writes to either, for the same reason. - * INFO-and-above {@code org.openqa.selenium} records, and everything from every other logger, are - * untouched either way: Debug's handler never covered those in the first place. - */ - private Filter rootHandlerFilter() { - boolean logFileConfigured = config.get(LOGGING_SECTION, "log-file").isPresent(); - boolean sameDestinationAsDebugHandler = !logFileConfigured && Debug.isDebugAll(); - return record -> - !sameDestinationAsDebugHandler - || !Debug.isHandledBySeleniumDebugHandler(record.getLoggerName(), record.getLevel()); - } - private void configureLogEncoding(Logger logger, @Nullable String encoding, Handler handler) { String message; try { diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index 428f9875a3656..347e86437d84e 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -24,6 +24,7 @@ import java.util.logging.Handler; import java.util.logging.Level; import java.util.logging.Logger; +import org.jspecify.annotations.Nullable; /** Used to provide information about whether Selenium is running under debug mode. */ public class Debug { @@ -70,56 +71,15 @@ public static Level getDebugLogLevel() { return isDebugging() ? Level.INFO : Level.FINE; } - /** - * Reports whether {@link #configureLogger()}'s handler is attached to {@code org.openqa.selenium} - * right now. Unlike {@link #isDebugging()} or {@link #isDebugAll()}, which read the live system - * property/environment variable, this reflects the handler's actual, current installation state - * -- the two can genuinely diverge for however long it takes some caller to next invoke {@link - * #configureLogger()} after a switch changes, since nothing installs or removes the handler - * except that call. This checks the logger's real handler list rather than trusting the {@code - * loggerConfigured} bookkeeping flag alone, since something outside this class can remove the - * handler without ever going through {@link #configureLogger()} -- e.g. {@code - * LogManager.getLogManager().reset()} (routine in embedding scenarios: Spring Boot's {@code - * JavaLoggingSystem}, a Log4j-JUL bridge, a container shutdown hook) or a direct {@code - * removeHandler()} call by unrelated code -- which would otherwise leave the flag stale-true. - * - * @return true when a handler installed by {@link #configureLogger()} is currently attached - */ public static synchronized boolean isHandlerCurrentlyInstalled() { return installedHandler != null && Arrays.asList(SELENIUM_LOGGER.getHandlers()).contains(installedHandler); } - /** - * Reports whether {@code handler} is specifically the one {@link #configureLogger()} installed on - * {@code org.openqa.selenium} -- not merely whether some handler exists there. A caller that - * needs to strip handlers from that logger down to a clean slate (e.g. Grid's logging setup) must - * preserve only Debug's own handler, not every handler that happens to be attached to that - * logger; this lets such a caller identify exactly the one to keep without this class exposing - * the field itself. - * - * @param handler the handler to check; {@code null} is never Debug's own - * @return true when {@code handler} is the exact instance {@link #configureLogger()} installed - */ public static synchronized boolean isOwnHandler(Handler handler) { return handler != null && handler == installedHandler; } - /** - * Reports whether a log record from {@code loggerName} at {@code level} would already be emitted - * by the handler {@link #configureLogger()} installs directly on {@code org.openqa.selenium} -- - * that handler and its filter together cover exactly {@link Level#FINE}- and {@link - * Level#CONFIG}-range records from that logger and its descendants, whenever that handler is - * {@linkplain #isHandlerCurrentlyInstalled() currently installed}. A caller further up the logger - * hierarchy (e.g. a handler on the root logger, which receives the same record too via normal - * handler propagation) can use this to avoid printing it a second time, without disabling - * propagation itself -- which would instead silently drop every {@link Level#INFO}-and-above - * {@code org.openqa.selenium} record that caller would otherwise print. - * - * @param loggerName the originating logger's name; {@code null} is never covered - * @param level the record's level - * @return true when {@link #configureLogger()}'s own handler already covers this record - */ public static boolean isHandledBySeleniumDebugHandler(String loggerName, Level level) { if (!isHandlerCurrentlyInstalled()) { return false; @@ -164,6 +124,17 @@ private static Level effectiveLevel(Logger logger) { return Level.INFO; } + @Nullable + private static Level getRequestedLogLevel() { + if (isDebugging()) { + return Level.FINE; + } + if (isDebugAll()) { + return Level.FINE; + } + return null; + } + /** * Reflects the current debug switches ({@code -Dselenium.debug=true}, {@code * -Dselenium.webdriver.verbose=true}, {@code SE_DEBUG}) onto the real {@code org.openqa.selenium} @@ -189,7 +160,8 @@ private static Level effectiveLevel(Logger logger) { * duplicated. */ public static synchronized void configureLogger() { - boolean shouldDebug = isDebugging() || isDebugAll(); + Level requestedLevel = getRequestedLogLevel(); + boolean shouldDebug = requestedLevel != null; // When shouldDebug is on and already configured, only skip if the handler this method // installed is still actually attached -- something outside this class (e.g. a LogManager // reset, or unrelated code calling removeHandler() directly) can remove it without ever @@ -216,15 +188,19 @@ public static synchronized void configureLogger() { // verbosity. What gets snapshotted/restored is still the logger's own level exactly as // before; only the raise/no-raise decision changes. Level currentLevel = SELENIUM_LOGGER.getLevel(); - levelRaisedByDebug = effectiveLevel(SELENIUM_LOGGER).intValue() > Level.FINE.intValue(); + levelRaisedByDebug = + effectiveLevel(SELENIUM_LOGGER).intValue() > requestedLevel.intValue(); if (levelRaisedByDebug) { previousLevel = currentLevel; - SELENIUM_LOGGER.setLevel(Level.FINE); } else { previousLevel = null; } } + if (effectiveLevel(SELENIUM_LOGGER).intValue() > requestedLevel.intValue()) { + SELENIUM_LOGGER.setLevel(requestedLevel); + } + // Runs unconditionally whenever shouldDebug is true and we reach this point -- both on a // genuine turn-on and on a handler-repair call -- since that's the actual state that needs // fixing in the repair case. diff --git a/java/src/org/openqa/selenium/remote/RemoteWebDriver.java b/java/src/org/openqa/selenium/remote/RemoteWebDriver.java index 7e24b08301230..2419da32974cd 100644 --- a/java/src/org/openqa/selenium/remote/RemoteWebDriver.java +++ b/java/src/org/openqa/selenium/remote/RemoteWebDriver.java @@ -227,7 +227,9 @@ public RemoteWebDriver( CommandExecutor executor, Capabilities capabilities, ClientConfig clientConfig) { // Instance-time (not class-load-time) so a property change made after this class has already // loaded still takes effect for drivers constructed afterwards. - this.clientConfig = Require.nonNull("Client config", clientConfig);`n this.executor = Require.nonNull("Command executor", executor);`n Debug.configureLogger(); + this.clientConfig = Require.nonNull("Client config", clientConfig); + this.executor = Require.nonNull("Command executor", executor); + Debug.configureLogger(); this.capabilities = requireNonNullElseGet(capabilities, () -> new ImmutableCapabilities()); try { @@ -1481,4 +1483,3 @@ public void setUserVerified(boolean verified) { } } } - diff --git a/java/src/org/openqa/selenium/remote/http/RetryRequest.java b/java/src/org/openqa/selenium/remote/http/RetryRequest.java index 70ee39708073e..00efadec5e7f8 100644 --- a/java/src/org/openqa/selenium/remote/http/RetryRequest.java +++ b/java/src/org/openqa/selenium/remote/http/RetryRequest.java @@ -23,7 +23,6 @@ import java.net.ConnectException; import java.util.logging.Level; import java.util.logging.Logger; -import org.openqa.selenium.internal.Debug; public class RetryRequest implements Filter { @@ -49,7 +48,7 @@ public HttpHandler apply(HttpHandler next) { // must be a connection failure and check whether we have retries left for this if (isConnectionFailure && i < RETRIES_ON_CONNECTION_FAILURE) { - LOG.log(Debug.getDebugLogLevel(), "Retry #" + (i + 1) + " on ConnectException", ex); + LOG.log(Level.FINE, "Retry #" + (i + 1) + " on ConnectException", ex); continue; } @@ -64,7 +63,7 @@ public HttpHandler apply(HttpHandler next) { // must be a server error and check whether we have retries left for this if (isServerError && i < RETRIES_ON_SERVER_ERROR) { - LOG.log(Debug.getDebugLogLevel(), "Retry #" + (i + 1) + " on ServerError: " + response.getStatus()); + LOG.log(Level.FINE, "Retry #" + (i + 1) + " on ServerError: " + response.getStatus()); continue; } @@ -78,4 +77,3 @@ public HttpHandler apply(HttpHandler next) { }; } } - diff --git a/java/test/org/openqa/selenium/grid/log/BUILD.bazel b/java/test/org/openqa/selenium/grid/log/BUILD.bazel deleted file mode 100644 index 709e0dd935562..0000000000000 --- a/java/test/org/openqa/selenium/grid/log/BUILD.bazel +++ /dev/null @@ -1,17 +0,0 @@ -load("@rules_jvm_external//:defs.bzl", "artifact") -load("//java:defs.bzl", "JUNIT5_DEPS", "java_test_suite") - -java_test_suite( - name = "SmallTests", - size = "small", - srcs = glob(["*Test.java"]), - deps = [ - "//java/src/org/openqa/selenium:core", - "//java/src/org/openqa/selenium/grid/config", - "//java/src/org/openqa/selenium/grid/log", - artifact("org.assertj:assertj-core"), - artifact("org.junit.jupiter:junit-jupiter-api"), - artifact("uk.org.webcompere:system-stubs-jupiter"), - artifact("uk.org.webcompere:system-stubs-core"), - ] + JUNIT5_DEPS, -) diff --git a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java b/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java deleted file mode 100644 index cddcb53e8d45c..0000000000000 --- a/java/test/org/openqa/selenium/grid/log/LoggingOptionsTest.java +++ /dev/null @@ -1,386 +0,0 @@ -// Licensed to the Software Freedom Conservancy (SFC) under one -// or more contributor license agreements. See the NOTICE file -// distributed with this work for additional information -// regarding copyright ownership. The SFC licenses this file -// to you under the Apache License, Version 2.0 (the -// "License"); you may not use this file except in compliance -// with the License. You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, -// software distributed under the License is distributed on an -// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY -// KIND, either express or implied. See the License for the -// specific language governing permissions and limitations -// under the License. - -package org.openqa.selenium.grid.log; - -import static org.assertj.core.api.Assertions.assertThat; - -import java.io.ByteArrayOutputStream; -import java.io.IOException; -import java.io.PrintStream; -import java.nio.file.Files; -import java.nio.file.Path; -import java.util.ArrayList; -import java.util.Arrays; -import java.util.List; -import java.util.Map; -import java.util.UUID; -import java.util.logging.ConsoleHandler; -import java.util.logging.Handler; -import java.util.logging.Level; -import java.util.logging.LogManager; -import java.util.logging.LogRecord; -import java.util.logging.Logger; -import org.junit.jupiter.api.AfterEach; -import org.junit.jupiter.api.BeforeEach; -import org.junit.jupiter.api.Tag; -import org.junit.jupiter.api.Test; -import org.junit.jupiter.api.extension.ExtendWith; -import org.openqa.selenium.grid.config.MapConfig; -import org.openqa.selenium.internal.Debug; -import uk.org.webcompere.systemstubs.environment.EnvironmentVariables; -import uk.org.webcompere.systemstubs.jupiter.SystemStub; -import uk.org.webcompere.systemstubs.jupiter.SystemStubsExtension; - -@Tag("UnitTests") -@ExtendWith(SystemStubsExtension.class) -class LoggingOptionsTest { - - @SystemStub private EnvironmentVariables environment; - - private String oldDebugProperty; - // Legacy alias for selenium.debug -- Debug.isDebugging() honors either, so a test JVM that - // happens to have this set externally must not leak into the "no switch" baseline assertions. - private String oldVerboseProperty; - private Level oldSeleniumLoggerLevel; - - @BeforeEach - void storeSystemProperty() { - oldDebugProperty = System.getProperty("selenium.debug"); - oldVerboseProperty = System.getProperty("selenium.webdriver.verbose"); - oldSeleniumLoggerLevel = Logger.getLogger("org.openqa.selenium").getLevel(); - System.clearProperty("selenium.debug"); - System.clearProperty("selenium.webdriver.verbose"); - } - - @AfterEach - void restoreSystemProperty() { - if (oldDebugProperty != null) { - System.setProperty("selenium.debug", oldDebugProperty); - } else { - System.clearProperty("selenium.debug"); - } - if (oldVerboseProperty != null) { - System.setProperty("selenium.webdriver.verbose", oldVerboseProperty); - } else { - System.clearProperty("selenium.webdriver.verbose"); - } - // Force the stubbed SE_DEBUG off BEFORE re-syncing Debug below: SystemStubsExtension only - // restores the real environment after this whole method returns (extension callbacks wrap - // user @AfterEach methods), so without this a test that stubbed SE_DEBUG=true would have - // configureLogger() still see debugging "on" here, keep its handler installed, and leak it - // -- with nothing ever re-syncing after the stub's later restoration. Unconditional: safe - // for tests that never touched the stub. - environment.set("SE_DEBUG", "false"); - // Reverts whatever configureLogging() may have done to the shared org.openqa.selenium logger - // via Debug.configureLogger() during the test, now that the properties are back to their - // original values. - Debug.configureLogger(); - Logger.getLogger("org.openqa.selenium").setLevel(oldSeleniumLoggerLevel); - } - - @Test - void setLoggingLevelForcesFineWhenSeleniumDebugPropertyIsSet() { - System.setProperty("selenium.debug", "true"); - - String output = captureStderrDuring(() -> new LoggingOptions(emptyConfig()).setLoggingLevel()); - - // Before this change, only the SE_DEBUG environment variable (isDebugAll()) forced Grid's log - // level to FINE; -Dselenium.debug=true had no effect on Grid at all. Grid operators using that - // property must not silently lose Grid diagnostic output now that RemoteWebDriver's - // configureLogger() reacts to it too. - assertThat(output).contains("forcing Grid log level to FINE"); - } - - @Test - void setLoggingLevelDoesNotForceFineWhenNoDebugSwitchIsSet() { - String output = captureStderrDuring(() -> new LoggingOptions(emptyConfig()).setLoggingLevel()); - - assertThat(output).doesNotContain("forcing Grid log level to FINE"); - } - - @Test - void configureLoggingRaisesSeleniumLoggerEvenWithExternalJulConfigSet() { - // configureLogging() early-returns once an external java.util.logging.config.* property is - // detected, handing the rest of logging setup off entirely. Debug.configureLogger() must still - // run before that early return, or Selenium's own FINE-level wire diagnostics stay invisible - // under -Dselenium.debug=true whenever an operator has such a property set. - System.setProperty("selenium.debug", "true"); - String oldConfigFile = System.getProperty("java.util.logging.config.file"); - System.setProperty("java.util.logging.config.file", "does-not-need-to-exist.properties"); - try { - new LoggingOptions(emptyConfig()).configureLogging(); - - // Checks effective loggability rather than the logger's own explicit level: Debug now - // decides whether to raise off the EFFECTIVE level (Debug.java's effectiveLevel()), so when - // an earlier test already left an ancestor logger (e.g. the root logger, via this same - // configureLogging() path) at FINE-or-more-verbose, org.openqa.selenium's own level - // correctly stays untouched -- there's nothing left to raise. Either way, what actually - // matters -- Selenium's FINE-level wire diagnostics being visible -- must hold. - assertThat(Logger.getLogger("org.openqa.selenium").isLoggable(Level.FINE)).isTrue(); - } finally { - if (oldConfigFile != null) { - System.setProperty("java.util.logging.config.file", oldConfigFile); - } else { - System.clearProperty("java.util.logging.config.file"); - } - } - } - - @Test - void configureLoggingPreservesDebugHandlerWhenNoExternalJulConfigIsSet() { - // configureLogging() enumerates every registered logger and strips its handlers so Grid's own - // console setup starts from a clean slate. org.openqa.selenium stays registered throughout - // (Debug holds a strong static reference to it), so the handler Debug.configureLogger() just - // installed one line above used to get swept up in that too: removed before configureLogging() - // returned, leaving debug mode silently broken since Debug's bookkeeping has no way to learn - // its handler was removed out from under it. - System.setProperty("selenium.debug", "true"); - - new LoggingOptions(emptyConfig()).configureLogging(); - - Logger seleniumLogger = Logger.getLogger("org.openqa.selenium"); - Handler[] handlers = seleniumLogger.getHandlers(); - assertThat(handlers).hasSize(1); - assertThat(handlers[0].getLevel()).isEqualTo(Level.FINE); - - LogRecord infoRecord = new LogRecord(Level.INFO, "info message"); - LogRecord fineRecord = new LogRecord(Level.FINE, "fine message"); - assertThat(handlers[0].isLoggable(infoRecord)).isFalse(); - assertThat(handlers[0].isLoggable(fineRecord)).isTrue(); - } - - @Test - void configureLoggingStripsUnrelatedHandlersFromSeleniumLoggerButKeepsDebugsOwn() { - // The "org.openqa.selenium" exemption in configureLogging()'s handler-reset loop exists only - // to preserve the handler Debug.configureLogger() installs -- not to preserve every handler on - // that logger unconditionally. An unrelated handler some other code attached there must still - // be stripped, same as on any other logger. - System.setProperty("selenium.debug", "true"); - Logger seleniumLogger = Logger.getLogger("org.openqa.selenium"); - Handler unrelatedHandler = new ConsoleHandler(); - seleniumLogger.addHandler(unrelatedHandler); - try { - new LoggingOptions(emptyConfig()).configureLogging(); - - Handler[] handlersAfter = seleniumLogger.getHandlers(); - assertThat(handlersAfter).doesNotContain(unrelatedHandler); - assertThat(handlersAfter).hasSize(1); - assertThat(handlersAfter[0].getLevel()).isEqualTo(Level.FINE); - assertThat(Debug.isOwnHandler(handlersAfter[0])).isTrue(); - } finally { - seleniumLogger.removeHandler(unrelatedHandler); - } - } - - @Test - void configureLoggingDoesNotDuplicateSeleniumDebugRecordsWhenNoLogFileIsConfigured() { - // Debug.configureLogger() (called one line into configureLogging()) installs a handler - // directly on org.openqa.selenium that already prints FINE/CONFIG-range records to stderr -- - // it never disables useParentHandlers, so those same records also propagate up to whatever - // handler(s) configureLogging() itself then attaches to the ROOT logger a few lines later. - // With SE_DEBUG set and no log-file configured, getOutputStream() defaults that root handler - // to System.err too -- the exact same destination Debug's own ConsoleHandler always targets -- - // so nothing stopped a FINE record from org.openqa.selenium(.*) printing twice, once from each - // handler. INFO-and-above records must be unaffected -- Debug's own handler already excludes - // those, so they only ever reached Grid's root handler in the first place. SE_DEBUG is set via - // an environment-variable stub rather than the selenium.debug property: this scenario is - // specifically about Debug.isDebugAll() (SE_DEBUG), which is what makes getOutputStream() - // route to System.err in the first place -- selenium.debug=true alone does not (see - // configureLoggingDoesNotSuppressSeleniumDebugRecordsOnRootHandlerWhenDebugPropertyIsSetWithoutSeDebug - // for that contrasting case). - environment.set("SE_DEBUG", "true"); - String marker = "duplicate-check-" + UUID.randomUUID(); - - Captured captured = - captureStdOutAndErrDuring( - () -> { - new LoggingOptions(emptyConfig()).configureLogging(); - Logger.getLogger("org.openqa.selenium.grid.log.LoggingOptionsTest").fine(marker); - }); - - // Debug's own handler must print it, and Grid's root handler -- defaulting to stderr here, - // the SAME destination as Debug's handler -- must not ALSO print it. Both handlers write to - // stderr in this scenario, so a duplication regression shows up as the marker appearing TWICE - // in the captured stderr; exactly-once is the whole assertion. - assertThat(captured.err()).containsOnlyOnce(marker); - // Secondary sanity check: with SE_DEBUG set and no log-file, nothing routes to stdout at all. - assertThat(captured.out()).doesNotContain(marker); - } - - @Test - void - configureLoggingDoesNotSuppressSeleniumDebugRecordsOnRootHandlerWhenDebugPropertyIsSetWithoutSeDebug() { - // With selenium.debug=true (property only -- SE_DEBUG is deliberately left unset here) and no - // log-file configured, getOutputStream() defaults Grid's root handler to System.out -- - // Debug.isDebugAll() is false in this scenario, so getOutputStream() never routes to - // System.err. Debug's own handler on org.openqa.selenium is always a ConsoleHandler, which per - // its JDK contract always targets System.err regardless of anything Grid does. Root handler - // (stdout) and Debug's handler (stderr) are therefore genuinely DIFFERENT destinations here -- - // suppressing the record from the root handler on the assumption it's already visible via - // Debug's handler would make it invisible to an operator watching Grid's own stdout/structured - // log output, this PR's own advertised primary use case. - System.setProperty("selenium.debug", "true"); - String marker = "distinct-destination-check-" + UUID.randomUUID(); - - Captured captured = - captureStdOutAndErrDuring( - () -> { - new LoggingOptions(emptyConfig()).configureLogging(); - Logger.getLogger("org.openqa.selenium.grid.log.LoggingOptionsTest").fine(marker); - }); - - // Debug's own handler on org.openqa.selenium must still print it -- unchanged behavior. - assertThat(captured.err()).contains(marker); - // Grid's root handler (stdout here, a genuinely different destination) must ALSO print it -- - // it must not be suppressed as if it were a duplicate of Debug's stderr output. - assertThat(captured.out()).contains(marker); - } - - @Test - void configureLoggingLetsSeleniumDebugRecordsReachAConfiguredLogFileAlongsideDebugsHandler() - throws IOException { - // A configured log-file is a destination genuinely separate from anything Debug touches -- - // Debug's own handler always targets stderr (java.util.logging.ConsoleHandler's fixed - // target), regardless of Grid's own logging config. Suppressing FINE/CONFIG-range - // org.openqa.selenium records from that file the same way they're suppressed from the - // stdout/stderr default (above) would silently drop them from the operator's chosen sink and - // its plain/structured formatting -- worse than the duplicate this suppression exists to fix. - // Debug's stderr trace legitimately coexists with the file here; both must fire. - System.setProperty("selenium.debug", "true"); - Path logFile = Files.createTempFile("logging-options-test", ".log"); - String marker = "log-file-check-" + UUID.randomUUID(); - try { - String seleniumErr = - captureStderrDuring( - () -> { - new LoggingOptions( - new MapConfig( - Map.of( - "logging", - Map.of("log-file", logFile.toAbsolutePath().toString())))) - .configureLogging(); - Logger.getLogger("org.openqa.selenium.grid.log.LoggingOptionsTest").fine(marker); - }); - - assertThat(seleniumErr).contains(marker); - assertThat(Files.readString(logFile)).contains(marker); - } finally { - for (Handler handler : LogManager.getLogManager().getLogger("").getHandlers()) { - handler.close(); - } - Files.deleteIfExists(logFile); - } - } - - @Test - void captureStdOutAndErrDuringDoesNotLeakRootLoggerHandlers() { - // configureLogging() installs root-logger handlers bound to whatever System.out/err are AT - // THAT MOMENT (via getOutputStream()). If the capture helper only swaps the streams back - // afterward without also removing those handlers, they keep writing into the now-discarded - // ByteArrayOutputStream instead of the real console, and pollute later tests/output in the - // same JVM. - System.setProperty("selenium.debug", "true"); - Logger rootLogger = LogManager.getLogManager().getLogger(""); - List handlersBefore = List.of(rootLogger.getHandlers()); - - captureStdOutAndErrDuring(() -> new LoggingOptions(emptyConfig()).configureLogging()); - - List leakedHandlers = new ArrayList<>(List.of(rootLogger.getHandlers())); - leakedHandlers.removeAll(handlersBefore); - assertThat(leakedHandlers).isEmpty(); - } - - @Test - void afterEachCleanupTearsDownDebugHandlerInstalledUnderStubbedSeDebug() { - // The @AfterEach cleanup re-syncs Debug via Debug.configureLogger(), which only works if that - // call sees the FINAL switch state. The plain selenium.debug/selenium.webdriver.verbose - // properties are restored synchronously inside that same method, but the stubbed SE_DEBUG is - // only restored by SystemStubsExtension's own lifecycle callback, which runs AFTER user - // @AfterEach methods complete. A cleanup that merely calls configureLogger() therefore still - // sees SE_DEBUG=true, leaves Debug's handler installed, and nothing re-syncs after the stub's - // later restoration -- the handler (and Debug's loggerConfigured bookkeeping) silently leaks - // into every later test in this JVM. Invoking the REAL cleanup method here proves it tears - // the handler down deterministically instead of depending on extension-restoration timing. - environment.set("SE_DEBUG", "true"); - captureStdOutAndErrDuring(() -> new LoggingOptions(emptyConfig()).configureLogging()); - assertThat(Debug.isHandlerCurrentlyInstalled()).isTrue(); - - restoreSystemProperty(); - - assertThat(Debug.isHandlerCurrentlyInstalled()).isFalse(); - } - - private static MapConfig emptyConfig() { - return new MapConfig(Map.of()); - } - - private static String captureStderrDuring(Runnable action) { - PrintStream originalErr = System.err; - ByteArrayOutputStream captured = new ByteArrayOutputStream(); - try { - System.setErr(new PrintStream(captured)); - action.run(); - } finally { - System.setErr(originalErr); - } - return captured.toString(); - } - - private static Captured captureStdOutAndErrDuring(Runnable action) { - PrintStream originalOut = System.out; - PrintStream originalErr = System.err; - ByteArrayOutputStream capturedOut = new ByteArrayOutputStream(); - ByteArrayOutputStream capturedErr = new ByteArrayOutputStream(); - Logger rootLogger = LogManager.getLogManager().getLogger(""); - Handler[] handlersBefore = rootLogger.getHandlers(); - try { - System.setOut(new PrintStream(capturedOut)); - System.setErr(new PrintStream(capturedErr)); - action.run(); - } finally { - System.setOut(originalOut); - System.setErr(originalErr); - for (Handler handler : rootLogger.getHandlers()) { - if (!Arrays.asList(handlersBefore).contains(handler)) { - rootLogger.removeHandler(handler); - handler.close(); - } - } - } - return new Captured(capturedOut.toString(), capturedErr.toString()); - } - - /** Plain holder, not a record: this test target still compiles at source level 11. */ - private static class Captured { - private final String out; - private final String err; - - Captured(String out, String err) { - this.out = out; - this.err = err; - } - - String out() { - return out; - } - - String err() { - return err; - } - } -} diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java index c603124f9bc29..2e248dd9be1e6 100644 --- a/java/test/org/openqa/selenium/internal/DebugTest.java +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -369,6 +369,82 @@ void configureLoggerRepairsAnExternallyRemovedHandlerWithoutCorruptingRestoreBoo assertThat(seleniumLogger().getLevel()).isEqualTo(preDebugLevel); } + @Test + void configureLoggerRepairRestoresHandlerAndFineLoggabilityWithoutReplacingSnapshot() { + Level preDebugLevel = seleniumLogger().getLevel(); + List handlersBeforeDebug = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + + List handlersWhileDebugging = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + handlersWhileDebugging.removeAll(handlersBeforeDebug); + seleniumLogger().removeHandler(handlersWhileDebugging.get(0)); + seleniumLogger().setLevel(Level.INFO); + + Debug.configureLogger(); + + assertThat(Debug.isHandlerCurrentlyInstalled()).isTrue(); + assertThat(seleniumLogger().isLoggable(Level.FINE)).isTrue(); + + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + + assertThat(seleniumLogger().getLevel()).isEqualTo(preDebugLevel); + } + + @Test + void configureLoggerDoesNotChangeRootLoggerForSystemPropertyDebugging() { + Logger rootLogger = Logger.getLogger(""); + Level rootLevel = rootLogger.getLevel(); + List rootHandlers = List.of(rootLogger.getHandlers()); + + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + + assertThat(rootLogger.getLevel()).isEqualTo(rootLevel); + assertThat(rootLogger.getHandlers()).containsExactlyElementsOf(rootHandlers); + } + + @Test + void configureLoggerLeavesExplicitMoreVerboseLevelsEffective() { + for (Level level : List.of(Level.FINER, Level.FINEST, Level.ALL)) { + seleniumLogger().setLevel(level); + System.setProperty("selenium.debug", "true"); + + Debug.configureLogger(); + + assertThat(seleniumLogger().getLevel()).isEqualTo(level); + assertThat(seleniumLogger().isLoggable(level)).isTrue(); + + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + } + } + + @Test + void configureLoggerLeavesInheritedMoreVerboseLevelsEffective() { + Logger parentLogger = Logger.getLogger("org.openqa"); + Level oldParentLevel = parentLogger.getLevel(); + try { + for (Level level : List.of(Level.FINER, Level.FINEST, Level.ALL)) { + parentLogger.setLevel(level); + seleniumLogger().setLevel(null); + System.setProperty("selenium.debug", "true"); + + Debug.configureLogger(); + + assertThat(seleniumLogger().getLevel()).isNull(); + assertThat(seleniumLogger().isLoggable(level)).isTrue(); + + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + } + } finally { + parentLogger.setLevel(oldParentLevel); + } + } + @Test void isHandlerCurrentlyInstalledReflectsExternalHandlerRemoval() { // isHandlerCurrentlyInstalled() must answer whether Debug's handler is REALLY still attached diff --git a/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java b/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java index aec6358cdf088..d9e9719ac54d6 100644 --- a/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java +++ b/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java @@ -41,6 +41,10 @@ import java.util.concurrent.Future; import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.atomic.AtomicReference; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.openqa.selenium.TimeoutException; @@ -355,4 +359,39 @@ void shouldDeliverUnmodifiedServerErrors() { assertThat(handler.execute(new HttpRequest(GET, "/"))).isSameAs(lastResponse.get()); assertThat(count).hasValue(3); } + + @Test + void retryRecordsStayFineWhenSystemPropertyDebuggingIsEnabled() { + Logger logger = Logger.getLogger(RetryRequest.class.getName()); + Level oldLevel = logger.getLevel(); + List records = new ArrayList<>(); + Handler handler = + new Handler() { + @Override + public void publish(LogRecord record) { + records.add(record); + } + + @Override + public void flush() {} + + @Override + public void close() {} + }; + handler.setLevel(Level.ALL); + logger.setLevel(Level.ALL); + logger.addHandler(handler); + System.setProperty("selenium.debug", "true"); + try { + new RetryRequest() + .andFinally(request -> new HttpResponse().setStatus(HTTP_UNAVAILABLE)) + .execute(new HttpRequest(GET, "/")); + + assertThat(records).extracting(LogRecord::getLevel).contains(Level.FINE); + } finally { + System.clearProperty("selenium.debug"); + logger.removeHandler(handler); + logger.setLevel(oldLevel); + } + } } From 1a69c0d05a8340134b286226cc64dd3a7f98b5e9 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Sat, 1 Aug 2026 17:37:20 +0300 Subject: [PATCH 13/19] [java] Propagate requested debug level --- .../org/openqa/selenium/internal/Debug.java | 36 ++++++++++++------- .../org/openqa/selenium/internal/BUILD.bazel | 2 ++ .../openqa/selenium/internal/DebugTest.java | 30 ++++++++++++++++ 3 files changed, 56 insertions(+), 12 deletions(-) diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index 347e86437d84e..32e14ae736564 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -36,6 +36,8 @@ public class Debug { private static Handler installedHandler = null; private static Level previousLevel = null; private static boolean levelRaisedByDebug = false; + private static Level configuredLevel = null; + private static Level levelSetByDebug = null; private Debug() { // Utility class @@ -167,7 +169,9 @@ public static synchronized void configureLogger() { // reset, or unrelated code calling removeHandler() directly) can remove it without ever // going through configureLogger(), and that divergence must be repaired here rather than // silently left until the debug switch itself changes. - if (shouldDebug == loggerConfigured && (!shouldDebug || isHandlerCurrentlyInstalled())) { + if (shouldDebug == loggerConfigured + && (!shouldDebug + || (isHandlerCurrentlyInstalled() && requestedLevel.equals(configuredLevel)))) { return; } @@ -178,6 +182,7 @@ public static synchronized void configureLogger() { // level happens to be right now, corrupting the snapshot that turning debug off later needs // to restore the correct pre-debug level. if (!loggerConfigured) { + configuredLevel = requestedLevel; // Only raise the level when the logger's EFFECTIVE level is currently LESS verbose than // FINE (higher intValue). A more-verbose effective level (FINER, FINEST, ALL) is left // alone: lowering it would make records like W3CHttpResponseCodec's FINER diagnostics @@ -199,17 +204,20 @@ public static synchronized void configureLogger() { if (effectiveLevel(SELENIUM_LOGGER).intValue() > requestedLevel.intValue()) { SELENIUM_LOGGER.setLevel(requestedLevel); + levelSetByDebug = requestedLevel; } - // Runs unconditionally whenever shouldDebug is true and we reach this point -- both on a - // genuine turn-on and on a handler-repair call -- since that's the actual state that needs - // fixing in the repair case. - Handler handler = new ConsoleHandler(); - handler.setLevel(Level.FINE); - Filter belowInfo = record -> record.getLevel().intValue() < Level.INFO.intValue(); - handler.setFilter(belowInfo); - SELENIUM_LOGGER.addHandler(handler); - installedHandler = handler; + configuredLevel = requestedLevel; + if (isHandlerCurrentlyInstalled()) { + installedHandler.setLevel(requestedLevel); + } else { + Handler handler = new ConsoleHandler(); + handler.setLevel(requestedLevel); + Filter belowInfo = record -> record.getLevel().intValue() < Level.INFO.intValue(); + handler.setFilter(belowInfo); + SELENIUM_LOGGER.addHandler(handler); + installedHandler = handler; + } } else { // installedHandler can already be null here if it was removed externally and debugging // turned off before any repair call ever ran -- Logger.removeHandler(null) throws NPE per @@ -220,14 +228,18 @@ public static synchronized void configureLogger() { installedHandler = null; } // Restore only when Debug itself raised the level AND nothing else changed it since. The - // FINE-equality guard keeps the existing "external override while debugging" protection; + // The equality guard keeps the existing "external override while debugging" protection; // levelRaisedByDebug additionally covers the case where Debug never touched the level at // all and so has nothing to restore. - if (levelRaisedByDebug && Level.FINE.equals(SELENIUM_LOGGER.getLevel())) { + if (levelRaisedByDebug + && levelSetByDebug != null + && levelSetByDebug.equals(SELENIUM_LOGGER.getLevel())) { SELENIUM_LOGGER.setLevel(previousLevel); } levelRaisedByDebug = false; previousLevel = null; + configuredLevel = null; + levelSetByDebug = null; } loggerConfigured = shouldDebug; diff --git a/java/test/org/openqa/selenium/internal/BUILD.bazel b/java/test/org/openqa/selenium/internal/BUILD.bazel index e0e9427d6cb5d..4a70406ee6f39 100644 --- a/java/test/org/openqa/selenium/internal/BUILD.bazel +++ b/java/test/org/openqa/selenium/internal/BUILD.bazel @@ -9,5 +9,7 @@ java_test_suite( "//java/src/org/openqa/selenium:core", artifact("org.assertj:assertj-core"), artifact("org.junit.jupiter:junit-jupiter-api"), + artifact("uk.org.webcompere:system-stubs-core"), + artifact("uk.org.webcompere:system-stubs-jupiter"), ] + JUNIT5_DEPS, ) diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java index 2e248dd9be1e6..09292fc83f0a2 100644 --- a/java/test/org/openqa/selenium/internal/DebugTest.java +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -33,8 +33,13 @@ import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Tag; import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.ExtendWith; +import uk.org.webcompere.systemstubs.environment.EnvironmentVariables; +import uk.org.webcompere.systemstubs.jupiter.SystemStub; +import uk.org.webcompere.systemstubs.jupiter.SystemStubsExtension; @Tag("UnitTests") +@ExtendWith(SystemStubsExtension.class) class DebugTest { /** @@ -50,6 +55,8 @@ private static Logger seleniumLogger() { private String oldVerboseProperty; private Level oldLoggerLevel; + @SystemStub private EnvironmentVariables environment; + @BeforeEach void storeSystemProperties() { oldDebugProperty = System.getProperty("selenium.debug"); @@ -406,6 +413,29 @@ void configureLoggerDoesNotChangeRootLoggerForSystemPropertyDebugging() { assertThat(rootLogger.getHandlers()).containsExactlyElementsOf(rootHandlers); } + @Test + void seDebugConfiguresFineHandlerAndRestoresLoggerLevel() { + environment.set("SE_DEBUG", "false"); + Debug.configureLogger(); + Level preDebugLevel = seleniumLogger().getLevel(); + List handlersBeforeDebug = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + + environment.set("SE_DEBUG", "true"); + Debug.configureLogger(); + + List handlersWhileDebugging = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + handlersWhileDebugging.removeAll(handlersBeforeDebug); + assertThat(handlersWhileDebugging) + .singleElement() + .extracting(Handler::getLevel) + .isEqualTo(Level.FINE); + + environment.set("SE_DEBUG", "false"); + Debug.configureLogger(); + + assertThat(seleniumLogger().getLevel()).isEqualTo(preDebugLevel); + } + @Test void configureLoggerLeavesExplicitMoreVerboseLevelsEffective() { for (Level level : List.of(Level.FINER, Level.FINEST, Level.ALL)) { From 65a4e4ee3cbc47092ae28c27eba0aafed1f98c35 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Sat, 1 Aug 2026 17:43:01 +0300 Subject: [PATCH 14/19] [java] Repair configured debug logger level --- .../org/openqa/selenium/internal/Debug.java | 8 ++++--- .../openqa/selenium/internal/DebugTest.java | 24 +++++++++++++++++++ 2 files changed, 29 insertions(+), 3 deletions(-) diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index 32e14ae736564..c078f68682bbf 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -91,7 +91,7 @@ public static boolean isHandledBySeleniumDebugHandler(String loggerName, Level l && (loggerName.equals("org.openqa.selenium") || loggerName.startsWith("org.openqa.selenium.")); return withinSeleniumHierarchy - && level.intValue() >= Level.FINE.intValue() + && level.intValue() >= installedHandler.getLevel().intValue() && level.intValue() < Level.INFO.intValue(); } @@ -171,7 +171,9 @@ public static synchronized void configureLogger() { // silently left until the debug switch itself changes. if (shouldDebug == loggerConfigured && (!shouldDebug - || (isHandlerCurrentlyInstalled() && requestedLevel.equals(configuredLevel)))) { + || (isHandlerCurrentlyInstalled() + && requestedLevel.equals(configuredLevel) + && effectiveLevel(SELENIUM_LOGGER).intValue() <= requestedLevel.intValue()))) { return; } @@ -228,7 +230,7 @@ public static synchronized void configureLogger() { installedHandler = null; } // Restore only when Debug itself raised the level AND nothing else changed it since. The - // The equality guard keeps the existing "external override while debugging" protection; + // equality guard keeps the existing "external override while debugging" protection; // levelRaisedByDebug additionally covers the case where Debug never touched the level at // all and so has nothing to restore. if (levelRaisedByDebug diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java index 09292fc83f0a2..e7de48ae36e4c 100644 --- a/java/test/org/openqa/selenium/internal/DebugTest.java +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -400,6 +400,30 @@ void configureLoggerRepairRestoresHandlerAndFineLoggabilityWithoutReplacingSnaps assertThat(seleniumLogger().getLevel()).isEqualTo(preDebugLevel); } + @Test + void configureLoggerRepairsLevelWithoutReplacingItsHandler() { + Level preDebugLevel = seleniumLogger().getLevel(); + List handlersBeforeDebug = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + + List handlersWhileDebugging = new ArrayList<>(List.of(seleniumLogger().getHandlers())); + handlersWhileDebugging.removeAll(handlersBeforeDebug); + Handler installedHandler = handlersWhileDebugging.get(0); + seleniumLogger().setLevel(Level.INFO); + + Debug.configureLogger(); + + assertThat(seleniumLogger().getHandlers()).contains(installedHandler); + assertThat(seleniumLogger().isLoggable(Level.FINE)).isTrue(); + + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + + assertThat(seleniumLogger().getLevel()).isEqualTo(preDebugLevel); + } + @Test void configureLoggerDoesNotChangeRootLoggerForSystemPropertyDebugging() { Logger rootLogger = Logger.getLogger(""); From 9b8a93e08ba84a789269f5ddfdd9604840eaeae0 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Sat, 1 Aug 2026 17:54:23 +0300 Subject: [PATCH 15/19] [java] Restore repaired debug logger level --- .../org/openqa/selenium/internal/Debug.java | 28 +++------- .../openqa/selenium/internal/DebugTest.java | 52 ++++++++++++++++++- 2 files changed, 57 insertions(+), 23 deletions(-) diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index c078f68682bbf..292e8da68bd12 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -178,35 +178,19 @@ && effectiveLevel(SELENIUM_LOGGER).intValue() <= requestedLevel.intValue()))) { } if (shouldDebug) { - // Only run the level-raising bookkeeping on a genuine off->on transition. A call that - // reaches here merely to repair a missing handler (loggerConfigured already true) must not - // re-run this: doing so would overwrite levelRaisedByDebug/previousLevel with whatever the - // level happens to be right now, corrupting the snapshot that turning debug off later needs - // to restore the correct pre-debug level. + // Capture the original own level on a genuine off->on transition. A repair call must not + // overwrite this snapshot with the level it is repairing. if (!loggerConfigured) { configuredLevel = requestedLevel; - // Only raise the level when the logger's EFFECTIVE level is currently LESS verbose than - // FINE (higher intValue). A more-verbose effective level (FINER, FINEST, ALL) is left - // alone: lowering it would make records like W3CHttpResponseCodec's FINER diagnostics - // unloggable while "debugging". This decides off the effective level rather than the - // logger's own (possibly null/inherited) level -- a null own level with a more-verbose - // level set on a parent logger already means FINER-or-better records are loggable right - // now, and forcing this logger's own level to FINE would clobber that inherited - // verbosity. What gets snapshotted/restored is still the logger's own level exactly as - // before; only the raise/no-raise decision changes. - Level currentLevel = SELENIUM_LOGGER.getLevel(); - levelRaisedByDebug = - effectiveLevel(SELENIUM_LOGGER).intValue() > requestedLevel.intValue(); - if (levelRaisedByDebug) { - previousLevel = currentLevel; - } else { - previousLevel = null; - } + previousLevel = SELENIUM_LOGGER.getLevel(); + levelRaisedByDebug = false; + levelSetByDebug = null; } if (effectiveLevel(SELENIUM_LOGGER).intValue() > requestedLevel.intValue()) { SELENIUM_LOGGER.setLevel(requestedLevel); levelSetByDebug = requestedLevel; + levelRaisedByDebug = true; } configuredLevel = requestedLevel; diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java index e7de48ae36e4c..5d0fc52a8073d 100644 --- a/java/test/org/openqa/selenium/internal/DebugTest.java +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -21,14 +21,19 @@ import java.io.ByteArrayOutputStream; import java.io.PrintStream; +import java.io.UnsupportedEncodingException; import java.util.ArrayList; import java.util.List; import java.util.UUID; import java.util.logging.ConsoleHandler; +import java.util.logging.ErrorManager; +import java.util.logging.Filter; +import java.util.logging.Formatter; import java.util.logging.Handler; import java.util.logging.Level; import java.util.logging.LogRecord; import java.util.logging.Logger; +import java.util.logging.SimpleFormatter; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Tag; @@ -167,17 +172,35 @@ void configureLoggerIsIdempotent() { } @Test - void configureLoggerLeavesUserHandlersAlone() { + void configureLoggerLeavesUserHandlerConfigurationAlone() throws UnsupportedEncodingException { Handler userHandler = new ConsoleHandler(); + Filter userFilter = record -> false; + Formatter userFormatter = new SimpleFormatter(); + ErrorManager userErrorManager = new ErrorManager(); + userHandler.setLevel(Level.WARNING); + userHandler.setFilter(userFilter); + userHandler.setFormatter(userFormatter); + userHandler.setEncoding("UTF-8"); + userHandler.setErrorManager(userErrorManager); seleniumLogger().addHandler(userHandler); try { System.setProperty("selenium.debug", "true"); Debug.configureLogger(); assertThat(seleniumLogger().getHandlers()).contains(userHandler); + assertThat(userHandler.getLevel()).isEqualTo(Level.WARNING); + assertThat(userHandler.getFilter()).isSameAs(userFilter); + assertThat(userHandler.getFormatter()).isSameAs(userFormatter); + assertThat(userHandler.getEncoding()).isEqualTo("UTF-8"); + assertThat(userHandler.getErrorManager()).isSameAs(userErrorManager); System.clearProperty("selenium.debug"); Debug.configureLogger(); assertThat(seleniumLogger().getHandlers()).contains(userHandler); + assertThat(userHandler.getLevel()).isEqualTo(Level.WARNING); + assertThat(userHandler.getFilter()).isSameAs(userFilter); + assertThat(userHandler.getFormatter()).isSameAs(userFormatter); + assertThat(userHandler.getEncoding()).isEqualTo("UTF-8"); + assertThat(userHandler.getErrorManager()).isSameAs(userErrorManager); } finally { seleniumLogger().removeHandler(userHandler); } @@ -499,6 +522,33 @@ void configureLoggerLeavesInheritedMoreVerboseLevelsEffective() { } } + @Test + void configureLoggerRestoresMoreVerboseLevelAfterLateRepair() { + Logger parentLogger = Logger.getLogger("org.openqa"); + Level oldParentLevel = parentLogger.getLevel(); + parentLogger.setLevel(Level.FINER); + try { + for (boolean inherited : List.of(false, true)) { + seleniumLogger().setLevel(inherited ? null : Level.FINER); + System.setProperty("selenium.debug", "true"); + Debug.configureLogger(); + + seleniumLogger().setLevel(Level.INFO); + Debug.configureLogger(); + + assertThat(seleniumLogger().isLoggable(Level.FINE)).isTrue(); + + System.clearProperty("selenium.debug"); + Debug.configureLogger(); + + assertThat(seleniumLogger().getLevel()).isEqualTo(inherited ? null : Level.FINER); + assertThat(seleniumLogger().isLoggable(Level.FINER)).isTrue(); + } + } finally { + parentLogger.setLevel(oldParentLevel); + } + } + @Test void isHandlerCurrentlyInstalledReflectsExternalHandlerRemoval() { // isHandlerCurrentlyInstalled() must answer whether Debug's handler is REALLY still attached From d536e3ad097ad6040c1cc29708acff07ae5690a7 Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Sat, 1 Aug 2026 18:56:02 +0300 Subject: [PATCH 16/19] [java] Make debug handler inspection atomic --- java/src/org/openqa/selenium/internal/Debug.java | 7 ++++--- .../test/org/openqa/selenium/internal/DebugTest.java | 1 + .../selenium/remote/http/RetryRequestTest.java | 12 ++++++++++-- 3 files changed, 15 insertions(+), 5 deletions(-) diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index 292e8da68bd12..0d94eaacde54e 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -82,8 +82,9 @@ public static synchronized boolean isOwnHandler(Handler handler) { return handler != null && handler == installedHandler; } - public static boolean isHandledBySeleniumDebugHandler(String loggerName, Level level) { - if (!isHandlerCurrentlyInstalled()) { + public static synchronized boolean isHandledBySeleniumDebugHandler(String loggerName, Level level) { + Handler handler = installedHandler; + if (handler == null || !Arrays.asList(SELENIUM_LOGGER.getHandlers()).contains(handler)) { return false; } boolean withinSeleniumHierarchy = @@ -91,7 +92,7 @@ public static boolean isHandledBySeleniumDebugHandler(String loggerName, Level l && (loggerName.equals("org.openqa.selenium") || loggerName.startsWith("org.openqa.selenium.")); return withinSeleniumHierarchy - && level.intValue() >= installedHandler.getLevel().intValue() + && level.intValue() >= handler.getLevel().intValue() && level.intValue() < Level.INFO.intValue(); } diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java index 5d0fc52a8073d..0b08933f6d20b 100644 --- a/java/test/org/openqa/selenium/internal/DebugTest.java +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -576,5 +576,6 @@ void isHandlerCurrentlyInstalledReflectsExternalHandlerRemoval() { assertThat(Debug.isHandlerCurrentlyInstalled()) .as("the handler was removed out from under Debug's bookkeeping by something else") .isFalse(); + assertThat(Debug.isHandledBySeleniumDebugHandler("org.openqa.selenium", Level.FINE)).isFalse(); } } diff --git a/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java b/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java index d9e9719ac54d6..4ff358714f19d 100644 --- a/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java +++ b/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java @@ -364,6 +364,7 @@ void shouldDeliverUnmodifiedServerErrors() { void retryRecordsStayFineWhenSystemPropertyDebuggingIsEnabled() { Logger logger = Logger.getLogger(RetryRequest.class.getName()); Level oldLevel = logger.getLevel(); + String originalDebugProperty = System.getProperty("selenium.debug"); List records = new ArrayList<>(); Handler handler = new Handler() { @@ -381,17 +382,24 @@ public void close() {} handler.setLevel(Level.ALL); logger.setLevel(Level.ALL); logger.addHandler(handler); - System.setProperty("selenium.debug", "true"); + System.setProperty("selenium.debug", "false"); try { + System.setProperty("selenium.debug", "true"); new RetryRequest() .andFinally(request -> new HttpResponse().setStatus(HTTP_UNAVAILABLE)) .execute(new HttpRequest(GET, "/")); assertThat(records).extracting(LogRecord::getLevel).contains(Level.FINE); } finally { - System.clearProperty("selenium.debug"); + System.setProperty("selenium.debug", "false"); + assertThat(System.getProperty("selenium.debug")).isEqualTo("false"); logger.removeHandler(handler); logger.setLevel(oldLevel); + if (originalDebugProperty == null) { + System.clearProperty("selenium.debug"); + } else { + System.setProperty("selenium.debug", originalDebugProperty); + } } } } From f87fd10ae28b532a005542a467e33277498defeb Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Sat, 1 Aug 2026 19:11:32 +0300 Subject: [PATCH 17/19] [java] Remove unused debug handler APIs --- .../org/openqa/selenium/grid/log/BUILD.bazel | 1 - .../org/openqa/selenium/internal/Debug.java | 20 +------------ .../openqa/selenium/internal/DebugTest.java | 28 ------------------- 3 files changed, 1 insertion(+), 48 deletions(-) diff --git a/java/src/org/openqa/selenium/grid/log/BUILD.bazel b/java/src/org/openqa/selenium/grid/log/BUILD.bazel index 78b93d5c555ae..68c796f96396b 100644 --- a/java/src/org/openqa/selenium/grid/log/BUILD.bazel +++ b/java/src/org/openqa/selenium/grid/log/BUILD.bazel @@ -7,7 +7,6 @@ java_library( visibility = [ "//java/src/org/openqa/selenium/grid:__subpackages__", "//java/src/org/openqa/selenium/remote/server:__subpackages__", - "//java/test/org/openqa/selenium/grid/log:__pkg__", ], deps = [ "//java:auto-service", diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index 0d94eaacde54e..5baa29ce74b75 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -73,29 +73,11 @@ public static Level getDebugLogLevel() { return isDebugging() ? Level.INFO : Level.FINE; } - public static synchronized boolean isHandlerCurrentlyInstalled() { + static synchronized boolean isHandlerCurrentlyInstalled() { return installedHandler != null && Arrays.asList(SELENIUM_LOGGER.getHandlers()).contains(installedHandler); } - public static synchronized boolean isOwnHandler(Handler handler) { - return handler != null && handler == installedHandler; - } - - public static synchronized boolean isHandledBySeleniumDebugHandler(String loggerName, Level level) { - Handler handler = installedHandler; - if (handler == null || !Arrays.asList(SELENIUM_LOGGER.getHandlers()).contains(handler)) { - return false; - } - boolean withinSeleniumHierarchy = - loggerName != null - && (loggerName.equals("org.openqa.selenium") - || loggerName.startsWith("org.openqa.selenium.")); - return withinSeleniumHierarchy - && level.intValue() >= handler.getLevel().intValue() - && level.intValue() < Level.INFO.intValue(); - } - public static boolean isDebugAll() { boolean everything = Boolean.parseBoolean(System.getenv("SE_DEBUG")); if (everything && DEBUG_WARNING_LOGGED.compareAndSet(false, true)) { diff --git a/java/test/org/openqa/selenium/internal/DebugTest.java b/java/test/org/openqa/selenium/internal/DebugTest.java index 0b08933f6d20b..9b91a02c46b29 100644 --- a/java/test/org/openqa/selenium/internal/DebugTest.java +++ b/java/test/org/openqa/selenium/internal/DebugTest.java @@ -339,33 +339,6 @@ void getDebugLogLevelStillReportsInfoWhileDeprecated() { assertThat(Debug.getDebugLogLevel()).isEqualTo(Level.FINE); } - @Test - void isHandledBySeleniumDebugHandlerReflectsActualHandlerInstallationNotLiveProperty() { - // isHandledBySeleniumDebugHandler() exists so a caller further up the logger hierarchy (e.g. - // Grid's root handler) can tell whether THIS handler will actually also print a given record, - // to avoid a duplicate. That question is about the handler's real, current installation - // state, not the live system property: a property change takes effect only once something - // calls configureLogger() again to react to it, and the two can genuinely diverge for however - // long that takes -- checking the live property instead would answer "yes, handled" the - // instant the property flips, even though the handler that must actually be there to back - // that answer hasn't been installed (or removed) yet. - System.setProperty("selenium.debug", "true"); - Debug.configureLogger(); - assertThat(Debug.isHandledBySeleniumDebugHandler("org.openqa.selenium", Level.FINE)).isTrue(); - - // The property flips off, but nothing has called configureLogger() again yet -- the handler - // installed above is still attached and will still print a FINE record published right now. - System.clearProperty("selenium.debug"); - assertThat(Debug.isHandledBySeleniumDebugHandler("org.openqa.selenium", Level.FINE)) - .as("the handler installed while debugging was on is still attached and still handling") - .isTrue(); - - // Only once configureLogger() actually reacts does the handler come off, and only then must - // callers stop treating this range as already handled. - Debug.configureLogger(); - assertThat(Debug.isHandledBySeleniumDebugHandler("org.openqa.selenium", Level.FINE)).isFalse(); - } - @Test void configureLoggerRepairsAnExternallyRemovedHandlerWithoutCorruptingRestoreBookkeeping() { Level preDebugLevel = seleniumLogger().getLevel(); @@ -576,6 +549,5 @@ void isHandlerCurrentlyInstalledReflectsExternalHandlerRemoval() { assertThat(Debug.isHandlerCurrentlyInstalled()) .as("the handler was removed out from under Debug's bookkeeping by something else") .isFalse(); - assertThat(Debug.isHandledBySeleniumDebugHandler("org.openqa.selenium", Level.FINE)).isFalse(); } } From c7ba45403a8c1180d534ce6d6aa1dc9ef4e9d44d Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Mon, 3 Aug 2026 03:45:32 +0300 Subject: [PATCH 18/19] [java] Clarify debug logger configuration --- .../org/openqa/selenium/internal/Debug.java | 18 ++++++++++-------- 1 file changed, 10 insertions(+), 8 deletions(-) diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index 5baa29ce74b75..34b9fe445243f 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -111,10 +111,10 @@ private static Level effectiveLevel(Logger logger) { @Nullable private static Level getRequestedLogLevel() { - if (isDebugging()) { + if (isDebugAll()) { return Level.FINE; } - if (isDebugAll()) { + if (isDebugging()) { return Level.FINE; } return null; @@ -125,9 +125,10 @@ private static Level getRequestedLogLevel() { * -Dselenium.webdriver.verbose=true}, {@code SE_DEBUG}) onto the real {@code org.openqa.selenium} * logger: raises it to {@link Level#FINE} when it is currently less verbose than {@link * Level#FINE}; a level already at {@link Level#FINE} or more verbose is left untouched. It also - * attaches a handler Selenium owns, filtered to leave {@link Level#INFO} and above to the - * caller's own handlers so output they already print is never duplicated. Idempotent: repeated - * calls while the switches are unchanged do nothing. Reversible: once every switch is off, the + * attaches a handler Selenium owns, filtered to exclude {@link Level#INFO} and above. Caller-owned + * direct or ancestor handlers that accept {@link Level#FINE} can still receive and print FINE + * records, so FINE output can be duplicated. Idempotent: repeated calls while the switches are + * unchanged do nothing. Reversible: once every switch is off, the * next call removes exactly the handler this method installed and restores the logger's level to * what it was before debugging turned on, only when this method was the one that raised it and * unless something else changed the level in the meantime -- that change is left alone rather @@ -140,9 +141,10 @@ private static Level getRequestedLogLevel() { * SE_DEBUG} environment variable is set it puts the {@code selenium} logger at {@code DEBUG} and * attaches an unfiltered {@code StreamHandler} if the logger has none of its own. Two deliberate * differences here: Java only raises the level when the logger is currently less verbose than - * {@link Level#FINE} (Python sets {@code DEBUG} unconditionally), and Java's handler is filtered - * to records below {@link Level#INFO} so output the caller's own handlers already print is never - * duplicated. + * {@link Level#FINE} (Python sets {@code DEBUG} unconditionally), and Java's Selenium-owned + * handler is filtered to records below {@link Level#INFO}. Caller-owned direct or ancestor + * handlers accepting {@link Level#FINE} can still print FINE records, so duplicates remain + * possible. */ public static synchronized void configureLogger() { Level requestedLevel = getRequestedLogLevel(); From 7372c1ef2eaf39ebcdd3b030427a159027a483ff Mon Sep 17 00:00:00 2001 From: Mohab Mohie Date: Mon, 3 Aug 2026 03:49:46 +0300 Subject: [PATCH 19/19] [java] Clarify debug logger repair behavior --- java/src/org/openqa/selenium/internal/Debug.java | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/java/src/org/openqa/selenium/internal/Debug.java b/java/src/org/openqa/selenium/internal/Debug.java index 34b9fe445243f..da585ca389a4c 100644 --- a/java/src/org/openqa/selenium/internal/Debug.java +++ b/java/src/org/openqa/selenium/internal/Debug.java @@ -127,8 +127,9 @@ private static Level getRequestedLogLevel() { * Level#FINE}; a level already at {@link Level#FINE} or more verbose is left untouched. It also * attaches a handler Selenium owns, filtered to exclude {@link Level#INFO} and above. Caller-owned * direct or ancestor handlers that accept {@link Level#FINE} can still receive and print FINE - * records, so FINE output can be duplicated. Idempotent: repeated calls while the switches are - * unchanged do nothing. Reversible: once every switch is off, the + * records, so FINE output can be duplicated. Calls are no-ops when the requested configuration + * is already consistent, but repair the Selenium-owned handler and FINE loggability after + * external divergence. Reversible: once every switch is off, the * next call removes exactly the handler this method installed and restores the logger's level to * what it was before debugging turned on, only when this method was the one that raised it and * unless something else changed the level in the meantime -- that change is left alone rather