search

SeleniumHQ / selenium

A browser automation framework and ecosystem.
https://selenium.dev
Apache License 2.0
30.23k stars 8.12k forks source link

[🐛 Bug]: `org.openqa.selenium.WebDriverException: java.io.IOException: Output closed` seen on calling devTools.createSession() #13397

Closed jonn-set closed 6 months ago

jonn-set commented 8 months ago

What happened?

I am upgrading from selenium 4.13 to 4.16.1 to stay in line with the browser version on my machine (I have no control over the version as its controlled by our organisation).

I am using BiDI/CDP Network Interception and it works alright in 4.13 but does not work in 4.16.1 and ends up giving the above error when devTools.createSession() or .createSessionIfThereIsNotOne() is called.

I am using Cucumber-Java8 as my Test Runner and OpenJDK11.

How can we reproduce the issue?

protected DevTools interceptResponseEndingWith(String urlPrefix) {
    log.info("Starting HTTP Response interception...");
    DevTools devTools = ((HasDevTools) driver).getDevTools();
    devTools.createSessionIfThereIsNotOne();
    devTools.send(Network.enable(Optional.empty(), Optional.empty(), Optional.empty()));
    final RequestId[] requestId = new RequestId[1];
    devTools.addListener(
        Network.responseReceived(),
        responseConsumer -> {
          Response response = responseConsumer.getResponse();
          log.info("Intercepted Response--> {}", response.getUrl());
          requestId[0] = responseConsumer.getRequestId();
          if (response.getUrl().endsWith(urlPrefix)
              && !response.getUrl().contains("www.google-analytics.com")) {
            log.info("Filtered Response--> {}", response.getUrl());
            log.info("Filtered ResponseId --> {}", requestId[0]);
            log.info("Response Status Code --> {}", response.getStatus());
            scenarioContext.responseStatusCode = response.getStatus();
            scenarioContext.responseBody =
                devTools.send(Network.getResponseBody(requestId[0])).getBody();
            log.info("Response Body--> {}", scenarioContext.responseBody);
          }
        });
    log.info("Started HTTP Response interception!!");
    return devTools;
  }

### Relevant log output

```shell
org.openqa.selenium.WebDriverException: java.io.IOException: Output closed
Build info: version: '4.16.1', revision: '9b4c83354e'
System info: os.name: 'Windows 10', os.arch: 'amd64', os.version: '10.0', java.version: '11.0.0.1'
Driver info: driver.version: unknown
    at org.openqa.selenium.remote.http.jdk.JdkHttpClient$5.send(JdkHttpClient.java:304)
    at org.openqa.selenium.remote.http.WebSocket.sendText(WebSocket.java:32)
    at org.openqa.selenium.devtools.Connection.send(Connection.java:172)
    at org.openqa.selenium.devtools.Connection.sendAndWait(Connection.java:183)
    at org.openqa.selenium.devtools.DevTools.findTarget(DevTools.java:171)
    at org.openqa.selenium.devtools.DevTools.createSession(DevTools.java:131)
    at org.openqa.selenium.devtools.DevTools.createSession(DevTools.java:117)
    at com.jcs.race.steps.BaseSteps.interceptResponseEndingWith(BaseSteps.java:104)
...
Caused by: java.io.IOException: Output closed
    at java.net.http/jdk.internal.net.http.websocket.MessageEncoder.encodeText(MessageEncoder.java:136)
    at java.net.http/jdk.internal.net.http.websocket.TransportImpl$SendTask$1.onText(TransportImpl.java:366)
    at java.net.http/jdk.internal.net.http.websocket.TransportImpl$SendTask$1.onText(TransportImpl.java:357)
    at java.net.http/jdk.internal.net.http.websocket.MessageQueue.peek(MessageQueue.java:223)
    at java.net.http/jdk.internal.net.http.websocket.TransportImpl$SendTask.run(TransportImpl.java:545)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
    at java.net.http/jdk.internal.net.http.websocket.TransportImpl.sendText(TransportImpl.java:149)
    at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl.sendText(WebSocketImpl.java:184)
    at org.openqa.selenium.remote.http.jdk.JdkHttpClient$5.lambda$send$1(JdkHttpClient.java:271)
    at org.openqa.selenium.remote.http.jdk.JdkHttpClient$5.send(JdkHttpClient.java:294)
    at org.openqa.selenium.remote.http.WebSocket.sendText(WebSocket.java:32)
    at org.openqa.selenium.devtools.Connection.send(Connection.java:172)
    at org.openqa.selenium.devtools.Connection.sendAndWait(Connection.java:183)
    at org.openqa.selenium.devtools.DevTools.findTarget(DevTools.java:171)
    at org.openqa.selenium.devtools.DevTools.createSession(DevTools.java:131)
    at org.openqa.selenium.devtools.DevTools.createSession(DevTools.java:117)
    at com.jcs.race.steps.BaseSteps.interceptResponseEndingWith(BaseSteps.java:104)

Operating System

Windows 10

Selenium version

4.16.1

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

Edge

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

120.0.2210.91

Are you using Selenium Grid?

No response

github-actions[bot] commented 8 months ago

@jonn-set, thank you for creating this issue. We will troubleshoot it as soon as we can.

Info for maintainers

Triage this issue by using labels.

If information is missing, add a helpful comment and then I-issue-template label.

If the issue is a question, add the I-question label.

If the issue is valid but there is no time to troubleshoot it, consider adding the help wanted label.

If the issue requires changes or fixes from an external project (e.g., ChromeDriver, GeckoDriver, MSEdgeDriver, W3C), add the applicable G-* label, and it will provide the correct link and auto-close the issue.

After troubleshooting the issue, please add the R-awaiting answer label.

Thank you!

diemol commented 8 months ago

@jonn-set Is Cucumber-Java8 compatible with Selenium 4.14 and above? Since 4.14 Java 11 is required.

jonn-set commented 8 months ago

I mean I am using this:

        <dependency>
            <groupId>io.cucumber</groupId>
            <artifactId>cucumber-java8</artifactId>
            <version>7.14.0</version>
        </dependency>

I am only 1 version behind the latest, 7.15.0

I did mention I am using OpenJDK11 and the error stacktrace also shows the version: System info: os.name: 'Windows 10', os.arch: 'amd64', os.version: '10.0', java.version: '11.0.0.1'

diemol commented 8 months ago

Yes, but is that dependency compatible with Selenium versions that require Java 11?

Have you checked with them?

jonn-set commented 8 months ago

My other tests are working OK, its only where it calls devTools.createSession() or devTools.createSessionIfThereIsNotOne(), it generates this error.

diemol commented 8 months ago

Most likely that code is using Java 11 features. Which is why I suggest you check with the maintainers of the other dependency you are using.

jonn-set commented 8 months ago

@pujagani can you help please? I have seen you resolve issues related to BiDi many times in the past. Any help is appreciated.

jonn-set commented 8 months ago

Most likely that code is using Java 11 features. Which is why I suggest you check with the maintainers of the other dependency you are using.

Its unlikely its anything to do with Cucumber, I just mentioned it for completeness. The issue is with BiDi, everything else is working fine, browser opens, run every other test that does not use BiDi/CDP and passes. I have checked with lower versions of Selenium like 4.14, 4.15 as well and end up with the same error, whereas on 4.13, it works just fine.

diemol commented 8 months ago

What happens if you run the code without the cucumber Java 8 dependency? Just Selenium?

jonn-set commented 8 months ago

What happens if you run the code without the cucumber Java 8 dependency? Just Selenium?

I will need some time for that as tests in my production code uses Cucumber, I will need to decouple it from that and use Junit.

I still feel it has nothing to do with Cucumber as it seem something to do with the implementation of BiDi in versions past selenium 4.13. Moreover, Cucumber is just a test runner like Junit and does not share any library with selenium, under the hood Cucumber uses Junit to run tests in Java and needs this dependency:

        <dependency>
            <groupId>io.cucumber</groupId>
            <artifactId>cucumber-junit</artifactId>
        </dependency>
github-actions[bot] commented 8 months ago

We need more information about this issue in order to troubleshoot.

Please turn on logging and re-run your code. Information on how to adjust logs for your language can be found in our Troubleshooting documentation.

jonn-set commented 8 months ago

Looks like the issue I am seeing is caused by an earlier call to CDP to carry out Basic Auth, the code to create a DevTools Session is called after Auth. As you can see from the logs, Basic Auth is seen throwing error after the log line Opening-->, which is when driver.get() is called, here, it cant continue to create session or enable Network as the Output is now closed.

I hope there's enough information to replicate the issue.

None of the other configs like Browser, OS, JDK, etc has changed. And this code is pure Junit, there's no Cucumber calls in it.

The browser was started with the following flags, in case that's needed:

--disable-save-password-bubble
--disable-extensions
--disable-client-side-phishing-detection
--no-default-browser-check
--no-first-run
--no-sandbox
--enable-logging=stderr
--log-level=0

Code causing the issue:

    String username = env.getProperty("user");
    String password = env.getProperty("password");

    Predicate<URI> uriPredicate = uri -> uri.getHost().contains("<hidden>");
    log.info("Logging in as '{}'!", username);
    ((HasAuthentication) driver)
        .register(
            uriPredicate,
            UsernameAndPassword.of(
                Objects.requireNonNull(username), Objects.requireNonNull(password)));
    String url = env.getProperty("url");
    log.info("Opening--> {}", url);
    driver.get(url);

Logs:

Jan 05, 2024 2:41:33 PM org.openqa.selenium.remote.RemoteWebDriver log
FINE: Executing: getCurrentWindowHandle [d1223449f4e95d5332ed3bcb58c38b74, getCurrentWindowHandle {}]
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Exchange establishExchange
FINE: [pool-2-thread-2] [3s 506ms] Exchange establishing exchange for http://localhost:19540/session/d1223449f4e95d5332ed3bcb58c38b74/window GET,
     proxy=null
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Exchange checkFor407
FINE: [pool-2-thread-2] [3s 509ms] Exchange checkFor407: all clear
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange sendHeadersAsync
FINE: [pool-2-thread-2] [3s 509ms] Http1Exchange Sending headers only
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver subscribe
FINE: [pool-2-thread-2] [3s 515ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@7db0ef3a queue.isEmpty: true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver handlePendingDelegate
FINE: [pool-2-thread-2] [3s 524ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@7db0ef3a, demand=1, canRequestMore=true, queue.isEmpty=true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-2] [3s 525ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver checkRequestMore
FINE: [pool-2-thread-2] [3s 531ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-2] [3s 533ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver checkRequestMore
FINE: [pool-2-thread-2] [3s 534ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange sendHeadersAsync
FINE: [pool-2-thread-2] [3s 535ms] Http1Exchange response created in advance
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange connectFlows
FINE: [pool-2-thread-2] [3s 535ms] Http1Exchange SocketTube(1) connecting flows
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber onSubscribe
FINE: [HttpClient-1-SelectorManager] [3s 537ms] Http1AsyncReceiver(SocketTube(1)) Received onSubscribed from upstream
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher subscribe
FINE: [pool-2-thread-2] [3s 537ms] Http1Publisher(SocketTube(1)) got subscriber: SocketTube(1)
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-3] [3s 539ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange lambda$sendHeadersAsync$4
FINE: [pool-2-thread-2] [3s 540ms] Http1Exchange requestAction.headers
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver checkRequestMore
FINE: [pool-2-thread-3] [3s 540ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$Http1WriteSubscription request
FINE: [pool-2-thread-1] [3s 540ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-1] [3s 543ms] Http1Publisher(SocketTube(1)) WriteTask
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber requestMore
FINE: [pool-2-thread-3] [3s 542ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: requesting one more from upstream
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange lambda$sendHeadersAsync$4
FINE: [pool-2-thread-2] [3s 541ms] Http1Exchange setting outgoing with headers
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-1] [3s 544ms] Http1Publisher(SocketTube(1)) hasOutgoing = false
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange appendToOutgoing
FINE: [pool-2-thread-2] [3s 545ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=332 cap=332]], throwable=null]
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-2] [3s 546ms] Http1Publisher(SocketTube(1)) WriteTask
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-2] [3s 546ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange getOutgoing
FINE: [pool-2-thread-2] [3s 547ms] Http1Exchange initiating completion of headersSentCF
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-2] [3s 548ms] Http1Publisher(SocketTube(1)) onNext with 332 bytes
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$Http1WriteSubscription request
FINE: [pool-2-thread-2] [3s 548ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-2] [3s 549ms] Http1Publisher(SocketTube(1)) WriteTask
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver asyncReceive
FINE: [HttpClient-1-SelectorManager] [3s 549ms] Http1AsyncReceiver(SocketTube(1)) Putting 152 bytes into the queue
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-2] [3s 550ms] Http1Publisher(SocketTube(1)) hasOutgoing = false
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-1] [3s 551ms] Http1AsyncReceiver(SocketTube(1)) Got 152 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@7db0ef3a
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Exchange checkFor407
FINE: [pool-2-thread-2] [3s 551ms] Exchange checkFor407: all clear
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Exchange sendRequestBody
FINE: [pool-2-thread-2] [3s 552ms] Exchange sendRequestBody
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-1] [3s 552ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange sendBodyAsync
FINE: [pool-2-thread-2] [3s 553ms] Http1Exchange sendBodyAsync
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-1] [3s 554ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 152 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@7db0ef3a
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange sendBodyAsync
FINE: [pool-2-thread-2] [3s 554ms] Http1Exchange bodySubscriber is null
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange appendToOutgoing
FINE: [pool-2-thread-2] [3s 555ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-2] [3s 556ms] Http1Publisher(SocketTube(1)) WriteTask
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-2] [3s 557ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange getOutgoing
FINE: [pool-2-thread-2] [3s 557ms] Http1Exchange initiating completion of bodySentCF
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-2] [3s 558ms] Http1Publisher(SocketTube(1)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@23b2904e
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.common.Utils lambda$wrapForDebug$7
FINE: [pool-2-thread-2] [3s 559ms] Http1Exchange sendBodyAsync completed successfully
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange getResponseAsync
FINE: [pool-2-thread-2] [3s 560ms] Http1Exchange reading headers
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response readHeadersAsync
FINE: [pool-2-thread-2] [3s 570ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) Reading Headers: (remaining: 152) READING_HEADERS
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response$HeadersReader handle
FINE: [pool-2-thread-1] [3s 570ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) Sending 152/152 bytes to header parser
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response readHeadersAsync
FINE: [pool-2-thread-2] [3s 571ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) First time around
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response readHeadersAsync
FINE: [pool-2-thread-2] [3s 572ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) headersReader is not yet completed
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response$HeadersReader handle
FINE: [pool-2-thread-1] [3s 574ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) Parsing headers completed. bytes=108
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver unsubscribe
FINE: [pool-2-thread-1] [3s 576ms] Http1AsyncReceiver(SocketTube(1)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@7db0ef3a
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response lambda$readHeadersAsync$0
FINE: [pool-2-thread-1] [3s 576ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) Reading Headers: creating Response object; state is now READING_BODY
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.common.Utils lambda$wrapForDebug$7
FINE: [pool-2-thread-1] [3s 577ms] Http1Exchange getResponseAsync completed successfully
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response$ClientRefCountTracker acquire
FINE: [pool-2-thread-1] [3s 585ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@1520a25(1)
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver subscribe
FINE: [pool-2-thread-1] [3s 586ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@2fe1002e/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@19b79a23 queue.isEmpty: false
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-1] [3s 599ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 44
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.ResponseContent$FixedLengthBodyParser onSubscribe
FINE: [pool-2-thread-1] [3s 605ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser length=44, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver handlePendingDelegate
FINE: [pool-2-thread-1] [3s 606ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@2fe1002e/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@19b79a23, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-1] [3s 607ms] Http1AsyncReceiver(SocketTube(1)) Got 44 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@2fe1002e/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@19b79a23
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-1] [3s 607ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 9223372036854775807
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-1] [3s 608ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 44 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@2fe1002e/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@19b79a23
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response$BodyReader handle
FINE: [pool-2-thread-1] [3s 609ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) Sending 44/152 bytes to body parser
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.ResponseContent$FixedLengthBodyParser accept
FINE: [pool-2-thread-1] [3s 609ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got 44 bytes (44 remaining / 44)
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.ResponseContent$FixedLengthBodyParser accept
FINE: [pool-2-thread-1] [3s 610ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver clear
FINE: [pool-2-thread-1] [3s 610ms] Http1AsyncReceiver(SocketTube(1)) cleared
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response onFinished
FINE: [pool-2-thread-1] [3s 611ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) SocketTube(1): return to HTTP/1.1 pool
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber dropSubscription
FINE: [HttpClient-1-SelectorManager] [3s 611ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: dropSubscription
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response lambda$readBody$2
FINE: [pool-2-thread-1] [3s 612ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) Finished reading body: READING_BODY
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response$ClientRefCountTracker tryRelease
FINE: [pool-2-thread-1] [3s 612ms] Http1Response(id=8, PlainHttpConnection(SocketTube(1))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@1520a25(1)
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-1] [3s 613ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 0
Jan 05, 2024 2:41:33 PM org.openqa.selenium.remote.RemoteWebDriver log
FINE: Executed: getCurrentWindowHandle (Response: SessionID: d1223449f4e95d5332ed3bcb58c38b74, State: success, Value: 75DF4B153A6B94FA24D2D22D693B9CBE)
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-1] [3s 613ms] Http1AsyncReceiver(SocketTube(1)) Got 0 bytes for delegate null
14:41:33.832 [main] INFO  com.jcs.race.Junit.loginAndSearch:53 - Opening--> <hidden>
Jan 05, 2024 2:41:33 PM org.openqa.selenium.remote.RemoteWebDriver log
FINE: Executing: get [d1223449f4e95d5332ed3bcb58c38b74, get {url=<hidden>}]
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Exchange establishExchange
FINE: [pool-2-thread-1] [3s 937ms] Exchange establishing exchange for http://localhost:19540/session/d1223449f4e95d5332ed3bcb58c38b74/url POST,
     proxy=null
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Exchange checkFor407
FINE: [pool-2-thread-1] [3s 938ms] Exchange checkFor407: all clear
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange sendHeadersAsync
FINE: [pool-2-thread-1] [3s 938ms] Http1Exchange Sending headers only
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver subscribe
FINE: [pool-2-thread-1] [3s 939ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@61e341c5 queue.isEmpty: true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver handlePendingDelegate
FINE: [pool-2-thread-1] [3s 939ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@61e341c5, demand=1, canRequestMore=true, queue.isEmpty=true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-1] [3s 940ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver checkRequestMore
FINE: [pool-2-thread-1] [3s 940ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-1] [3s 940ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver checkRequestMore
FINE: [pool-2-thread-1] [3s 941ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange sendHeadersAsync
FINE: [pool-2-thread-1] [3s 941ms] Http1Exchange response created in advance
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange connectFlows
FINE: [pool-2-thread-1] [3s 941ms] Http1Exchange SocketTube(1) connecting flows
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher subscribe
FINE: [pool-2-thread-1] [3s 942ms] Http1Publisher(SocketTube(1)) got subscriber: SocketTube(1)
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber onSubscribe
FINE: [HttpClient-1-SelectorManager] [3s 942ms] Http1AsyncReceiver(SocketTube(1)) Received onSubscribed from upstream
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange lambda$sendHeadersAsync$4
FINE: [pool-2-thread-1] [3s 943ms] Http1Exchange requestAction.headers
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$Http1WriteSubscription request
FINE: [pool-2-thread-3] [3s 943ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-2] [3s 943ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver checkRequestMore
FINE: [pool-2-thread-2] [3s 944ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber requestMore
FINE: [pool-2-thread-2] [3s 944ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: requesting one more from upstream
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange lambda$sendHeadersAsync$4
FINE: [pool-2-thread-1] [3s 944ms] Http1Exchange setting outgoing with headers
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange appendToOutgoing
FINE: [pool-2-thread-1] [3s 945ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=307 cap=307]], throwable=null]
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-3] [3s 943ms] Http1Publisher(SocketTube(1)) WriteTask
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-3] [3s 946ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange getOutgoing
FINE: [pool-2-thread-3] [3s 946ms] Http1Exchange initiating completion of headersSentCF
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Exchange checkFor407
FINE: [pool-2-thread-3] [3s 947ms] Exchange checkFor407: all clear
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Exchange sendRequestBody
FINE: [pool-2-thread-3] [3s 947ms] Exchange sendRequestBody
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange sendBodyAsync
FINE: [pool-2-thread-3] [3s 947ms] Http1Exchange sendBodyAsync
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange sendBodyAsync
FINE: [pool-2-thread-3] [3s 948ms] Http1Exchange bodySubscriber is class jdk.internal.net.http.Http1Request$FixedContentSubscriber
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange requestMoreBody
FINE: [pool-2-thread-3] [3s 948ms] Http1Exchange requesting more request body from the subscriber
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1BodySubscriber request
FINE: [pool-2-thread-3] [3s 948ms] jdk.internal.net.http.Http1Request@e059cdf Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@2892c38e
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Request$FixedContentSubscriber onNext
FINE: [pool-2-thread-3] [3s 949ms] jdk.internal.net.http.Http1Request@e059cdf onNext
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange appendToOutgoing
FINE: [pool-2-thread-3] [3s 949ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=133 cap=16384]], throwable=null]
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Request$FixedContentSubscriber onComplete
FINE: [pool-2-thread-3] [3s 949ms] jdk.internal.net.http.Http1Request@e059cdf onComplete
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange appendToOutgoing
FINE: [pool-2-thread-3] [3s 950ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-3] [3s 950ms] Http1Publisher(SocketTube(1)) onNext with 307 bytes
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$Http1WriteSubscription request
FINE: [pool-2-thread-3] [3s 950ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange requestMoreBody
FINE: [pool-2-thread-3] [3s 951ms] Http1Exchange requesting more request body from the subscriber
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1BodySubscriber request
FINE: [pool-2-thread-3] [3s 951ms] jdk.internal.net.http.Http1Request@e059cdf Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@2892c38e
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-3] [3s 951ms] Http1Publisher(SocketTube(1)) onNext with 133 bytes
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$Http1WriteSubscription request
FINE: [pool-2-thread-3] [3s 952ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange getOutgoing
FINE: [pool-2-thread-3] [3s 952ms] Http1Exchange initiating completion of bodySentCF
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.common.Utils lambda$wrapForDebug$7
FINE: [pool-2-thread-3] [3s 952ms] Http1Exchange sendBodyAsync completed successfully
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange getResponseAsync
FINE: [pool-2-thread-3] [3s 952ms] Http1Exchange reading headers
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response readHeadersAsync
FINE: [pool-2-thread-3] [3s 953ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) Reading Headers: (remaining: 0) READING_HEADERS
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response readHeadersAsync
FINE: [pool-2-thread-3] [3s 953ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) First time around
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Response readHeadersAsync
FINE: [pool-2-thread-3] [3s 953ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) headersReader is not yet completed
Jan 05, 2024 2:41:33 PM jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask run
FINE: [pool-2-thread-3] [3s 954ms] Http1Publisher(SocketTube(1)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@19f00ecb
Exception in thread "CDP Connection" org.openqa.selenium.devtools.DevToolsException: java.io.IOException: Output closed
Build info: version: '4.16.1', revision: '9b4c83354e'
System info: os.name: 'Windows 10', os.arch: 'amd64', os.version: '10.0', java.version: '11.0.0.1'
Driver info: driver.version: unknown
    at org.openqa.selenium.devtools.Connection$Listener.lambda$onText$0(Connection.java:239)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.openqa.selenium.WebDriverException: java.io.IOException: Output closed
Build info: version: '4.16.1', revision: '9b4c83354e'
System info: os.name: 'Windows 10', os.arch: 'amd64', os.version: '10.0', java.version: '11.0.0.1'
Driver info: driver.version: unknown
    at org.openqa.selenium.remote.http.jdk.JdkHttpClient$5.send(JdkHttpClient.java:304)
    at org.openqa.selenium.remote.http.WebSocket.sendText(WebSocket.java:32)
    at org.openqa.selenium.devtools.Connection.send(Connection.java:172)
    at org.openqa.selenium.devtools.Connection.sendAndWait(Connection.java:183)
    at org.openqa.selenium.devtools.DevTools.send(DevTools.java:89)
    at org.openqa.selenium.devtools.idealized.Network.lambda$prepareToInterceptTraffic$5(Network.java:258)
    at org.openqa.selenium.devtools.Connection.lambda$handle$5(Connection.java:345)
    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
    at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
    at java.base/java.util.stream.ReferencePipeline$11$1.accept(ReferencePipeline.java:442)
    at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1746)
    at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
    at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
    at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
    at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
    at org.openqa.selenium.devtools.Connection.handle(Connection.java:308)
    at org.openqa.selenium.devtools.Connection$Listener.lambda$onText$0(Connection.java:236)
    ... 3 more
Caused by: java.io.IOException: Output closed
    at java.net.http/jdk.internal.net.http.websocket.TransportImpl$SendTask.tryCompleteWrite(TransportImpl.java:609)
    at java.net.http/jdk.internal.net.http.websocket.TransportImpl$SendTask.run(TransportImpl.java:533)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
    at java.net.http/jdk.internal.net.http.websocket.TransportImpl.closeOutput(TransportImpl.java:318)
    at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl.close(WebSocketImpl.java:736)
    at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl.signalError(WebSocketImpl.java:720)
    at java.net.http/jdk.internal.net.http.websocket.WebSocketImpl$SignallingMessageConsumer.onError(WebSocketImpl.java:825)
    at java.net.http/jdk.internal.net.http.websocket.TransportImpl$ReceiveTask.run(TransportImpl.java:700)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
    at java.net.http/jdk.internal.net.http.websocket.TransportImpl$ReadEvent.handle(TransportImpl.java:762)
    at java.net.http/jdk.internal.net.http.RawChannelTube$ReadSubscriber.checkEvents(RawChannelTube.java:174)
    at java.net.http/jdk.internal.net.http.RawChannelTube$ReadSubscriber.onError(RawChannelTube.java:212)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadSubscription.signalCompletion(SocketTube.java:629)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:810)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:175)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:763)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:245)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:957)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:912)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1540)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:912)
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver asyncReceive
FINE: [HttpClient-1-SelectorManager] [16s 918ms] Http1AsyncReceiver(SocketTube(1)) Putting 122 bytes into the queue
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-3] [16s 919ms] Http1AsyncReceiver(SocketTube(1)) Got 122 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@61e341c5
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-3] [16s 920ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-3] [16s 920ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 122 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@61e341c5
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1Response$HeadersReader handle
FINE: [pool-2-thread-3] [16s 921ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) Sending 122/122 bytes to header parser
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1Response$HeadersReader handle
FINE: [pool-2-thread-3] [16s 921ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) Parsing headers completed. bytes=108
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver unsubscribe
FINE: [pool-2-thread-3] [16s 923ms] Http1AsyncReceiver(SocketTube(1)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@61e341c5
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1Response lambda$readHeadersAsync$0
FINE: [pool-2-thread-3] [16s 923ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) Reading Headers: creating Response object; state is now READING_BODY
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.common.Utils lambda$wrapForDebug$7
FINE: [pool-2-thread-3] [16s 924ms] Http1Exchange getResponseAsync completed successfully
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1Response$ClientRefCountTracker acquire
FINE: [pool-2-thread-3] [16s 925ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@1520a25(1)
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver subscribe
FINE: [pool-2-thread-3] [16s 926ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@768d0f2d/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@48bd3cc1 queue.isEmpty: false
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-3] [16s 926ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 14
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.ResponseContent$FixedLengthBodyParser onSubscribe
FINE: [pool-2-thread-3] [16s 926ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser length=14, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver handlePendingDelegate
FINE: [pool-2-thread-3] [16s 926ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@768d0f2d/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@48bd3cc1, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-3] [16s 927ms] Http1AsyncReceiver(SocketTube(1)) Got 14 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@768d0f2d/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@48bd3cc1
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver hasDemand
FINE: [pool-2-thread-3] [16s 927ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 9223372036854775807
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-3] [16s 927ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 14 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@768d0f2d/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@48bd3cc1
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1Response$BodyReader handle
FINE: [pool-2-thread-3] [16s 937ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) Sending 14/122 bytes to body parser
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.ResponseContent$FixedLengthBodyParser accept
FINE: [pool-2-thread-3] [16s 937ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got 14 bytes (14 remaining / 14)
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.ResponseContent$FixedLengthBodyParser accept
FINE: [pool-2-thread-3] [16s 938ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver clear
FINE: [pool-2-thread-3] [16s 938ms] Http1AsyncReceiver(SocketTube(1)) cleared
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1Response onFinished
FINE: [pool-2-thread-3] [16s 938ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) SocketTube(1): return to HTTP/1.1 pool
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber dropSubscription
FINE: [HttpClient-1-SelectorManager] [16s 939ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: dropSubscription
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1Response lambda$readBody$2
FINE: [pool-2-thread-3] [16s 939ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) Finished reading body: READING_BODY
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1Response$ClientRefCountTracker tryRelease
FINE: [pool-2-thread-3] [16s 940ms] Http1Response(id=9, PlainHttpConnection(SocketTube(1))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@1520a25(1)
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-3] [16s 940ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 0
Jan 05, 2024 2:41:46 PM jdk.internal.net.http.Http1AsyncReceiver flush
FINE: [pool-2-thread-3] [16s 941ms] Http1AsyncReceiver(SocketTube(1)) Got 0 bytes for delegate null
Jan 05, 2024 2:41:46 PM org.openqa.selenium.remote.RemoteWebDriver log
FINE: Executed: get (Response: SessionID: d1223449f4e95d5332ed3bcb58c38b74, State: success, Value: null)
pujagani commented 8 months ago

Sorry,I missed this. Sure, I can help take a look into this.

pujagani commented 8 months ago

I have tried to reproduce this using a simple Java class to run the example below. I am on MacOS, Edge version Version 120.0.2210.133. 

        WebDriver driver = new EdgeDriver();

        DevTools devTools = ((HasDevTools) driver).getDevTools();
        devTools.createSessionIfThereIsNotOne();

        devTools.send(Network.enable(Optional.empty(), Optional.empty(), Optional.empty()));
        devTools.addListener(
                Network.responseReceived(),
                responseConsumer -> {
                    Response response = responseConsumer.getResponse();
                    System.out.println("Intercepted Response--> {}" + response.getUrl());
                });

        Predicate<URI> uriPredicate = uri -> uri.getHost().contains("herokuapp");

        ((HasAuthentication) driver).register(uriPredicate,
                UsernameAndPassword.of("admin", "admin"));

        driver.get("https://the-internet.herokuapp.com/basic_auth");

        System.out.println(driver.findElement(By.tagName("p")).getText());

        driver.quit();

The output is:

Intercepted Response--> https://the-internet.herokuapp.com/basic_auth
Intercepted Response--> https://the-internet.herokuapp.com/js/foundation/foundation.js
Intercepted Response--> https://the-internet.herokuapp.com/css/font-awesome.css
Intercepted Response--> https://the-internet.herokuapp.com/js/vendor/298279967.js
Intercepted Response--> https://the-internet.herokuapp.com/js/foundation/foundation.alerts.js
Intercepted Response--> https://the-internet.herokuapp.com/img/forkme_right_green_007200.png
Intercepted Response--> https://the-internet.herokuapp.com/css/app.css
Intercepted Response--> https://the-internet.herokuapp.com/js/vendor/jquery-1.11.3.min.js
Intercepted Response--> https://the-internet.herokuapp.com/js/vendor/jquery-ui-1.11.4/jquery-ui.js
Congratulations! You must have the proper credentials.

Can you help me with a reproducible test script? Are you augmenting and using the RemoteWebDriver?

jonn-set commented 8 months ago

Thanks @pujagani for trying it out, I am unable to reproduce it on my personal machine either. Not sure if its caused by any leftover libraries from previous selenium versions, surprisingly everything works on 4.13. Give me some time, I will build and run the project in isolation and see if that resolves the issue. I will get back you soon.

pujagani commented 8 months ago

Sounds good. Please provide updates when you get a chance to do so, I will be happy to help.

jonn-set commented 8 months ago

Hi @pujagani,

I copied the project into a new folder on my work PC and ran the test again but I am seeing the same error, I am out of ideas to try.

This time I was running the tests through Cucumber and not using JUnit directly. The message is slightly different: Caused by: org.openqa.selenium.WebDriverException: java.io.IOException: closed output, last time it was Caused by: org.openqa.selenium.WebDriverException: java.io.IOException: Output closed. The point at which it is generated is also different this time.

Any clue in the logs below that I might have missed? Do you think I can try out anything more, please?

error-log.txt

pujagani commented 8 months ago

Are you able to reproduce it without using Cucumber using 4.16.1? Can you try to isolate it and create a simple project and try it out please? I think Diego is right in his suggestion here https://github.com/SeleniumHQ/selenium/issues/13397#issuecomment-1878439629. Can you also share the code you are using to reproduce this? Something is closing the socket before we create the connection, based on the log error message. That's very strange.

jonn-set commented 8 months ago

The first one I posted here was using JUnit but created in the same code base and not using any Cucumber.

Could something be timing out causing the issue. I use a few other libraries like spring-test, spring-context, awaitility, etc in the Test framework but awaitlity does not come into picture until much later in the code, the point where this happens only spring-context has been loaded to autowire dependencies.

Unfortunately, I cant share the full code as its against our company policy, but let me try creating a fresh project and hitting the same URL (its an internal app), I will try to retain the same libraries in the new project. I will get back to you.

And thanks for your help so far.

pujagani commented 8 months ago

I appreciate your efforts here. However, I will need something reproducible to work with. It could be a sample project (GitHub project with instructions)or a minimal reproducible test script/setup, possibly with minimum dependencies too, to isolate the issue at hand. It is easier to triage that way and fix things. I will appreciate something on these lines if possible.

jonn-set commented 8 months ago

sure, will do something like that. I will create new project that will only authenticate using BiDi and intercept network but will retain all libraries I am currently using. If I am able to reproduce the issue, then I will share a runnable project, I will keep you updated.

Thanks.

diemol commented 6 months ago

I will close this for now, as we have not gotten any updates. I can reopen as soon as more information is provided.

jonn-set commented 6 months ago

Sorry I couldn't get back earlier, thanks everyone who helped with this, especially @pujagani. We stopped using BiDi for auth, instead went back to passing username:password@ in the URL and no failure is seen even after upgrading to 4.18.1. It looks like its a problem specific to our kerberos server which is causing the Predicate to timeout. When I get some time, I will probably revert back to BiDi auth on the new version of Selenium and get back if I can reproduce the issue.

Appreciate your help on this.

pujagani commented 6 months ago

Thank you for the update and the details around it.

jonn-set commented 6 months ago

@pujagani sorry for a being a pain. The BiDi feature is a bit new to a lot of people, so have a few questions and I am not sure where to ask this so asking here.

I am trying to use the instructions here to authenticate using BiDi: https://github.com/SeleniumHQ/seleniumhq.github.io/blob/e8a3a8566ab3f2ecb9f57adf0285890051231f90/examples/java/src/test/java/dev/selenium/bidirectional/webdriver_bidi/NetworkCommandsTest.java#L56

This is the code that I have added to my existing method and commented out the (HasAuthentication) way:

try (Network network = new Network(driver)) {
  network.addIntercept(new AddInterceptParameters(InterceptPhase.AUTH_REQUIRED).urlPattern(
      new UrlPattern()
          .hostname("test.site.net")
          .protocol("https"));

  network.onAuthRequired(
      responseDetails ->
          network.continueWithAuth(
              responseDetails.getRequest().getRequestId(),
              new UsernameAndPassword(username, password)));

  driver.get("https://test.site.net/some/path/auth");
}

I have also set the capability when intialising the EdgeDriver:

options.setCapability("webSocketUrl", true);

But instead of being authenticated successfully, I am seeing the Browser AUTH popup and Selenium is unable to enter username/password into it. I believe like the (HasAuthentication) interface, it should already be authenticated and should not be popping the Browser AUTH Window

The code I used previously that worked when it worked before it started timing out:

Predicate<URI> uriPredicate = uri -> uri.getHost().contains("site.net");
              log.info("Logging in as '{}' using BiDi!", username);
              ((HasAuthentication) driver)
                  .register(
                      uriPredicate,
                      UsernameAndPassword.of(
                          Objects.requireNonNull(username), Objects.requireNonNull(password)));

  driver.get("https://test.site.net/some/path/auth");

Any help is appreciated.

Thanks

pujagani commented 6 months ago

I understand your concern. Ideally, it should work. The code example works as expected. The underlying implemented for both methods are different protocols. While the goal is to achieve the same outcome, the way the protocol achieves that might be different. I think it has something to do with the URL pattern passed. Let me try something and get back to you.

pujagani commented 6 months ago

Can you check the debug logs? I don't think it is supported in Edge yet https://wpt.fyi/results/webdriver/tests/bidi/network/continue_with_auth?label=master&label=experimental&aligned&view=subtest.

jonn-set commented 6 months ago

that's a shame :( NP, I will wait for it to be available on Edge as well then. Thanks again for your help.

github-actions[bot] commented 5 months ago

This issue has been automatically locked since there has not been any recent activity since it was closed. Please open a new issue for related bugs.