diff --git a/java/src/org/openqa/selenium/bidi/Connection.java b/java/src/org/openqa/selenium/bidi/Connection.java index 45376716bec5c..48d244f800676 100644 --- a/java/src/org/openqa/selenium/bidi/Connection.java +++ b/java/src/org/openqa/selenium/bidi/Connection.java @@ -18,7 +18,6 @@ package org.openqa.selenium.bidi; import static java.util.concurrent.TimeUnit.MILLISECONDS; -import static org.openqa.selenium.internal.Debug.getDebugLogLevel; import static org.openqa.selenium.json.Json.MAP_TYPE; import static org.openqa.selenium.remote.http.HttpMethod.GET; @@ -47,6 +46,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 +78,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); @@ -147,7 +152,7 @@ public String toString() { try (JsonOutput out = JSON.newOutput(json).writeClassName(false)) { out.write(serialized); } - LOG.log(getDebugLogLevel(), "-> {0}", json); + LOG.log(Level.FINE, "-> {0}", json); socket.sendText(json); if (!command.getSendsResponse()) { @@ -302,7 +307,7 @@ private void handle(CharSequence data) { // TODO: decode once, and once only String asString = String.valueOf(data); - LOG.log(getDebugLogLevel(), "<- {0}", asString); + LOG.log(Level.FINE, "<- {0}", asString); Map raw = JSON.toType(asString, MAP_TYPE); if (raw.get("id") instanceof Number @@ -346,7 +351,7 @@ private void handleResponse(String rawDataString, Map rawDataMap private void handleEventResponse(Map rawDataMap) { LOG.log( - getDebugLogLevel(), + Level.FINE, () -> String.format( "Method %s called with %s callbacks available", @@ -365,7 +370,7 @@ private void handleEventResponse(Map rawDataMap) { .filter( event -> { LOG.log( - getDebugLogLevel(), + Level.FINE, "Matching {0} with {1}", new Object[] {rawDataMap.get("method"), event.getKey().getMethod()}); return rawDataMap.get("method").equals(event.getKey().getMethod()); @@ -387,7 +392,7 @@ private void handleEventResponse(Map rawDataMap) { @SuppressWarnings("unchecked") Consumer obj = (Consumer) action; LOG.log( - getDebugLogLevel(), + Level.FINE, "Calling callback for {0} using {1} being passed {2}", new Object[] {event.getKey(), obj, finalValue}); obj.accept(finalValue); diff --git a/java/src/org/openqa/selenium/devtools/Connection.java b/java/src/org/openqa/selenium/devtools/Connection.java index 9a91094d85b8f..98b9621d55a0c 100644 --- a/java/src/org/openqa/selenium/devtools/Connection.java +++ b/java/src/org/openqa/selenium/devtools/Connection.java @@ -18,7 +18,6 @@ package org.openqa.selenium.devtools; import static java.util.concurrent.TimeUnit.MILLISECONDS; -import static org.openqa.selenium.internal.Debug.getDebugLogLevel; import static org.openqa.selenium.json.Json.MAP_TYPE; import static org.openqa.selenium.remote.http.HttpMethod.GET; @@ -51,6 +50,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 +92,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()); @@ -182,7 +188,7 @@ public CompletableFuture send(@Nullable SessionID sessionId, Command c try (JsonOutput out = JSON.newOutput(json).writeClassName(false)) { out.write(Map.copyOf(serialized)); } - LOG.log(getDebugLogLevel(), "-> {0}", json); + LOG.log(Level.FINE, "-> {0}", json); socket.sendText(json); if (!command.getSendsResponse()) { @@ -267,7 +273,7 @@ private void handle(long sequence, CharSequence data) { // TODO: decode once, and once only String asString = String.valueOf(data); - LOG.log(getDebugLogLevel(), "<- {0}", asString); + LOG.log(Level.FINE, "<- {0}", asString); Map raw = JSON.toType(asString, MAP_TYPE); if (raw.get("id") instanceof Number @@ -300,7 +306,7 @@ private void handle(long sequence, CharSequence data) { } } else if (raw.get("method") instanceof String && raw.get("params") instanceof Map) { LOG.log( - getDebugLogLevel(), + Level.FINE, "Method {0} called with {1} callbacks available", new Object[] {raw.get("method"), eventCallbacks.size()}); Lock lock = callbacksLock.readLock(); @@ -320,7 +326,7 @@ private void handle(long sequence, CharSequence data) { .peek( event -> LOG.log( - getDebugLogLevel(), + Level.FINE, "Matching {0} with {1}", new Object[] {raw.get("method"), event.getKey().getMethod()})) .filter(event -> raw.get("method").equals(event.getKey().getMethod())) @@ -358,7 +364,7 @@ private void handle(long sequence, CharSequence data) { @SuppressWarnings("unchecked") BiConsumer obj = (BiConsumer) action; LOG.log( - getDebugLogLevel(), + Level.FINE, "Calling callback for {0} using {1} being passed {2}", new Object[] {event.getKey(), obj, params}); obj.accept(sequence, params); diff --git a/java/src/org/openqa/selenium/grid/distributor/local/LocalDistributor.java b/java/src/org/openqa/selenium/grid/distributor/local/LocalDistributor.java index 65715330c0a65..d522d80e6240e 100644 --- a/java/src/org/openqa/selenium/grid/distributor/local/LocalDistributor.java +++ b/java/src/org/openqa/selenium/grid/distributor/local/LocalDistributor.java @@ -18,7 +18,6 @@ package org.openqa.selenium.grid.distributor.local; import static org.openqa.selenium.concurrent.ExecutorServices.shutdownGracefully; -import static org.openqa.selenium.internal.Debug.getDebugLogLevel; import static org.openqa.selenium.remote.RemoteTags.CAPABILITIES; import static org.openqa.selenium.remote.RemoteTags.CAPABILITIES_EVENT; import static org.openqa.selenium.remote.RemoteTags.SESSION_ID; @@ -464,7 +463,7 @@ private SlotId reserveSlot(RequestId requestId, Capabilities caps) { if (slotIds.isEmpty()) { LOG.log( - getDebugLogLevel(), + Level.FINE, String.format("No slots found for request %s and capabilities %s", requestId, caps)); return null; } @@ -574,7 +573,7 @@ public void run() { sessionCreatorExecutor.execute(() -> handleNewSessionRequest(req)); } catch (RejectedExecutionException e) { LOG.log( - getDebugLogLevel(), + Level.FINE, "Dropping session creation task while shutting down distributor", e); } @@ -632,9 +631,7 @@ private void handleNewSessionRequest(SessionRequest sessionRequest) { if (response.isLeft() && response.left() instanceof RetrySessionRequestException) { try (Span childSpan = span.createSpan("distributor.retry")) { - if (LOG.isLoggable(getDebugLogLevel())) { - LOG.log(getDebugLogLevel(), "Retrying {0}", sessionRequest.getDesiredCapabilities()); - } + LOG.log(Level.FINE, "Retrying {0}", sessionRequest.getDesiredCapabilities()); boolean retried = sessionQueue.retryAddToQueue(sessionRequest); attributeMap.put("request.retry_add", retried); diff --git a/java/src/org/openqa/selenium/grid/distributor/local/LocalGridModel.java b/java/src/org/openqa/selenium/grid/distributor/local/LocalGridModel.java index da497a794c5f5..3608e9547ea34 100644 --- a/java/src/org/openqa/selenium/grid/distributor/local/LocalGridModel.java +++ b/java/src/org/openqa/selenium/grid/distributor/local/LocalGridModel.java @@ -33,6 +33,7 @@ import java.util.concurrent.locks.Lock; import java.util.concurrent.locks.ReadWriteLock; import java.util.concurrent.locks.ReentrantReadWriteLock; +import java.util.logging.Level; import java.util.logging.Logger; import org.jspecify.annotations.Nullable; import org.openqa.selenium.events.EventBus; @@ -49,7 +50,6 @@ import org.openqa.selenium.grid.data.SlotId; import org.openqa.selenium.grid.distributor.GridModel; import org.openqa.selenium.grid.server.EventBusOptions; -import org.openqa.selenium.internal.Debug; import org.openqa.selenium.internal.Require; import org.openqa.selenium.remote.SessionId; @@ -101,7 +101,7 @@ public void add(NodeStatus node) { && next.getExternalUri().equals(node.getExternalUri())) { iterator.remove(); - LOG.log(Debug.getDebugLogLevel(), "Refreshing node with id {0}", node.getNodeId()); + LOG.log(Level.FINE, "Refreshing node with id {0}", node.getNodeId()); NodeStatus refreshed = rewrite(node, next.getAvailability()); nodes.add(refreshed); nodePurgeTimes.put(refreshed.getNodeId(), Instant.now()); @@ -140,7 +140,7 @@ public void add(NodeStatus node) { // Nodes are initially added in the "down" state until something changes their availability LOG.log( - Debug.getDebugLogLevel(), + Level.FINE, "Adding node with id {0} and URI {1}", new Object[] {node.getNodeId(), node.getExternalUri()}); NodeStatus refreshed = rewrite(node, DOWN); diff --git a/java/src/org/openqa/selenium/grid/distributor/local/LocalNodeRegistry.java b/java/src/org/openqa/selenium/grid/distributor/local/LocalNodeRegistry.java index bcd21fc1675d0..42a38c54c4826 100644 --- a/java/src/org/openqa/selenium/grid/distributor/local/LocalNodeRegistry.java +++ b/java/src/org/openqa/selenium/grid/distributor/local/LocalNodeRegistry.java @@ -22,7 +22,6 @@ import static org.openqa.selenium.grid.data.Availability.DOWN; import static org.openqa.selenium.grid.data.Availability.DRAINING; import static org.openqa.selenium.grid.data.Availability.UP; -import static org.openqa.selenium.internal.Debug.getDebugLogLevel; import java.net.URI; import java.time.Duration; @@ -228,7 +227,7 @@ public void add(Node node) { } } catch (Exception e) { LOG.log( - getDebugLogLevel(), String.format("Exception while adding Node %s", node.getUri()), e); + Level.WARNING, String.format("Exception while adding Node %s", node.getUri()), e); return; } @@ -298,7 +297,7 @@ public void updateNodeAvailability(URI nodeUri, NodeId id, Availability availabi writeLock.lock(); try { LOG.log( - getDebugLogLevel(), + Level.FINE, String.format("Health check result for %s was %s", nodeUri, availability)); model.setAvailability(id, availability); model.updateHealthCheckCount(id, availability); @@ -310,7 +309,7 @@ public void updateNodeAvailability(URI nodeUri, NodeId id, Availability availabi @Override public void runHealthChecks() { if (!healthChecksInProgress.compareAndSet(false, true)) { - LOG.log(getDebugLogLevel(), "Skipping health checks because previous cycle is still running"); + LOG.log(Level.FINE, "Skipping health checks because previous cycle is still running"); return; } @@ -335,7 +334,7 @@ public void runHealthChecks() { futures.add(nodeHealthCheckExecutor.submit(() -> runHealthCheck(nodeId, check))); } catch (RejectedExecutionException e) { LOG.log( - getDebugLogLevel(), + Level.FINE, String.format( "Unable to schedule health check for node %s, running in caller thread", nodeId), @@ -351,7 +350,7 @@ public void runHealthChecks() { Thread.currentThread().interrupt(); break; } catch (Exception e) { - LOG.log(getDebugLogLevel(), "Error waiting for health check execution", e); + LOG.log(Level.FINE, "Error waiting for health check execution", e); } } } finally { @@ -452,7 +451,7 @@ private void runHealthCheck(NodeId nodeId, Runnable check) { try { check.run(); } catch (Throwable t) { - LOG.log(getDebugLogLevel(), "Health check execution failed for node " + nodeId, t); + LOG.log(Level.FINE, "Health check execution failed for node " + nodeId, t); } } @@ -462,7 +461,7 @@ private Runnable asRunnableHealthCheck(Node node) { return () -> { boolean checkFailed = false; Exception failedCheckException = null; - LOG.log(getDebugLogLevel(), "Running healthcheck for Node " + node.getUri()); + LOG.log(Level.FINE, "Running healthcheck for Node " + node.getUri()); HealthCheck.Result result; try { @@ -500,7 +499,7 @@ public boolean reserve(SlotId slotId) { NodeId nodeId = slotId.getOwningNodeId(); Node node = nodes.get(nodeId); if (node == null) { - LOG.log(getDebugLogLevel(), String.format("Unable to find node with id %s", slotId)); + LOG.log(Level.FINE, String.format("Unable to find node with id %s", slotId)); return false; } diff --git a/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedDistributor.java b/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedDistributor.java index 72bc8c2e02139..69ea7622622ab 100644 --- a/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedDistributor.java +++ b/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedDistributor.java @@ -18,7 +18,6 @@ package org.openqa.selenium.grid.distributor.redis; import static org.openqa.selenium.concurrent.ExecutorServices.shutdownGracefully; -import static org.openqa.selenium.internal.Debug.getDebugLogLevel; import static org.openqa.selenium.remote.RemoteTags.CAPABILITIES; import static org.openqa.selenium.remote.RemoteTags.CAPABILITIES_EVENT; import static org.openqa.selenium.remote.RemoteTags.SESSION_ID; @@ -506,7 +505,7 @@ private SlotId reserveSlot(RequestId requestId, Capabilities caps) { if (slotIds.isEmpty()) { LOG.log( - getDebugLogLevel(), + Level.FINE, String.format("No slots found for request %s and capabilities %s", requestId, caps)); return null; } @@ -629,7 +628,7 @@ public void run() { sessionCreatorExecutor.execute(() -> handleNewSessionRequest(req)); } catch (RejectedExecutionException e) { LOG.log( - getDebugLogLevel(), + Level.FINE, "Dropping session creation task while shutting down distributor", e); } @@ -684,9 +683,7 @@ private void handleNewSessionRequest(SessionRequest sessionRequest) { if (response.isLeft() && response.left() instanceof RetrySessionRequestException) { try (Span childSpan = span.createSpan("distributor.retry")) { - if (LOG.isLoggable(getDebugLogLevel())) { - LOG.log(getDebugLogLevel(), "Retrying {0}", sessionRequest.getDesiredCapabilities()); - } + LOG.log(Level.FINE, "Retrying {0}", sessionRequest.getDesiredCapabilities()); boolean retried = sessionQueue.retryAddToQueue(sessionRequest); attributeMap.put("request.retry_add", retried); childSpan.addEvent("Retry adding to front of queue. No slot available.", attributeMap); diff --git a/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedGridModel.java b/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedGridModel.java index 8977d95a29c42..fc0b5eafc02cb 100644 --- a/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedGridModel.java +++ b/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedGridModel.java @@ -26,6 +26,7 @@ import java.util.Optional; import java.util.Set; import java.util.UUID; +import java.util.logging.Level; import java.util.logging.Logger; import org.jspecify.annotations.Nullable; import org.openqa.selenium.events.EventBus; @@ -40,7 +41,6 @@ import org.openqa.selenium.grid.data.Slot; import org.openqa.selenium.grid.data.SlotId; import org.openqa.selenium.grid.distributor.GridModel; -import org.openqa.selenium.internal.Debug; import org.openqa.selenium.internal.Require; import org.openqa.selenium.json.Json; import org.openqa.selenium.redis.GridRedisClient; @@ -197,7 +197,7 @@ public void add(NodeStatus node) { if (existing.getNodeId().equals(node.getNodeId()) && existing.getExternalUri().equals(node.getExternalUri())) { // Same node refreshing — keep existing availability. - LOG.log(Debug.getDebugLogLevel(), "Refreshing node with id {0}", node.getNodeId()); + LOG.log(Level.FINE, "Refreshing node with id {0}", node.getNodeId()); NodeStatus refreshed = rewrite(node, existing.getAvailability()); writeNodeBlob(refreshed); redis.set(lastTouchKey(node.getNodeId()), String.valueOf(Instant.now().toEpochMilli())); @@ -229,7 +229,7 @@ public void add(NodeStatus node) { // Add as DOWN until health check promotes it. LOG.log( - Debug.getDebugLogLevel(), + Level.FINE, "Adding node with id {0} and URI {1}", new Object[] {node.getNodeId(), node.getExternalUri()}); NodeStatus asDown = rewrite(node, DOWN); diff --git a/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedNodeRegistry.java b/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedNodeRegistry.java index d4d8119f510b7..2177e06a05c15 100644 --- a/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedNodeRegistry.java +++ b/java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedNodeRegistry.java @@ -22,7 +22,6 @@ import static org.openqa.selenium.grid.data.Availability.DOWN; import static org.openqa.selenium.grid.data.Availability.DRAINING; import static org.openqa.selenium.grid.data.Availability.UP; -import static org.openqa.selenium.internal.Debug.getDebugLogLevel; import java.net.URI; import java.time.Duration; @@ -292,7 +291,7 @@ public void add(Node node) { } } catch (Exception e) { LOG.log( - getDebugLogLevel(), String.format("Exception while adding Node %s", node.getUri()), e); + Level.WARNING, String.format("Exception while adding Node %s", node.getUri()), e); return; } @@ -361,7 +360,7 @@ public void updateNodeAvailability(URI nodeUri, NodeId id, Availability availabi writeLock.lock(); try { LOG.log( - getDebugLogLevel(), + Level.FINE, String.format("Health check result for %s was %s", nodeUri, availability)); model.setAvailability(id, availability); model.updateHealthCheckCount(id, availability); @@ -373,7 +372,7 @@ public void updateNodeAvailability(URI nodeUri, NodeId id, Availability availabi @Override public void runHealthChecks() { if (!healthChecksInProgress.compareAndSet(false, true)) { - LOG.log(getDebugLogLevel(), "Skipping health checks because previous cycle is still running"); + LOG.log(Level.FINE, "Skipping health checks because previous cycle is still running"); return; } @@ -400,7 +399,7 @@ public void runHealthChecks() { redis.setIfAbsent("grid:healthcheck:lock:" + nodeId, instanceId, lockTtlMillis); if (!won) { LOG.log( - getDebugLogLevel(), + Level.FINE, "Another replica is handling health check for node {0}, skipping", nodeId); return; @@ -409,7 +408,7 @@ public void runHealthChecks() { futures.add(nodeHealthCheckExecutor.submit(() -> runHealthCheck(nodeId, check))); } catch (RejectedExecutionException e) { LOG.log( - getDebugLogLevel(), + Level.FINE, String.format( "Unable to schedule health check for node %s, running in caller thread", nodeId), @@ -425,7 +424,7 @@ public void runHealthChecks() { Thread.currentThread().interrupt(); break; } catch (Exception e) { - LOG.log(getDebugLogLevel(), "Error waiting for health check execution", e); + LOG.log(Level.FINE, "Error waiting for health check execution", e); } } } finally { @@ -521,7 +520,7 @@ private void runHealthCheck(NodeId nodeId, Runnable check) { try { check.run(); } catch (Throwable t) { - LOG.log(getDebugLogLevel(), "Health check execution failed for node " + nodeId, t); + LOG.log(Level.FINE, "Health check execution failed for node " + nodeId, t); } } @@ -531,7 +530,7 @@ private Runnable asRunnableHealthCheck(Node node) { return () -> { boolean checkFailed = false; Exception failedCheckException = null; - LOG.log(getDebugLogLevel(), "Running healthcheck for Node " + node.getUri()); + LOG.log(Level.FINE, "Running healthcheck for Node " + node.getUri()); HealthCheck.Result result; try { @@ -560,7 +559,7 @@ public boolean reserve(SlotId slotId) { NodeId nodeId = slotId.getOwningNodeId(); Node node = nodes.get(nodeId); if (node == null) { - LOG.log(getDebugLogLevel(), String.format("Unable to find node with id %s", slotId)); + LOG.log(Level.FINE, String.format("Unable to find node with id %s", slotId)); return false; } try { 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/grid/node/ProxyNodeWebsockets.java b/java/src/org/openqa/selenium/grid/node/ProxyNodeWebsockets.java index d6b9b34696fcc..6a4222b294bd8 100644 --- a/java/src/org/openqa/selenium/grid/node/ProxyNodeWebsockets.java +++ b/java/src/org/openqa/selenium/grid/node/ProxyNodeWebsockets.java @@ -17,7 +17,6 @@ package org.openqa.selenium.grid.node; -import static org.openqa.selenium.internal.Debug.getDebugLogLevel; import static org.openqa.selenium.remote.http.HttpMethod.GET; import io.netty.buffer.Unpooled; @@ -181,7 +180,7 @@ private Optional> findCdpEndpoint( } if (cdpUri.isPresent()) { - LOG.log(getDebugLogLevel(), String.format("Endpoint found in %s", cdpEndpointCap)); + LOG.log(Level.FINE, String.format("Endpoint found in %s", cdpEndpointCap)); return cdpUri.map(cdp -> createWsEndPoint(cdp, downstream, sessionConsumer, sessionId)); } else { try { @@ -246,7 +245,7 @@ private Optional> findVncEndpoint( LOG.warning("Invalid URI for endpoint " + vncLocalAddress); return Optional.empty(); } - LOG.log(getDebugLogLevel(), String.format("Endpoint found in %s", "se:vncLocalAddress")); + LOG.log(Level.FINE, String.format("Endpoint found in %s", "se:vncLocalAddress")); return vncUri.map(vnc -> createWsEndPoint(vnc, downstream, sessionConsumer, sessionId)); } diff --git a/java/src/org/openqa/selenium/grid/node/local/LocalNode.java b/java/src/org/openqa/selenium/grid/node/local/LocalNode.java index 06b78eaa89405..d2198e9668987 100644 --- a/java/src/org/openqa/selenium/grid/node/local/LocalNode.java +++ b/java/src/org/openqa/selenium/grid/node/local/LocalNode.java @@ -114,7 +114,6 @@ import org.openqa.selenium.grid.node.config.NodeOptions; import org.openqa.selenium.grid.node.docker.DockerSession; import org.openqa.selenium.grid.security.Secret; -import org.openqa.selenium.internal.Debug; import org.openqa.selenium.internal.Either; import org.openqa.selenium.internal.Require; import org.openqa.selenium.io.FileHandler; @@ -407,7 +406,7 @@ private void stopTimedOutSession( } } } else { - LOG.log(Debug.getDebugLogLevel(), "Received stop session notification with null values"); + LOG.log(Level.FINE, "Received stop session notification with null values"); span.setStatus(Status.INVALID_ARGUMENT); span.addEvent("Received stop session notification with null values", attributeMap); } @@ -1412,7 +1411,7 @@ private boolean decrementSessionCount() { if (this.drainAfterSessions) { int remainingSessions = this.sessionCount.decrementAndGet(); LOG.log( - Debug.getDebugLogLevel(), + Level.FINE, "{0} remaining sessions before draining Node", remainingSessions); return remainingSessions >= 0; @@ -1428,7 +1427,7 @@ private void restoreSessionCount() { if (this.drainAfterSessions) { int remainingSessions = this.sessionCount.incrementAndGet(); LOG.log( - Debug.getDebugLogLevel(), + Level.FINE, "Session creation failed, restored count. {0} remaining sessions before draining Node", remainingSessions); } diff --git a/java/src/org/openqa/selenium/grid/node/relay/RelaySessionFactory.java b/java/src/org/openqa/selenium/grid/node/relay/RelaySessionFactory.java index 949d96f9ca311..f715c9302bb43 100644 --- a/java/src/org/openqa/selenium/grid/node/relay/RelaySessionFactory.java +++ b/java/src/org/openqa/selenium/grid/node/relay/RelaySessionFactory.java @@ -49,7 +49,6 @@ import org.openqa.selenium.grid.node.ActiveSession; import org.openqa.selenium.grid.node.DefaultActiveSession; import org.openqa.selenium.grid.node.SessionFactory; -import org.openqa.selenium.internal.Debug; import org.openqa.selenium.internal.Either; import org.openqa.selenium.internal.Require; import org.openqa.selenium.remote.CapabilityType; @@ -244,7 +243,7 @@ public boolean isServiceUp() { try (HttpClient client = clientFactory.createClient(clientConfig)) { HttpResponse response = client.execute(new HttpRequest(HttpMethod.GET, serviceStatusUrl.toString())); - LOG.log(Debug.getDebugLogLevel(), response::contentAsString); + LOG.log(Level.FINE, response::contentAsString); return response.getStatus() == 200; } catch (Exception e) { LOG.log( @@ -252,7 +251,7 @@ public boolean isServiceUp() { () -> String.format( "Error checking service status %s. %s", serviceStatusUrl, e.getMessage())); - LOG.log(Debug.getDebugLogLevel(), "Error checking service status " + serviceStatusUrl, e); + LOG.log(Level.FINE, "Error checking service status " + serviceStatusUrl, e); } return false; } 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/netty/server/RequestConverter.java b/java/src/org/openqa/selenium/netty/server/RequestConverter.java index 4b98fe4ffa1f6..6084536a91c7a 100644 --- a/java/src/org/openqa/selenium/netty/server/RequestConverter.java +++ b/java/src/org/openqa/selenium/netty/server/RequestConverter.java @@ -38,9 +38,9 @@ import io.netty.util.ReferenceCountUtil; import java.util.Set; import java.util.concurrent.atomic.AtomicLong; +import java.util.logging.Level; import java.util.logging.Logger; import org.jspecify.annotations.Nullable; -import org.openqa.selenium.internal.Debug; import org.openqa.selenium.remote.http.Contents; import org.openqa.selenium.remote.http.HttpMethod; import org.openqa.selenium.remote.http.HttpRequest; @@ -58,10 +58,10 @@ class RequestConverter extends SimpleChannelInboundHandler { @Override protected void channelRead0(ChannelHandlerContext ctx, HttpObject msg) throws Exception { - LOG.log(Debug.getDebugLogLevel(), "Incoming message: {0}", msg); + LOG.log(Level.FINE, "Incoming message: {0}", msg); if (msg instanceof io.netty.handler.codec.http.HttpRequest) { - LOG.log(Debug.getDebugLogLevel(), "Start of http request: {0}", msg); + LOG.log(Level.FINE, "Start of http request: {0}", msg); io.netty.handler.codec.http.HttpRequest nettyRequest = (io.netty.handler.codec.http.HttpRequest) msg; @@ -112,7 +112,7 @@ protected void channelRead0(ChannelHandlerContext ctx, HttpObject msg) throws Ex } if (msg instanceof LastHttpContent) { - LOG.log(Debug.getDebugLogLevel(), "End of http request: {0}", msg); + LOG.log(Level.FINE, "End of http request: {0}", msg); if (buffer != null) { request.setContent( @@ -128,7 +128,7 @@ protected void channelRead0(ChannelHandlerContext ctx, HttpObject msg) throws Ex @Override public void channelInactive(ChannelHandlerContext ctx) throws Exception { - LOG.log(Debug.getDebugLogLevel(), "Channel became inactive."); + LOG.log(Level.FINE, "Channel became inactive."); super.channelInactive(ctx); } @@ -172,8 +172,7 @@ private HttpRequest createRequest( } catch (Exception ignore) { ctx.writeAndFlush( new DefaultFullHttpResponse(HttpVersion.HTTP_1_1, HttpResponseStatus.BAD_REQUEST)); - LOG.log( - Debug.getDebugLogLevel(), "Not possible to decode parameters. {0}", nettyRequest.uri()); + LOG.log(Level.FINE, "Not possible to decode parameters. {0}", nettyRequest.uri()); return null; } } 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/src/org/openqa/selenium/remote/RemoteWebDriverBuilder.java b/java/src/org/openqa/selenium/remote/RemoteWebDriverBuilder.java index 036d441f1d733..ebf1e14ebe2d7 100644 --- a/java/src/org/openqa/selenium/remote/RemoteWebDriverBuilder.java +++ b/java/src/org/openqa/selenium/remote/RemoteWebDriverBuilder.java @@ -18,7 +18,6 @@ package org.openqa.selenium.remote; import static java.util.logging.Level.WARNING; -import static org.openqa.selenium.internal.Debug.getDebugLogLevel; import static org.openqa.selenium.remote.DriverCommand.QUIT; import static org.openqa.selenium.remote.http.HttpMethod.DELETE; @@ -37,6 +36,7 @@ import java.util.TreeMap; import java.util.function.Function; import java.util.function.Supplier; +import java.util.logging.Level; import java.util.logging.Logger; import java.util.stream.Collectors; import java.util.stream.StreamSupport; @@ -114,8 +114,7 @@ public RemoteWebDriverBuilder oneOf(Capabilities maybeThis, Capabilities... orOn Require.nonNull("Capabilities to use", maybeThis); if (!requestedCapabilities.isEmpty()) { - LOG.log( - getDebugLogLevel(), "Removing existing requested capabilities: " + requestedCapabilities); + LOG.log(Level.FINE, "Removing existing requested capabilities: " + requestedCapabilities); requestedCapabilities.clear(); } @@ -155,7 +154,7 @@ public RemoteWebDriverBuilder addMetadata(String key, Object value) { Object previous = metadata.put(key, value); if (previous != null) { LOG.log( - getDebugLogLevel(), + Level.FINE, String.format( "Overwriting metadata %s. Previous value %s, new value %s", key, previous, value)); } @@ -176,7 +175,7 @@ public RemoteWebDriverBuilder setCapability(String capabilityName, Object value) Object previous = additionalCapabilities.put(capabilityName, value); if (previous != null) { LOG.log( - getDebugLogLevel(), + Level.FINE, () -> String.format( "Overwriting capability %s. Previous value %s, new value %s", diff --git a/java/src/org/openqa/selenium/remote/http/RetryRequest.java b/java/src/org/openqa/selenium/remote/http/RetryRequest.java index 17a3f7e0ed25c..f9957eb1facf4 100644 --- a/java/src/org/openqa/selenium/remote/http/RetryRequest.java +++ b/java/src/org/openqa/selenium/remote/http/RetryRequest.java @@ -23,12 +23,10 @@ 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 { 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 +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(LOG_LEVEL, "Retry #" + (i + 1) + " on ConnectException", ex); + LOG.log(Level.WARNING, "Retry #" + (i + 1) + " on ConnectException", ex); continue; } @@ -65,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(LOG_LEVEL, "Retry #" + (i + 1) + " on ServerError: " + response.getStatus()); + LOG.log(Level.WARNING, "Retry #" + (i + 1) + " on ServerError: " + response.getStatus()); continue; } diff --git a/java/src/org/openqa/selenium/remote/service/DriverFinder.java b/java/src/org/openqa/selenium/remote/service/DriverFinder.java index 60ba25060b98a..6a8131c032e6c 100644 --- a/java/src/org/openqa/selenium/remote/service/DriverFinder.java +++ b/java/src/org/openqa/selenium/remote/service/DriverFinder.java @@ -27,6 +27,7 @@ import org.openqa.selenium.Capabilities; import org.openqa.selenium.Proxy; import org.openqa.selenium.WebDriverException; +import org.openqa.selenium.internal.Debug; import org.openqa.selenium.internal.Require; import org.openqa.selenium.manager.SeleniumManager; import org.openqa.selenium.manager.SeleniumManagerOutput.Result; @@ -91,6 +92,12 @@ public boolean hasBrowserPath() { } private Result getBinaryPaths() { + // Discovery logging (this class and SeleniumManager) can run before any RemoteWebDriver + // constructor -- e.g. as an argument to a browser driver's super(...) call, or with no + // RemoteWebDriver involved at all (InternetExplorerDriver, DriverService's lazy lookup, the + // DriverInfo classes). Reflect the current debug switches before that logging happens; + // configureLogger() is idempotent, so repeated calls are cheap. + Debug.configureLogger(); if (result == null) { try { String driverName = service.getDriverName(); 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/distributor/local/LocalNodeRegistryTest.java b/java/test/org/openqa/selenium/grid/distributor/local/LocalNodeRegistryTest.java index 35e479d9160a1..d59ed0bd809b8 100644 --- a/java/test/org/openqa/selenium/grid/distributor/local/LocalNodeRegistryTest.java +++ b/java/test/org/openqa/selenium/grid/distributor/local/LocalNodeRegistryTest.java @@ -23,6 +23,8 @@ import java.lang.reflect.Field; import java.net.URI; import java.time.Duration; +import java.util.ArrayList; +import java.util.List; import java.util.Map; import java.util.Set; import java.util.UUID; @@ -33,6 +35,10 @@ import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; +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.Test; @@ -185,6 +191,58 @@ void shouldRunHealthChecksForMultipleNodesConcurrently() throws Exception { } } + @Test + void addLogsAtWarningWhenNodeStatusThrows() { + // An exception here aborts registration entirely (see the catch block in add()) -- that's an + // actionable failure, not routine diagnostics, so it must be visible at WARNING by default. + NodeId nodeId = new NodeId(UUID.randomUUID()); + RuntimeException statusFailure = new RuntimeException("node heartbeat started before ready"); + Node node = + new TestNode( + tracer, + nodeId, + URI.create("http://example:4444"), + registrationSecret, + () -> { + throw new AssertionError("health check must not run for a node that failed add()"); + }) { + @Override + public NodeStatus getStatus() { + throw statusFailure; + } + }; + + Logger log = Logger.getLogger(LocalNodeRegistry.class.getName()); + List records = new ArrayList<>(); + Handler capture = + new Handler() { + @Override + public void publish(LogRecord record) { + records.add(record); + } + + @Override + public void flush() {} + + @Override + public void close() {} + }; + capture.setLevel(Level.ALL); + Level oldLevel = log.getLevel(); + log.setLevel(Level.ALL); + log.addHandler(capture); + try { + registry.add(node); + + assertThat(records).hasSize(1); + assertThat(records.get(0).getLevel()).isEqualTo(Level.WARNING); + assertThat(records.get(0).getThrown()).isSameAs(statusFailure); + } finally { + log.removeHandler(capture); + log.setLevel(oldLevel); + } + } + @Test void closeShouldShutdownNodeHealthCheckWorkerPool() throws Exception { ExecutorService nodeHealthCheckExecutor = getNodeHealthCheckExecutor(registry); diff --git a/java/test/org/openqa/selenium/grid/distributor/redis/RedisBackedNodeRegistryTest.java b/java/test/org/openqa/selenium/grid/distributor/redis/RedisBackedNodeRegistryTest.java index 22e80836bd54c..f579e30661f34 100644 --- a/java/test/org/openqa/selenium/grid/distributor/redis/RedisBackedNodeRegistryTest.java +++ b/java/test/org/openqa/selenium/grid/distributor/redis/RedisBackedNodeRegistryTest.java @@ -26,6 +26,8 @@ import java.net.URISyntaxException; import java.time.Duration; import java.time.Instant; +import java.util.ArrayList; +import java.util.List; import java.util.Map; import java.util.Set; import java.util.UUID; @@ -33,6 +35,10 @@ import java.util.concurrent.Executors; import java.util.concurrent.Future; import java.util.concurrent.atomic.AtomicInteger; +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.Test; @@ -238,6 +244,60 @@ void isReadyReturnsTrueWhenBusIsReady() { assertThat(registry.isReady()).isTrue(); } + @Test + void addLogsAtWarningWhenNodeStatusThrows() { + // An exception here aborts registration entirely (see the catch block in add()) -- that's an + // actionable failure, not routine diagnostics, so it must be visible at WARNING by default. + // Mirrors LocalNodeRegistryTest.addLogsAtWarningWhenNodeStatusThrows: RedisBackedNodeRegistry's + // add() has the identical catch-and-warn path but had no test of its own. + NodeId nodeId = new NodeId(UUID.randomUUID()); + RuntimeException statusFailure = new RuntimeException("node heartbeat started before ready"); + TestNode node = + new TestNode( + tracer, + nodeId, + uri(PortProber.findFreePort()), + secret, + () -> { + throw new AssertionError("health check must not run for a node that failed add()"); + }) { + @Override + public NodeStatus getStatus() { + throw statusFailure; + } + }; + + Logger log = Logger.getLogger(RedisBackedNodeRegistry.class.getName()); + List records = new ArrayList<>(); + Handler capture = + new Handler() { + @Override + public void publish(LogRecord record) { + records.add(record); + } + + @Override + public void flush() {} + + @Override + public void close() {} + }; + capture.setLevel(Level.ALL); + Level oldLevel = log.getLevel(); + log.setLevel(Level.ALL); + log.addHandler(capture); + try { + registry.add(node); + + assertThat(records).hasSize(1); + assertThat(records.get(0).getLevel()).isEqualTo(Level.WARNING); + assertThat(records.get(0).getThrown()).isSameAs(statusFailure); + } finally { + log.removeHandler(capture); + log.setLevel(oldLevel); + } + } + private static class TestNode extends Node { private final NodeStatus status; 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 = diff --git a/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java b/java/test/org/openqa/selenium/remote/http/RetryRequestTest.java index aec6358cdf088..a998446be01f9 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; @@ -339,6 +343,66 @@ void shouldRethrowOnConnectFailure() { assertThat(count).hasValue(4); } + @Test + void retryLogsAtWarningRegardlessOfDebugToggle() { + // RetryRequest no longer varies its own report level with the debug switch (that was the + // deprecated getDebugLogLevel() dance, migrated away as part of #17835) -- it always logs at + // WARNING, since a connection-failure/server-error retry is an operationally significant, + // actionable event (bounded to a handful of attempts by RETRIES_ON_CONNECTION_FAILURE / + // RETRIES_ON_SERVER_ERROR), not routine diagnostics that should require debug mode to see. Lock + // in that invariant on both sides of the switch instead of the pre-migration toggle behavior. + HttpHandler handler = + new RetryRequest().andFinally(request -> new HttpResponse().setStatus(HTTP_UNAVAILABLE)); + + Logger log = Logger.getLogger(RetryRequest.class.getName()); + List records = new ArrayList<>(); + Handler capture = + new Handler() { + @Override + public void publish(LogRecord record) { + records.add(record); + } + + @Override + public void flush() {} + + @Override + public void close() {} + }; + capture.setLevel(Level.ALL); + Level oldLevel = log.getLevel(); + String oldDebugProperty = System.getProperty("selenium.debug"); + String oldVerboseProperty = System.getProperty("selenium.webdriver.verbose"); + log.setLevel(Level.ALL); + log.addHandler(capture); + try { + System.setProperty("selenium.debug", "true"); + handler.execute(new HttpRequest(GET, "/")); + assertThat(records).isNotEmpty(); + assertThat(records).allSatisfy(r -> assertThat(r.getLevel()).isEqualTo(Level.WARNING)); + + records.clear(); + System.clearProperty("selenium.debug"); + System.clearProperty("selenium.webdriver.verbose"); + handler.execute(new HttpRequest(GET, "/")); + assertThat(records).isNotEmpty(); + assertThat(records).allSatisfy(r -> assertThat(r.getLevel()).isEqualTo(Level.WARNING)); + } finally { + 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"); + } + log.removeHandler(capture); + log.setLevel(oldLevel); + } + } + @Test void shouldDeliverUnmodifiedServerErrors() { AtomicInteger count = new AtomicInteger(0); diff --git a/java/test/org/openqa/selenium/remote/service/DriverFinderTest.java b/java/test/org/openqa/selenium/remote/service/DriverFinderTest.java index 6a89fbb5176c9..6dcfebc3449ea 100644 --- a/java/test/org/openqa/selenium/remote/service/DriverFinderTest.java +++ b/java/test/org/openqa/selenium/remote/service/DriverFinderTest.java @@ -33,6 +33,9 @@ import java.util.ArrayList; import java.util.List; import java.util.Map; +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; @@ -42,6 +45,7 @@ import org.openqa.selenium.Proxy; import org.openqa.selenium.Proxy.ProxyType; import org.openqa.selenium.chrome.ElectronOptions; +import org.openqa.selenium.internal.Debug; import org.openqa.selenium.manager.SeleniumManager; import org.openqa.selenium.manager.SeleniumManagerOutput.Result; import uk.org.webcompere.systemstubs.environment.EnvironmentVariables; @@ -65,6 +69,85 @@ void createMocks() { when(service.getDriverName()).thenReturn("driverName"); } + /** + * 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 String oldDebugProperty; + private Level oldLoggerLevel; + + @BeforeEach + void storeDebugState() { + oldDebugProperty = System.getProperty("selenium.debug"); + oldLoggerLevel = seleniumLogger().getLevel(); + System.clearProperty("selenium.debug"); + } + + @AfterEach + void restoreDebugState() { + if (oldDebugProperty != null) { + System.setProperty("selenium.debug", oldDebugProperty); + } else { + System.clearProperty("selenium.debug"); + } + Debug.configureLogger(); + seleniumLogger().setLevel(oldLoggerLevel); + } + + @Test + void secondDiscoveryPicksUpADebugPropertyChangedAfterTheFirst() throws IOException { + // A small in-memory DriverService (no mocking framework): this test makes no verify()/ + // interaction assertions on the service, only on the shared org.openqa.selenium logger's + // level, so it doesn't need Mockito's machinery -- matching the pattern already applied + // elsewhere on this PR (e.g. RemoteWebDriverInitializationTest, commit 31ea2ca102). + DriverService inMemoryService = new InMemoryDriverService(driverFile); + Capabilities capabilities = new ImmutableCapabilities("browserName", "chrome"); + + // First discovery while debugging is off -- nothing for configureLogger to react to. + new DriverFinder(inMemoryService, capabilities).getDriverPath(); + + System.setProperty("selenium.debug", "true"); + + // Second discovery after the property changed. No RemoteWebDriver constructor is involved + // (this is also the only coverage InternetExplorerDriver's discovery path gets), so only + // getBinaryPaths' own Debug.configureLogger() call can pick this up. + new DriverFinder(inMemoryService, capabilities).getDriverPath(); + + assertThat(seleniumLogger().getLevel()).isEqualTo(Level.FINE); + } + + /** + * Minimal real {@link DriverService}: {@link #getExecutable()} answers straight from the + * constructor-set path (inherited, not overridden), {@link #getDriverName()} returns a fixed + * name, and the two abstract accessors throw since {@code getBinaryPaths()} never reaches them + * once {@link #getExecutable()} already resolves a path. + */ + private static class InMemoryDriverService extends DriverService { + InMemoryDriverService(Path driverFile) throws IOException { + super(driverFile.toFile(), 0, DEFAULT_TIMEOUT, null, null); + } + + @Override + protected String getDriverName() { + return "driverName"; + } + + @Override + public String getDriverProperty() { + throw new UnsupportedOperationException("getDriverProperty"); + } + + @Override + protected String getDriverEnvironmentVariable() { + throw new UnsupportedOperationException("getDriverEnvironmentVariable"); + } + } + @Test void serviceValueIgnoresSeleniumManager() { when(service.getExecutable()).thenReturn(driverFile.toString());