[🐛 Bug]: TimeoutException on closed NetworkInterceptor and quit driver

[tholewebgods]

What happened?

Summary

When a NetworkInterceptor and related WebDriver are closed/quit, the "CDP Connection" thread may eventually throw a TimeoutException.

This error occures a couple of seconds after the interceptor and driver have been closed/quit.

Here you can find a MCVE that is able to reproduce the error in at least 50% of the runs: https://github.com/tholewebgods/selenium-devtools-intercept-timeout-mcve (see the readme.md)

The code is reduced almost as much as possible for simplicity sake. The sleep is a replacement for a TestNG runner continuing to run further tests with new WebDriver sessions.

Guess

It looks like the CDP Connection thread is not informed of the interceptor shutdown and tries to handle communication that can no longer happen, finally running into a timeout.

Expectation

The CDP connection threads are

1. either terminated when the interceptor or related driver were quit or

2. brought into a state that allows the worker to either silently ignore timeouts or to log them as debug messages only to a proper logger. These exceptions should only be thrown by the thread runner if the interceptor is still open.

How can we reproduce the issue?

Here you can find a MCVE that is able to reproduce the error in at least 50% of the runs: https://github.com/tholewebgods/selenium-devtools-intercept-timeout-mcve (see the readme.md).

TL;DR:

1. Open an interceptor
2. Interact with the page
3. Close the interceptor
4. Close the driver
5. Wait > 10s

Relevant log output

org.openqa.selenium.TimeoutException: java.util.concurrent.TimeoutException
Build info: version: '4.1.3', revision: '7b1ebf28ef'
System info: host: 'h001287568', ip: '10.208.2.6', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-192-generic', java.version: '11.0.16'
Driver info: driver.version: unknown
    at org.openqa.selenium.devtools.Connection.sendAndWait(Connection.java:161)
    at org.openqa.selenium.devtools.DevTools.send(DevTools.java:70)
    at org.openqa.selenium.devtools.idealized.Network.lambda$prepareToInterceptTraffic$4(Network.java:216)
    at org.openqa.selenium.devtools.Connection.lambda$handle$6(Connection.java:288)
    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$KeySpliterator.forEachRemaining(HashMap.java:1621)
    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:257)
    at org.openqa.selenium.devtools.Connection.access$200(Connection.java:58)
    at org.openqa.selenium.devtools.Connection$Listener.lambda$onText$0(Connection.java:199)
    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:829)
Caused by: java.util.concurrent.TimeoutException
    at java.base/java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1886)
    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2021)
    at org.openqa.selenium.devtools.Connection.sendAndWait(Connection.java:150)
    ... 19 more

Operating System

Ubuntu

Selenium version

4.1.3

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

Chrome 101 (Docker)

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

101.0 (Docker)

Are you using Selenium Grid?

4.4.0-20220812 (Docker)

[github-actions]

@tholewebgods, 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!

[tholewebgods]

When comparing two thread dumps, one process able to reproduce the error, another one not able to reproduce the error, such a thread can be observed with reproducible runs:

"CDP Connection" #41 daemon prio=5 os_prio=0 cpu=34.55ms elapsed=6.17s tid=0x00007f1150063800 nid=0x4890 waiting on condition  [0x00007f10e7af8000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@11.0.16/Native Method)
    - parking to wait for  <0x0000000713eaf4e8> (a java.util.concurrent.CompletableFuture$Signaller)
    at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.16/LockSupport.java:234)
    at java.util.concurrent.CompletableFuture$Signaller.block(java.base@11.0.16/CompletableFuture.java:1798)
    at java.util.concurrent.ForkJoinPool.managedBlock(java.base@11.0.16/ForkJoinPool.java:3128)
    at java.util.concurrent.CompletableFuture.timedGet(java.base@11.0.16/CompletableFuture.java:1868)
    at java.util.concurrent.CompletableFuture.get(java.base@11.0.16/CompletableFuture.java:2021)
    at org.openqa.selenium.devtools.Connection.sendAndWait(Connection.java:150)
    at org.openqa.selenium.devtools.DevTools.send(DevTools.java:70)
    at org.openqa.selenium.devtools.idealized.Network.lambda$prepareToInterceptTraffic$4(Network.java:216)
    at org.openqa.selenium.devtools.idealized.Network$$Lambda$475/0x0000000840336c40.accept(Unknown Source)
    at org.openqa.selenium.devtools.Connection.lambda$handle$6(Connection.java:288)
    at org.openqa.selenium.devtools.Connection$$Lambda$469/0x0000000840335440.accept(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(java.base@11.0.16/ForEachOps.java:183)
    at java.util.stream.ReferencePipeline$2$1.accept(java.base@11.0.16/ReferencePipeline.java:177)
    at java.util.stream.ReferencePipeline$11$1.accept(java.base@11.0.16/ReferencePipeline.java:442)
    at java.util.HashMap$KeySpliterator.forEachRemaining(java.base@11.0.16/HashMap.java:1621)
    at java.util.stream.AbstractPipeline.copyInto(java.base@11.0.16/AbstractPipeline.java:484)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(java.base@11.0.16/AbstractPipeline.java:474)
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(java.base@11.0.16/ForEachOps.java:150)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(java.base@11.0.16/ForEachOps.java:173)
    at java.util.stream.AbstractPipeline.evaluate(java.base@11.0.16/AbstractPipeline.java:234)
    at java.util.stream.ReferencePipeline.forEach(java.base@11.0.16/ReferencePipeline.java:497)
    at org.openqa.selenium.devtools.Connection.handle(Connection.java:257)
    at org.openqa.selenium.devtools.Connection.access$200(Connection.java:58)
    at org.openqa.selenium.devtools.Connection$Listener.lambda$onText$0(Connection.java:199)
    at org.openqa.selenium.devtools.Connection$Listener$$Lambda$454/0x0000000840331840.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.16/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.16/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.16/Thread.java:829)

The two example thread dumps: https://gist.github.com/tholewebgods/29beb182e47a57fc8938011e3223abca

[pujagani]

Thank you for sharing the details. Have you seen this only when using the Grid or even without the Grid it is observable.

[pujagani]

Is the error still occurring with Selenium 4.4?

[pujagani]

Thank you for the details and the repo. I was able to reproduce the error. I am currently debugging to understand why it happens.

[tholewebgods]

Hello and thank you for looking into this.

• I've only tested against grids yet (one in our dev network and a local one, basically the one included in the MCVE)
• I've not tested with Selenium 4.4

[pujagani]

Thank you for the update. It is occurring with Selenium Grid and local Chrome webdriver. It is also present in version 4.4 and 4.5 as well.

[pujagani]

From the suggested approach, the second approach of throwing errors only if the network interceptor is open is implemented and landed. It will be available in the next release.

[tholewebgods]

Thank you for quickly fixing this @pujagani.
Will this be 4.6.0 or be part of a minor/patch update in current releases?

[pujagani]

There is a plan to do a Java minor release soon. A few other Java bug fixes are included as well. It will be a part of that. It should be 4.5.1.