Possible concurrency issue in DevTools
joerg1985 opened this issue · 8 comments
🐛 Bug Report
I am intercepting traffic using the org.openqa.selenium.devtools.v93.fetch.Fetch class.
In rare cases a TimeoutException Unable to process: {"method":"Fetch.requestPaused", ... is raised while calling Fetch.continueRequest.
I would suspect there an concurrency issue in the DevTools. The command is send and Selenium is waiting for the "okay" answer from the browser. Concurrently the browser is sending another "Fetch.requestPaused" event that can not be processed at this time.
[WARNING] 00:00:30 Unable to process: {"method":"Fetch.requestPaused","params":{"requestId":"interception-job-35.0","request":{"url":"https://**removed**","method":"GET","headers":{**removed**}]},"sessionId":"0DC762612D7CDDB09AB67995EB18CC02"}
[WARNING] org.openqa.selenium.TimeoutException: java.util.concurrent.TimeoutException
[WARNING] Build info: version: '4.0.0-rc-2', revision: '8d1e4aa5ae'
[WARNING] System info: host: '**removed**', ip: '**removed**', os.name: 'Windows 10', os.arch: 'amd64', os.version: '10.0', java.version: '11.0.12'
[WARNING] Driver info: driver.version: unknown
[WARNING] at org.openqa.selenium.devtools.Connection.sendAndWait(Connection.java:161)
[WARNING] at org.openqa.selenium.devtools.DevTools.send(DevTools.java:70)
[WARNING] at **removed**.TestCase.lambda$__register_devtools$3(TestCase.java:146)
[WARNING] at org.openqa.selenium.devtools.Connection.lambda$handle$6(Connection.java:288)
[WARNING] at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
[WARNING] at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
[WARNING] at java.base/java.util.stream.ReferencePipeline$11$1.accept(ReferencePipeline.java:442)
[WARNING] at java.base/java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1603)
[WARNING] at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
[WARNING] at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
[WARNING] at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
[WARNING] at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
[WARNING] at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
[WARNING] at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
[WARNING] at org.openqa.selenium.devtools.Connection.handle(Connection.java:257)
[WARNING] at org.openqa.selenium.devtools.Connection.access$200(Connection.java:58)
[WARNING] at org.openqa.selenium.devtools.Connection$Listener.lambda$onText$0(Connection.java:199)
[WARNING] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[WARNING] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[WARNING] at java.base/java.lang.Thread.run(Thread.java:829)
[WARNING] ... 1 skipped
[WARNING] Caused by: java.util.concurrent.TimeoutException
[WARNING] at java.base/java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1886)
[WARNING] at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2021)
[WARNING] at org.openqa.selenium.devtools.Connection.sendAndWait(Connection.java:150)
[WARNING] ... 19 more
The code in the TestCase.java is:
line 145: // continuing the request
line 146: devTools.send(Fetch.continueRequest(
line 147: requestId, Optional.empty(), Optional.empty(),
line 148: Optional.empty(), Optional.empty()
line 149: ));
To Reproduce
I am not able to reproduce, i will try when i am back to office in a view days.
Environment
OS: Windows 10 x64
Browser: Chrome
Browser version: 94.0.4606.71
Browser Driver version: 94.0.4606.61
Language Bindings version: Java, Selenium 4 rc2
Selenium Grid version (if applicable):
Ok, let us know when possible how to reproduce, or if this issue should be reported to the CDP team.
From memory, I believe that we only wait for a certain amount of time in some code paths (notably where we want to treat a devtools call as being synchronous). However, Fetch.requestPaused looks like someone is using the NetworkInterceptor, so I don't think they're hitting that code path. A reproducible test case would be really helpful here.
I am not using the NetworkInterceptor - if was not aware of it's existence - the Fetch class is used directly.
I enabled logging of the connection to be able to analize it the next time it happens.
In the mean time i had a deeper look into the issue and i am able to provoke this by simulation the communication between selenium and the browser. Selenium is waiting for the ´´okay´´ to the last ´´Fetch.continueRequest´´ and the browser is calling the next ´´Fetch.requestPaused´´ without sending the ´´okay´´.
If i remember correctly this only happed, while the page was initially loading and then got redirected to the single sign on at a different URL. Therefore the "missing" ´´okay´´ might be related to the reload of the page. I will try to provoke this situation with a real browser instance and a redirect to a different page, stay tuned.
I am not able to reliable reproduce this with a real browser, but with a simulated browser. It looks like a Fetch.requestPaused sent to selenium might spawn a new thread in the executor. All threads are calling DevTools.send and there is no synchronization inside the send method. In rare cases this leads to the reported TimeoutException.
There is a MONKEY_PATCH field in the Sample to enable synchronization on DevTools.send and the TimeoutException will not happen any more.
import java.io.UncheckedIOException;
import java.util.Optional;
import java.util.concurrent.atomic.AtomicLong;
import org.openqa.selenium.TimeoutException;
import org.openqa.selenium.devtools.Command;
import org.openqa.selenium.devtools.Connection;
import org.openqa.selenium.devtools.DevTools;
import org.openqa.selenium.devtools.v93.V93Domains;
import org.openqa.selenium.devtools.v93.fetch.Fetch;
import org.openqa.selenium.devtools.v93.fetch.model.RequestId;
import org.openqa.selenium.remote.http.*;
public class Sample {
// enables synchronisation on DevTools.send()
private static final boolean MONKEY_PATCH = false;
public static void main(String[] args) throws Exception {
HttpClient client = new HttpClient() {
String lastSend;
@Override
public WebSocket openSocket(HttpRequest request, WebSocket.Listener listener) {
Thread fakeBrowser = new Thread() {
@Override
public void run() {
AtomicLong id = new AtomicLong(7);
String lastHandled = null;
while (!this.interrupted()) {
Thread.onSpinWait();
synchronized (HttpClient.class) {
// identity check to handle exery message only once
if (lastHandled != lastSend) {
if (lastSend.contains("Target.getTargets")) {
listener.onText(
"{\"id\":1,\"result\":{\"targetInfos\":[{\"targetId\":\"FF3412F7FA4858A2C3164FB51CA9E3EC\",\"type\":\"page\",\"title\":\"MyPage\",\"url\":\"https://mypage.com\",\"attached\":true,\"canAccessOpener\":false,\"browserContextId\":\"A2E1698768A4812C074356A3F72EF219\"}]}}"
);
} else if (lastSend.contains("Target.attachToTarget")) {
listener.onText(
"{\"method\":\"Target.attachedToTarget\",\"params\":{\"sessionId\":\"76D7BD8BC80C0ED5A64F2DD25450284E\",\"targetInfo\":{\"targetId\":\"5C366C73D80387FA4DC9D4C30D2A7610\",\"type\":\"page\",\"title\":\"MyPage\",\"url\":\"https://mypage.com\",\"attached\":true,\"canAccessOpener\":false,\"browserContextId\":\"165C93C893DAFDA49246BF8C4F5B04B1\"},\"waitingForDebugger\":false}}"
);
listener.onText(
"{\"id\":2,\"result\":{\"sessionId\":\"76D7BD8BC80C0ED5A64F2DD25450284E\"}}"
);
} else if (lastSend.contains("Target.setAutoAttach")) {
listener.onText(
"{\"id\":3,\"result\":{},\"sessionId\":\"76D7BD8BC80C0ED5A64F2DD25450284E\"}"
);
} else if (lastSend.contains("Log.clear")) {
listener.onText(
"{\"id\":4,\"result\":{},\"sessionId\":\"76D7BD8BC80C0ED5A64F2DD25450284E\"}"
);
} else if (lastSend.contains("Fetch.enable")) {
listener.onText(
"{\"id\":5,\"result\":{},\"sessionId\":\"76D7BD8BC80C0ED5A64F2DD25450284E\"}"
);
listener.onText(
"{\"method\":\"Fetch.requestPaused\",\"params\":{\"requestId\":\"interception-job-7.0\",\"request\":{\"url\":\"https://mypage.com/dummy.txt\",\"method\":\"GET\",\"headers\":{\"sec-ch-ua\":\"\\\"Chromium\\\";v=\\\"94\\\", \\\"Google Chrome\\\";v=\\\"94\\\", \\\";Not A Brand\\\";v=\\\"99\\\"\",\"User-Agent\":\"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.81 Safari/537.36\",\"content-type\":\"application/json\",\"sec-ch-ua-platform\":\"\\\"Windows\\\"\",\"Accept\":\"*/*\",\"Referer\":\"https://mypage.com\",\"Cookie\":\"DUMMY=true\"},\"initialPriority\":\"High\",\"referrerPolicy\":\"strict-origin-when-cross-origin\"},\"frameId\":\"5C366C73D80387FA4DC9D4C30D2A7610\",\"resourceType\":\"XHR\",\"responseStatusCode\":200,\"responseHeaders\":[{\"name\":\"Content-Type\",\"value\":\"application/json\"},{\"name\":\"Keep-Alive\",\"value\":\"timeout=5, max=97\"},{\"name\":\"Connection\",\"value\":\"Keep-Alive\"},{\"name\":\"Transfer-Encoding\",\"value\":\"chunked\"}]},\"sessionId\":\"76D7BD8BC80C0ED5A64F2DD25450284E\"}"
);
} else if (lastSend.contains("Fetch.continueRequest")) {
long next = id.incrementAndGet();
listener.onText(
"{\"method\":\"Fetch.requestPaused\",\"params\":{\"requestId\":\"interception-job-" + next + ".0\",\"request\":{\"url\":\"https://mypage.com/dummy.txt\",\"method\":\"GET\",\"headers\":{\"sec-ch-ua\":\"\\\"Chromium\\\";v=\\\"94\\\", \\\"Google Chrome\\\";v=\\\"94\\\", \\\";Not A Brand\\\";v=\\\"99\\\"\",\"User-Agent\":\"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.81 Safari/537.36\",\"content-type\":\"application/json\",\"sec-ch-ua-platform\":\"\\\"Windows\\\"\",\"Accept\":\"*/*\",\"Referer\":\"https://mypage.com\",\"Cookie\":\"DUMMY=true\"},\"initialPriority\":\"High\",\"referrerPolicy\":\"strict-origin-when-cross-origin\"},\"frameId\":\"5C366C73D80387FA4DC9D4C30D2A7610\",\"resourceType\":\"XHR\",\"responseStatusCode\":200,\"responseHeaders\":[{\"name\":\"Content-Type\",\"value\":\"application/json\"},{\"name\":\"Keep-Alive\",\"value\":\"timeout=5, max=97\"},{\"name\":\"Connection\",\"value\":\"Keep-Alive\"},{\"name\":\"Transfer-Encoding\",\"value\":\"chunked\"}]},\"sessionId\":\"76D7BD8BC80C0ED5A64F2DD25450284E\"}"
);
// returning more than one 'Fetch.requestPaused' will make the client spawn new threads
if (next % 64 == 0) {
listener.onText(
"{\"method\":\"Fetch.requestPaused\",\"params\":{\"requestId\":\"interception-job-" + id.incrementAndGet() + ".0\",\"request\":{\"url\":\"https://mypage.com/dummy.txt\",\"method\":\"GET\",\"headers\":{\"sec-ch-ua\":\"\\\"Chromium\\\";v=\\\"94\\\", \\\"Google Chrome\\\";v=\\\"94\\\", \\\";Not A Brand\\\";v=\\\"99\\\"\",\"User-Agent\":\"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.81 Safari/537.36\",\"content-type\":\"application/json\",\"sec-ch-ua-platform\":\"\\\"Windows\\\"\",\"Accept\":\"*/*\",\"Referer\":\"https://mypage.com\",\"Cookie\":\"DUMMY=true\"},\"initialPriority\":\"High\",\"referrerPolicy\":\"strict-origin-when-cross-origin\"},\"frameId\":\"5C366C73D80387FA4DC9D4C30D2A7610\",\"resourceType\":\"XHR\",\"responseStatusCode\":200,\"responseHeaders\":[{\"name\":\"Content-Type\",\"value\":\"application/json\"},{\"name\":\"Keep-Alive\",\"value\":\"timeout=5, max=97\"},{\"name\":\"Connection\",\"value\":\"Keep-Alive\"},{\"name\":\"Transfer-Encoding\",\"value\":\"chunked\"}]},\"sessionId\":\"76D7BD8BC80C0ED5A64F2DD25450284E\"}"
);
}
int pos = lastSend.indexOf("\"id\":");
listener.onText(
"{\"id\":" + lastSend.substring(pos + 6, lastSend.indexOf(",", pos)) + ",\"result\":{},\"sessionId\":\"76D7BD8BC80C0ED5A64F2DD25450284E\"}"
);
} else {
return;
}
lastHandled = lastSend;
}
}
}
}
};
fakeBrowser.start();
return new WebSocket() {
@Override
public WebSocket sendText(CharSequence data) {
synchronized (HttpClient.class) {
lastSend = data.toString();
}
return this;
}
@Override
public WebSocket send(Message message) {
throw new UnsupportedOperationException("Not supported yet.");
}
@Override
public void close() {
fakeBrowser.interrupt();
}
};
}
@Override
public HttpResponse execute(HttpRequest req) throws UncheckedIOException {
throw new UnsupportedOperationException("Not supported yet.");
}
};
Connection connection = new Connection(client, "http://127.0.0.1");
DevTools tools;
if (MONKEY_PATCH) {
tools = new DevTools(V93Domains::new, connection) {
@Override
public <X> X send(Command<X> command) {
synchronized (connection) {
return super.send(command);
}
}
};
} else {
tools = new DevTools(V93Domains::new, connection);
}
tools.createSession();
tools.addListener(Fetch.requestPaused(), (entry) -> {
RequestId requestId = entry.getRequestId();
System.out.println("continueRequest: " + requestId);
try {
tools.send(Fetch.continueRequest(
requestId, Optional.empty(), Optional.empty(),
Optional.empty(), Optional.empty()
));
} catch (TimeoutException e) {
e.printStackTrace();
System.exit(666);
}
});
tools.send(Fetch.enable(Optional.empty(), Optional.empty()));
Thread.sleep(60000);
}
}
Thanks for the details, but in the end it is not easy for us to troubleshoot without a way to reproduce this. We'll leave this open in case someone has a way to reproduce this issue.
@diemol i am now able to reproduce, see code below.
The access to org.openqa.selenium.devtools.Connection.methodCallbacks is not synchronized, some threads are writing while others are reading. I guess this is the root cause of this issue and replacing the LinkedHashMap by a ConcurrentHashMap should fix this. I am not sure if the socket.sendText call needs to be synchronized too.
import java.util.List;
import java.util.Optional;
import org.openqa.selenium.TimeoutException;
import org.openqa.selenium.chrome.ChromeDriver;
import org.openqa.selenium.devtools.DevTools;
import org.openqa.selenium.devtools.v96.fetch.Fetch;
import org.openqa.selenium.devtools.v96.fetch.model.RequestId;
import org.openqa.selenium.devtools.v96.fetch.model.RequestPattern;
import org.openqa.selenium.devtools.v96.fetch.model.RequestStage;
import org.openqa.selenium.devtools.v96.browser.Browser;
public class Sample {
public static void main(String[] args) throws Exception {
ChromeDriver driver = new ChromeDriver();
try {
DevTools tools = driver.getDevTools();
tools.createSession();
tools.addListener(Fetch.requestPaused(), (entry) -> {
RequestId requestId = entry.getRequestId();
try {
// continue loading the request
tools.send(Fetch.continueRequest(
requestId, Optional.empty(), Optional.empty(),
Optional.empty(), Optional.empty(), Optional.empty()
));
// stress the connection by running a arbitrarily command for ever
while (true) {
tools.send(Browser.getVersion());
}
} catch (TimeoutException e) {
e.printStackTrace();
// we are doomed, the bug has occurred
System.exit(666);
}
});
tools.send(Fetch.enable(
Optional.of(List.of(new RequestPattern(Optional.of("*"), Optional.empty(), Optional.of(RequestStage.RESPONSE)))),
Optional.empty()
));
driver.get("https://www.selenium.dev/");
for (int i = 0; i < 8; i++) {
Thread.sleep(2000);
// each reload will spawn more threads
driver.executeScript("window.location.reload();");
}
Thread.sleep(600 * 1000);
} finally {
driver.close();
}
}
}
@joerg1985 Thank you for your efforts in reproducing this and pointing to the solution. I was able to reproduce it locally and use the suggested solution in the local maven project and run the code snippet shared above on repeat to ensure the TimeoutException is not thrown. However, I was not able to reproduce it with a test in the Selenium repo after spending significant time on it. Will spend some more time on it.
This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.