Boolean with delay is evaluated, but not properly timed-CodePudding

I have a method that executes a Runnable and then passes the time it took for it to finish to another method:

public static void benchmark(Runnable runnable) {
    LocalDateTime before = LocalDateTime.now();
    runnable.run();
    logToDocument(before, LocalDateTime.now());
}

When I use this method to time the loading of a webpage, both timestamps are exactly the same, i.e. LocalDateTime before = LocalDateTime.now() and logToDocument(before, LocalDateTime.now()) happen at the same time, even though I observe that in reality it takes a couple of seconds for each page to load. The method from which I call benchmark is as follows:

public static void subTestDelay(boolean log, boolean condition, int delay, String message) {
    if (log) {
        SoftAssert softAssert = new SoftAssert();
        ExtentTestManager.benchmark(() -> {
            if (!condition) {
               tempData.failStatus();
               softAssert.fail("Timeout after waiting ".concat(String.valueOf(delay)).concat(" seconds for ").concat(message));
           }
        });
        softAssert.assertAll();
    } else {
        Assert.assertTrue(condition, "Timeout after waiting ".concat(String.valueOf(delay)).concat(" seconds for ").concat(message));
    }
}

The variable condition, in this case, is this:

public static boolean expectedPageIsLoaded(WebDriver driver, int seconds, String pageName) {
    final By loadingBar = By.cssSelector("div[class*='progress']");
    final Wait<WebDriver> wait = new FluentWait<>(driver).withTimeout(Duration.ofSeconds(seconds)).pollingEvery(Duration.ofSeconds(1)).ignoring(NoSuchElementException.class).ignoring(NullPointerException.class);
    String originalPageName = driver.findElement(By.tagName("body")).getAttribute("page-name");
    if (originalPageName == null) {
        originalPageName = "no previous page";
        tempData.setAction(tempData.REDIRECT);
        tempData.setArbitraryData(driver,tempData.TRIGGER, tempData.NAVIGATION, tempData.ORIGIN, originalPageName, tempData.DESTINATION, "user authentication");
    }
    ExtentTestManager.log(logger, Level.INFO, "Loading page: ".concat(pageName).concat("; Waiting a maximum of: ").concat(String.valueOf(seconds)).concat(" seconds"));
    try {
        startDateTime = LocalDateTime.now();
        wait.until(ExpectedConditions.presenceOfAllElementsLocatedBy(loadingBar));
        wait.until(wd -> (GenericTestMethods.pageName(wd).equals(pageName) && wd.findElements(loadingBar).size() == 0));
        endDateTime = LocalDateTime.now();
        ExtentTestManager.log(logger, Level.INFO, "Page: ".concat(pageName).concat(" loaded after: ").concat(String.valueOf(Duration.between(startDateTime, endDateTime).toMillis())).concat(" milliseconds"));
        return true;
    } catch (TimeoutException ex) {
        return false;
    }
}

When I test this for 4 webpages in a row, I get the correct duration of each page load, as you can see here:

12:35:36.774 [main] INFO  test_classes.base.DriverInit - Loading page: user authentication; Waiting a maximum of: 180 seconds
12:35:39.902 [main] INFO  test_classes.base.DriverInit - Page: user authentication loaded after: 3124 milliseconds
12:35:41.333 [main] INFO  test_classes.base.DriverInit - Loading page: user_cockpit; Waiting a maximum of: 180 seconds
12:35:46.474 [main] INFO  test_classes.base.DriverInit - Page: user_cockpit loaded after: 5140 milliseconds
12:35:47.947 [main] INFO  test_classes.base.DriverInit - Loading page: organization_overview_time_focus; Waiting a maximum of: 180 seconds
12:35:50.013 [main] INFO  test_classes.base.DriverInit - Page: organization_overview_time_focus loaded after: 2066 milliseconds
12:35:51.210 [main] INFO  test_classes.base.DriverInit - Loading page: project_time_overview; Waiting a maximum of: 180 seconds
12:35:52.604 [main] INFO  test_classes.base.DriverInit - Page: project_time_overview loaded after: 1393 milliseconds
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 25.446 s - in TestSuite

This feedback comes from these lines from the boolean expectedPageIsLoaded :

startDateTime = LocalDateTime.now();
    wait.until(ExpectedConditions.presenceOfAllElementsLocatedBy(loadingBar));
    wait.until(wd -> (GenericTestMethods.pageName(wd).equals(pageName) && wd.findElements(loadingBar).size() == 0));
    endDateTime = LocalDateTime.now();
    ExtentTestManager.log(logger, Level.INFO, "Page: ".concat(pageName).concat(" loaded after: ").concat(String.valueOf(Duration.between(startDateTime, endDateTime).toMillis())).concat(" milliseconds"));

However, the feedback I get from benchmark is two timestamps each time before and after loading a page, which are always the same. To illustrate this, I modified benchmark to print out the timestamps before and after the Runnable. This is what I got:

Before loading: 2021-11-03T12:42:42.855008800
After loading: 2021-11-03T12:42:42.855008800
Before loading: 2021-11-03T12:42:51.505117900
After loading: 2021-11-03T12:42:51.505117900
Before loading: 2021-11-03T12:42:55.145636200
After loading: 2021-11-03T12:42:55.145636200
Before loading: 2021-11-03T12:42:57.555875200
After loading: 2021-11-03T12:42:57.555875200

It seems that condition in my subTestDelay method is evaluated correctly, but the actual time it takes is ignored. I suspect this is because runnable.run() inside the benchmark method is executed on another thread, but I lack the experience to figure out a solution to that. Could anyone steer me in the right direction?

CodePudding user response：

I was finally able to solve this problem! For those interested, here's what I did. I edited subTestDelay to take in a Supplier<Boolean> condition instead of a boolean condition. Now, the evaluation of condition.get() is timed. This seems to be what fixed the issue (I don't know why, though).

subTestDelay now looks like this:

public static void subTestDelay(boolean log, Supplier<Boolean> condition, int delay, String message) {
    String msg = "Timeout after waiting ".concat(String.valueOf(delay)).concat(" seconds for ");
    if (log) {
        Assert.assertTrue(ExtentTestManager.benchmark(() -> {
            if (!condition.get()) {
                tempData.failStatus();
                return false;
            }
            return true;
        }), msg.concat(message));
    } else {
        Assert.assertTrue(condition.get(), msg.concat(message));
    }
}

benchmark was also edited to take in a Supplier<Boolean> instead of a Runnable:

public static boolean benchmark(Supplier<Boolean> supplier) {
    LocalDateTime before = LocalDateTime.now();
    boolean returnValue = supplier.get();
    logToDocument(before, LocalDateTime.now());
    return returnValue;
}

The same test now yields the correct results:

Before loading:2021-11-05T11:08:39.758627100
After loading:2021-11-05T11:08:43.953063700
Before loading:2021-11-05T11:08:45.309372500
After loading:2021-11-05T11:08:52.510232700
Before loading:2021-11-05T11:08:53.963683900
After loading:2021-11-05T11:08:56.048520300
Before loading:2021-11-05T11:08:57.233896600
After loading:2021-11-05T11:08:58.438004100