WebClient.goTo requests cause 10s wasted delay for each call #946
Description
Jenkins and plugins versions report
The WebClientUtil.waitForJSExec(this) from goTo (code ref) is causing 10s wasted due to a hardcoded 10s blocking time,
jenkins-test-harness/src/main/java/org/htmlunit/WebClientUtil.java
Lines 38 to 58 in 10f2800
Due to this whenever a test visits a page having javascript calls and if it didn't explicitly disabled javascript by,
webClient.getOptions().setJavaScriptEnabled(false);
such test will be slow by 10s, for each page calls it makes. (for example, if there are two goTo calls, it will be 20s delays)
Currently this is known to affect the pages visiting a builds workspace page, example,
SlowTest
package test;
import hudson.model.FreeStyleProject;
import java.util.logging.Logger;
import org.junit.Rule;
import org.junit.Test;
import org.jvnet.hudson.test.JenkinsRule;
public class SlowTest {
@Rule
public JenkinsRule j = new JenkinsRule();
private static final Logger LOGGER = Logger.getLogger(SlowTest.class.getName());
@Test
public void slowTest() throws Exception {
var f = j.createProject(FreeStyleProject.class, "f");
var r = f.scheduleBuild2(0);
j.assertBuildStatusSuccess(r);
var client = j.createWebClient();
LOGGER.info("calling javascript enabled");
var page = client.goTo(f.getUrl() + "ws");
LOGGER.info("call returned");
client.getOptions().setJavaScriptEnabled(false);
LOGGER.info("calling with disable javascript");
page = client.goTo(f.getUrl() + "ws");
LOGGER.info("call returned");
}
}Notice 10s delay in goTo call when javascript is enabled, but goes away if disabling javascript,
log
[INFO] T E S T S
[INFO] -------------------------------------------------------
[INFO] Running test.SlowTest
=== Starting slowTest(test.SlowTest)
0.051 [id=20] INFO o.jvnet.hudson.test.WarExploder#explode: Using jenkins.war resources from /.../jenkins/war/target/jenkins
0.329 [id=20] INFO o.jvnet.hudson.test.JenkinsRule#createWebServer2: Running on http://localhost:56294/jenkins/
0.387 [id=20] INFO jenkins.model.Jenkins#<init>: Starting version 2.504-SNAPSHOT
0.438 [id=35] INFO jenkins.InitReactorRunner$1#onAttained: Started initialization
1.029 [id=40] INFO hudson.PluginManager#considerDetachedPlugin: Loading a detached plugin /var/folders/80/w8mmdy513sb3y9fp5fr7vvqc0000gn/T/jenkins12015357254730471352/command-launcher.jpi as a dependency of gradle
1.038 [id=40] INFO hudson.PluginManager#considerDetachedPlugin: Loading a detached plugin /var/folders/80/w8mmdy513sb3y9fp5fr7vvqc0000gn/T/jenkins12015357254730471352/apache-httpcomponents-client-4-api.jpi as a dependency of gradle
1.059 [id=40] INFO hudson.PluginManager#considerDetachedPlugin: Loading a detached plugin /var/folders/80/w8mmdy513sb3y9fp5fr7vvqc0000gn/T/jenkins12015357254730471352/jdk-tool.jpi as a dependency of gradle
1.072 [id=40] INFO hudson.PluginManager#considerDetachedPlugin: Loading a detached plugin /var/folders/80/w8mmdy513sb3y9fp5fr7vvqc0000gn/T/jenkins12015357254730471352/trilead-api.jpi as a dependency of gradle
1.100 [id=40] INFO hudson.PluginManager#considerDetachedPlugin: Loading a detached plugin /var/folders/80/w8mmdy513sb3y9fp5fr7vvqc0000gn/T/jenkins12015357254730471352/eddsa-api.jpi as a dependency of gradle
1.104 [id=40] INFO hudson.PluginManager#considerDetachedPlugin: Loading a detached plugin /var/folders/80/w8mmdy513sb3y9fp5fr7vvqc0000gn/T/jenkins12015357254730471352/gson-api.jpi as a dependency of gradle
1.118 [id=40] INFO hudson.PluginManager#considerDetachedPlugin: Loading a detached plugin /var/folders/80/w8mmdy513sb3y9fp5fr7vvqc0000gn/T/jenkins12015357254730471352/mina-sshd-api-common.jpi as a dependency of gradle
1.129 [id=40] INFO hudson.PluginManager#considerDetachedPlugin: Loading a detached plugin /var/folders/80/w8mmdy513sb3y9fp5fr7vvqc0000gn/T/jenkins12015357254730471352/mina-sshd-api-core.jpi as a dependency of gradle
1.147 [id=40] INFO hudson.PluginManager#considerDetachedPlugin: Loading a detached plugin /var/folders/80/w8mmdy513sb3y9fp5fr7vvqc0000gn/T/jenkins12015357254730471352/sshd.jpi as a dependency of gradle
1.365 [id=40] INFO jenkins.InitReactorRunner$1#onAttained: Listed all plugins
1.374 [id=56] INFO j.b.api.BouncyCastlePlugin#start: /.../jenkins/test/target/j h12717851222699405434/plugins/bouncycastle-api/WEB-INF/optional-lib not found; for non RealJenkinsRule this is fine and can be ignored.
1.939 [id=45] INFO jenkins.InitReactorRunner$1#onAttained: Prepared all plugins
1.945 [id=45] INFO jenkins.InitReactorRunner$1#onAttained: Started all plugins
1.945 [id=56] INFO jenkins.InitReactorRunner$1#onAttained: Augmented all extensions
2.284 [id=35] INFO jenkins.InitReactorRunner$1#onAttained: System config loaded
2.284 [id=39] INFO jenkins.InitReactorRunner$1#onAttained: System config adapted
2.284 [id=39] INFO jenkins.InitReactorRunner$1#onAttained: Loaded all jobs
2.287 [id=36] INFO jenkins.InitReactorRunner$1#onAttained: Configuration for all jobs updated
2.342 [id=40] INFO jenkins.InitReactorRunner$1#onAttained: Completed initialization
3.099 [id=20] INFO test.SlowTest#slowTest: calling javascript enabled
14.463 [id=20] INFO test.SlowTest#slowTest: call returned
14.463 [id=20] INFO test.SlowTest#slowTest: calling with disable javascript
14.593 [id=20] INFO test.SlowTest#slowTest: call returned
14.602 [id=20] INFO hudson.lifecycle.Lifecycle#onStatusUpdate: Stopping Jenkins
WARN: The method class org.apache.commons.logging.impl.SLF4JLogFactory#release() was invoked.
WARN: Please see http://www.slf4j.org/codes.html#release for an explanation.
14.631 [id=20] INFO hudson.lifecycle.Lifecycle#onStatusUpdate: Jenkins stopped
14.660 [id=20] INFO o.j.h.t.TemporaryDirectoryAllocator#dispose: deleting /.../jenkins/test/target/j h12717851222699405434
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 14.97 s -- in test.SlowTest
[INFO]
[INFO] Results:
[INFO]
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 18.210 s
[INFO] Finished at: 2025-03-27T19:59:54+05:30
[INFO] ------------------------------------------------------------------------
What Operating System are you using (both controller, and any agents involved in the problem)?
This occurs in the current version of JTH, and latest jenkins.
Reproduction steps
(sample test and logs provided in description)
Expected Results
WebClient.goTo shouldn't block silently (with constant timeout such as 10s), or at least forces the developer to specific delay explicitly.
Actual Results
Each goTo calls seem to be causing 10s blocking delays.
Anything else?
This problem was noticed and debugged here jenkinsci/jenkins#10471 (comment)
This might be already having a larger impact on the test suit by causing several minutes of delays when aggregated.
As per discussion in here,
we should make a breaking change that makes the test supply a required timeout value, and ideally library methods like goTo shouldn't do waiting internally on it's own - but require the developers to use await().until pattern.
There are 3 such calls for WebClientUtil.waitForJSExec(this) in JenkinsRule, need to check those as well.
Are you interested in contributing a fix?
No response