[java] Make selenium.debug/webdriver.verbose configure the real logger (Mechanism Only)

java/src/org/openqa/selenium/internal/Debug.java

@@ -17,37 +17,80 @@
 
 package org.openqa.selenium.internal;
 
+import java.util.Arrays;
 import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.logging.ConsoleHandler;
+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;
+import org.jspecify.annotations.Nullable;
 
-/** Used to provide information about whether Selenium is running under debug mode. */
+/**
+ * Decides whether Selenium's Java bindings run in debug mode and exposes Selenium's diagnostic log
+ * records when they do.
+ *
+ * <p>Debug mode is a convenience for troubleshooting. It is switched on by either of these:
+ *
+ * <ul>
+ *   <li>the {@code selenium.debug} system property, or the legacy {@code
+ *       selenium.webdriver.verbose} property, which only affect the Java bindings' {@code
+ *       java.util.logging} output; or
+ *   <li>the {@code SE_DEBUG} environment variable, the broader switch also used by Selenium Grid,
+ *       the other language bindings and the driver services.
+ * </ul>
+ *
+ * <p>Users who need fine-grained control should configure {@code java.util.logging} or an SLF4J
+ * bridge themselves instead.
+ */
 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;
+  private static final Object LOCK = new Object();
+  // Kept separate so either switch can move to a more verbose level without changing the other.
+  private static final Level SE_DEBUG_LEVEL = Level.FINE;
+  private static final Level DEBUG_PROPERTY_LEVEL = Level.FINE;
 
-  static {
-    IS_DEBUG =
-        Boolean.getBoolean("selenium.debug") || Boolean.getBoolean("selenium.webdriver.verbose");
-  }
+  private static @Nullable Level enabledLevel;
+  private static @Nullable Handler installedHandler;
 
   private Debug() {
     // Utility class
   }
 
+  /**
+   * Returns whether the {@code selenium.debug} or {@code selenium.webdriver.verbose} system
+   * property is currently set to {@code true}.
+   *
+   * <p>The properties are read on every call, so a value set after Selenium's classes are loaded is
+   * honoured.
+   *
+   * @return {@code true} if either debug system property is currently enabled
+   */
   public static boolean isDebugging() {
-    return IS_DEBUG;
+    return Boolean.getBoolean("selenium.debug") || Boolean.getBoolean("selenium.webdriver.verbose");
   }
 
+  /**
+   * Returns the level that legacy call sites use for their diagnostic messages.
+   *
+   * @return {@link Level#INFO} while {@link #isDebugging()} is {@code true}, {@link Level#FINE}
+   *     otherwise
+   * @deprecated Log diagnostics at a fixed level such as {@link Level#FINE}. {@link
+   *     #configureLogger()} makes those records visible when debugging is enabled.
+   */
+  @Deprecated(forRemoval = true)
   public static Level getDebugLogLevel() {
     return isDebugging() ? Level.INFO : Level.FINE;
   }
 
+  /**
+   * Returns whether the {@code SE_DEBUG} environment variable is set to {@code true}.
+   *
+   * <p>The first time this returns {@code true}, a warning is printed to {@code System.err}.
+   *
+   * @return {@code true} if {@code SE_DEBUG} is enabled
+   */
   public static boolean isDebugAll() {
     boolean everything = Boolean.parseBoolean(System.getenv("SE_DEBUG"));
     if (everything && DEBUG_WARNING_LOGGED.compareAndSet(false, true)) {
@@ -59,16 +102,107 @@ public static boolean isDebugAll() {
     return everything;
   }
 
+  /**
+   * Shows Selenium's diagnostic log records on the console if debugging is enabled.
+   *
+   * <p>The switches are read on every call. Once one of them has been seen, debug logging stays on
+   * for the life of the JVM, even if the switch is turned off again later. While debugging is on,
+   * each call makes sure that:
+   *
+   * <ul>
+   *   <li>the {@code org.openqa.selenium} logger lets {@link Level#FINE} records through. A level
+   *       that is already more verbose, set on the logger or inherited from a parent, is left as it
+   *       is; and
+   *   <li>one Selenium-owned console handler, which prints records below {@link Level#INFO} to
+   *       {@code System.err}, is attached to that logger. It is re-attached if something removed
+   *       it.
+   * </ul>
+   *
+   * <p>Handlers added by the user, and the root logger, are never changed. Because Selenium's
+   * handler prints every record below {@code INFO}, a user who has also attached a handler that
+   * accepts {@code FINE} records will see those records twice. Records at {@code INFO} and above
+   * are left to the handlers that already print them, such as the root logger's console handler, so
+   * a user who turns off {@code useParentHandlers} on {@code org.openqa.selenium} must attach their
+   * own handler to see them.
+   *
+   * <p>Calling this method when debugging is disabled does nothing. It is safe to call repeatedly
+   * and from several threads.
+   *
+   * <pre>{@code
+   * System.setProperty("selenium.debug", "true");
+   * Debug.configureLogger(); // FINE records from org.openqa.selenium now reach System.err
+   * }</pre>
+   */
   public static void configureLogger() {
-    if (!isDebugAll() || loggerConfigured) {
-      return;
+    synchronized (LOCK) {
+      Level requested = requestedLevel();
+      if (requested != null
+          && (enabledLevel == null || requested.intValue() < enabledLevel.intValue())) {
+        enabledLevel = requested;
+      }
+      if (enabledLevel != null) {
+        enable(enabledLevel);
+      }
+    }
+  }
+
+  /** Returns the level asked for by the debug switches, or {@code null} when none is enabled. */
+  private static @Nullable Level requestedLevel() {
+    // SE_DEBUG is checked first because it is the broader switch.
+    if (isDebugAll()) {
+      return SE_DEBUG_LEVEL;
+    }
+    if (isDebugging()) {
+      return DEBUG_PROPERTY_LEVEL;
+    }
+    return null;
+  }
+
+  private static void enable(Level minimum) {
+    Level level = effectiveLevel(SELENIUM_LOGGER);
+    if (level.intValue() > minimum.intValue()) {
+      SELENIUM_LOGGER.setLevel(minimum);
+      level = minimum;
     }
 
-    SELENIUM_LOGGER.setLevel(Level.FINE);
+    Handler handler = installedHandler;
+    if (handler == null || !isAttached(handler)) {
+      if (handler != null) {
+        handler.close();
+      }
+      handler = new ConsoleHandler();
+      // Leave INFO and above to the existing handlers so those records are not printed twice.
+      handler.setFilter(record -> record.getLevel().intValue() < Level.INFO.intValue());
+      SELENIUM_LOGGER.addHandler(handler);
+      installedHandler = handler;
+    }
+    handler.setLevel(level);
+  }
+
+  private static boolean isAttached(Handler handler) {
+    return Arrays.asList(SELENIUM_LOGGER.getHandlers()).contains(handler);
+  }
 
-    StreamHandler handler = new StreamHandler(System.err, new SimpleFormatter());
-    handler.setLevel(Level.FINE);
-    SELENIUM_LOGGER.addHandler(handler);
-    loggerConfigured = true;
+  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;
+  }
+
+  /** Detaches Selenium's handler and switches debug logging off again. Only for tests. */
+  static void resetForTesting() {
+    synchronized (LOCK) {
+      Handler handler = installedHandler;
+      if (handler != null) {
+        SELENIUM_LOGGER.removeHandler(handler);
+        handler.close();
+        installedHandler = null;
+      }
+      enabledLevel = null;
+    }
   }
 }

java/src/org/openqa/selenium/remote/RemoteWebDriver.java

@@ -119,8 +119,9 @@ public class RemoteWebDriver
         PrintsPage,
         TakesScreenshot {
 
+  // Configure before subclass constructor arguments can trigger driver discovery logs.
   static {
-    org.openqa.selenium.internal.Debug.configureLogger();
+    Debug.configureLogger();
   }
 
   private static final Logger LOG = Logger.getLogger(RemoteWebDriver.class.getName());
@@ -229,6 +230,20 @@ public RemoteWebDriver(
     this(executor, capabilities, DEFAULT_CLIENT_FACTORY, clientConfig);
   }
 
+  /**
+   * Creates a driver and starts a new session through the given executor.
+   *
+   * <p>Before the session starts, the current Selenium debug switches ({@code selenium.debug},
+   * {@code selenium.webdriver.verbose} and {@code SE_DEBUG}) are applied to Selenium's logger, so a
+   * switch set after this class was loaded still takes effect for this driver.
+   *
+   * @param executor the executor that sends commands to the remote end
+   * @param capabilities the capabilities requested for the new session
+   * @param clientFactory the factory used to create HTTP clients for this driver
+   * @param clientConfig the HTTP client configuration used by this driver
+   * @throws IllegalArgumentException if any argument is {@code null}
+   * @throws SessionNotCreatedException if the remote end cannot start a session
+   */
   // ignore WEBDRIVER_REMOTE_ENABLE_TRACING here, to allow extended external control
   public RemoteWebDriver(
       CommandExecutor executor,
@@ -239,6 +254,7 @@ public RemoteWebDriver(
     this.clientConfig = Require.nonNull("Client config", clientConfig);
     this.executor = Require.nonNull("Command executor", executor);
     this.capabilities = Require.nonNull("Capabilities", capabilities);
+    Debug.configureLogger();
 
     try {
       startSession(capabilities);

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,
 )