Add more logging to the JDK HTTP client

SeleniumHQ · Oct 11, 2022 · 97109ac · 97109ac
1 parent 53571b2
commit 97109ac
Showing 1 changed file with 22 additions and 0 deletions.
diff --git a/java/src/org/openqa/selenium/remote/http/jdk/JdkHttpClient.java b/java/src/org/openqa/selenium/remote/http/jdk/JdkHttpClient.java
@@ -57,10 +57,13 @@
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.TimeUnit;
 import java.util.function.Supplier;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 
 import static java.net.http.HttpClient.Redirect.ALWAYS;
 
 public class JdkHttpClient implements HttpClient {
+  public static final Logger LOG = Logger.getLogger(JdkHttpClient.class.getName());
   private final JdkHttpMessages messages;
   private final java.net.http.HttpClient client;
   private final Duration readTimeout;
@@ -127,9 +130,11 @@ public WebSocket openSocket(HttpRequest request, WebSocket.Listener listener) {
 
           @Override
           public CompletionStage<?> onText(java.net.http.WebSocket webSocket, CharSequence data, boolean last) {
+            LOG.fine("Text message received. Appending data");
             builder.append(data);
 
             if (last) {
+              LOG.fine("Final part of text message received. Calling listener with " + builder);
               listener.onText(builder.toString());
               builder.setLength(0);
             }
@@ -140,6 +145,7 @@ public CompletionStage<?> onText(java.net.http.WebSocket webSocket, CharSequence
 
           @Override
           public CompletionStage<?> onBinary(java.net.http.WebSocket webSocket, ByteBuffer data, boolean last) {
+            LOG.fine("Binary data received.");
             byte[] ary = new byte[data.remaining()];
             data.get(ary, 0, ary.length);
 
@@ -150,12 +156,14 @@ public CompletionStage<?> onBinary(java.net.http.WebSocket webSocket, ByteBuffer
 
           @Override
           public CompletionStage<?> onClose(java.net.http.WebSocket webSocket, int statusCode, String reason) {
+            LOG.fine("Closing websocket");
             listener.onClose(statusCode, reason);
             return null;
           }
 
           @Override
           public void onError(java.net.http.WebSocket webSocket, Throwable error) {
+            LOG.log(Level.FINE, error, () -> "An error has occurred: " + error.getMessage());
             listener.onError(error);
             webSocket.request(1);
           }
@@ -170,18 +178,22 @@ public WebSocket send(Message message) {
 
         if (message instanceof BinaryMessage) {
           BinaryMessage binaryMessage = (BinaryMessage) message;
+          LOG.fine("Sending binary message");
           makeCall = () -> underlyingSocket.sendBinary(ByteBuffer.wrap(binaryMessage.data()), true);
         } else if (message instanceof TextMessage) {
           TextMessage textMessage = (TextMessage) message;
+          LOG.fine("Sending text message: " + textMessage.text());
           makeCall = () -> underlyingSocket.sendText(textMessage.text(), true);
         } else if (message instanceof CloseMessage) {
+          LOG.fine("Sending close message");
           CloseMessage closeMessage = (CloseMessage) message;
           makeCall = () -> underlyingSocket.sendClose(closeMessage.code(), closeMessage.reason());
         } else {
           throw new IllegalArgumentException("Unsupported message type: " + message);
         }
 
         synchronized (underlyingSocket) {
+          long start = System.currentTimeMillis();
           CompletableFuture<java.net.http.WebSocket> future = makeCall.get();
           try {
             future.get(readTimeout.toMillis(), TimeUnit.MILLISECONDS);
@@ -198,13 +210,16 @@ public WebSocket send(Message message) {
             throw new WebDriverException(e.getMessage());
           } catch (java.util.concurrent.TimeoutException e) {
             throw new TimeoutException(e);
+          } finally {
+            LOG.fine(String.format("Websocket response to %s read in %sms", message, (System.currentTimeMillis() - start)));
           }
         }
         return this;
       }
 
       @Override
       public void close() {
+        LOG.fine("Closing websocket");
         underlyingSocket.sendClose(1000, "WebDriver closing socket");
       }
     };
@@ -231,6 +246,10 @@ private URI getWebSocketUri(HttpRequest request) {
   @Override
   public HttpResponse execute(HttpRequest req) throws UncheckedIOException {
     Objects.requireNonNull(req, "Request");
+
+    LOG.fine("Executing request: " + req);
+    long start = System.currentTimeMillis();
+
     BodyHandler<byte[]> byteHandler = BodyHandlers.ofByteArray();
     try {
       return messages.createResponse(client.send(messages.createRequest(req), byteHandler));
@@ -241,7 +260,10 @@ public HttpResponse execute(HttpRequest req) throws UncheckedIOException {
     } catch (InterruptedException e) {
       Thread.currentThread().interrupt();
       throw new RuntimeException(e);
+    } finally {
+      LOG.fine(String.format("Ending request %s in %sms", req, (System.currentTimeMillis() - start)));
     }
+
   }
 
   @AutoService(HttpClient.Factory.class)