Report generation timed out for Requirements report

[vivregenek]

serenity-maven-plugin 1.9.19
serenity-core 1.9.19
serenity-junit 1.9.19
serenity-rest-assured 1.9.19
Hi! I have some problem with getting report.
[WARNING] Report generation timed out for Requirements report capabilities.html - java.util.concurrent.TimeoutException java.util.concurrent.FutureTask.get(FutureTask.java:205)
Also for other files capabilities.html. *.html.
What can be wrong?
And tell me please, is it ok? that in Reporter.generateReports() there are about 700 tasks just for one test.
Thank you.

[wakaleo]

It's normal that there are lots of tasks (one per page generated), as the report generation happens in parallel streams. Can you provide a project that reproduces the issue?

[vivregenek]

Sorry, I can't. But I suppose it can be
, affected by our big package structure with tests (many inner packages). When I set serenity.test.root to main package (with all test) get this error. And when set to inner package all is well.

[DjerohN]

Same issue here, versions:
<serenity.version>1.9.25</serenity.version>
<serenity.maven.version>1.9.25</serenity.maven.version>
<serenity.cucumber.version>1.9.8</serenity.cucumber.version>
<serenity.rest.assured.version>1.9.25</serenity.rest.assured.version>

[vivregenek]

I fixed problem by change all packages name with tests to unique values. In my packeges sturcture was with the same names. @DjerohN Maybe it also solves your issue.

[DjerohN]

I have a little bit more complex structure in my tests, like: features/some_container/some_service/*.feature
If I understand you right, I can't make my whole structure unique for each feature file.
But I managed to solve this issue by specifying serenity.requirements.dir in serenity.properties file, because my features directory not in standard path src/test/resources/features

[SumantaSarathiChakraborty]

We have lots of stories in my project and I get this issue in every build.

[wakaleo]

@SumantaSarathiChakraborty Can you provide a sample project that reproduces the issue? Also, this issue has been reported when you have multiple feature files with the same names, so check that your feature file names (and feature names) are unique.

[DjerohN]

The issue reproduces again, I think it's because of significantly increased number of tests (requirements). As a temporary fix you can increase number of threads for maven (-T 8 for example), but for me this is not enough for ~1900 tests and ~400 requirements.

I'm getting errors:

[INFO] --- serenity-maven-plugin:1.9.31:aggregate (default-cli) @ api-test-maker ---
[INFO] current_project.base.dir: some_dir
[INFO] Generating test results for 1940 tests
[INFO] 403 requirements loaded after 20029 ms
[INFO] 403 related requirements found after 20029 ms
[INFO] Generating test outcome reports: false
[INFO] Starting generating reports: 55251 ms
[INFO] Configured report threads: 30
[WARNING] Report generation timed out for net.thucydides.core.reports.html.AggregateReportingTask@27b9d20d - java.util.concurrent.TimeoutException
java.util.concurrent.FutureTask.get(FutureTask.java:205)
[WARNING] Report generation timed out for net.thucydides.core.reports.html.TagTypeReportingTask@32421fcc - java.util.concurrent.TimeoutException
java.util.concurrent.FutureTask.get(FutureTask.java:205)
[WARNING] SOME REPORT PAGES COULD NOT BE GENERATED
 * Report generation timed out for net.thucydides.core.reports.html.AggregateReportingTask@27b9d20d - java.util.concurrent.TimeoutException
java.util.concurrent.FutureTask.get(FutureTask.java:205)

 * Report generation timed out for net.thucydides.core.reports.html.TagTypeReportingTask@32421fcc - java.util.concurrent.TimeoutException
java.util.concurrent.FutureTask.get(FutureTask.java:205)


[INFO] Test results for 1940 tests generated in 116092 ms
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 02:01 min (Wall Clock)
[INFO] Finished at: 2018-10-01T19:37:26+03:00
[INFO] Final Memory: 273M/1606M
[INFO] ------------------------------------------------------------------------

Unfortunately, I can't provide sample project to reproduce the issue, because of NDA stuff.

[wakaleo]

Have a look in the AggregateReportingTask to see why it might time out - happy to review any PRs

[DjerohN]

I haven't found problem, but I've found workaround: you can specify report.timeout property in seconds in serenity.properties file (e.g. report.timeout=60) and everything works fine.

[INFO] 
[INFO] --- serenity-maven-plugin:1.9.31:aggregate (default-cli) @ api-test-maker ---
[INFO] current_project.base.dir: /app/jenkins/jobs/sp-auto-tests-report/workspace
[INFO] Generating test results for 1966 tests
[INFO] 403 requirements loaded after 19302 ms
[INFO] 403 related requirements found after 19303 ms
[INFO] Generating test outcome reports: false
[INFO] Starting generating reports: 55331 ms
[INFO] Configured report threads: 30
[INFO] Test results for 1966 tests generated in 137497 ms
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 02:23 min (Wall Clock)
[INFO] Finished at: 2018-10-09T13:20:18+03:00
[INFO] Final Memory: 40M/1686M
[INFO] ------------------------------------------------------------------------

Build time slightly increased. Obviously, it needs more time for each task to aggregate report page.
@wakaleo, I have a big favor to ask you: could you please update Serenity Reference Manual, because big part of features in Serenity BDD are not described there.

[goel-p]

@wakaleo
I have verified that this is not only the problem when we will be having multiple feature files with the same names but there is some other issue.
I am getting the same issue and forcefully we have to terminate the job
[WARNING] Report generation timed out for Test Summary Report - java.util.concurrent.TimeoutException
java.util.concurrent.FutureTask.get(FutureTask.java:205)
[WARNING] Report generation timed out for net.thucydides.core.reports.html.AggregateReportingTask@3cb376a3 - java.util.concurrent.TimeoutException
java.util.concurrent.FutureTask.get(FutureTask.java:205)
[WARNING] Report generation timed out for TagReportingTask for TestTag{name='loginCeSmoke', type='tag'} - java.util.concurrent.TimeoutException
java.util.concurrent.FutureTask.get(FutureTask.java:205)

Its not resolved even after specifying report.timeout property in seconds in serenity.properties file

Please look into it

[jayzsuarez]

Problem still persists given that configuration set to report.timeout=300. I have ~300 stories running in one build and failed to perform aggregate report.

java.util.concurrent.FutureTask.get(FutureTask.java:205)

[scormaq]

Can confirm, issue is reproduced on my project. I have ~400 Cucumber features from different parallel launches, merged together to 1 target/site/serenity folder to generate single report.

On latest versions (serenity-core 2.0.91 & serenity-cucumber 1.0.30 I get mentioned timeout exception, and part of scenarios not reported.

[wakaleo]

Can you provide a sample project?

[grtangs]

Hi John,

I am also facing this issue, please let me know how can i fix this issue, i am facing this everytime maven build is executed from jenkins pipeline job, its working fine on local build. please help, as it seems blocking without much help in forums.

I have tried below properties but result is same

serenity.requirements.dir=com.trading.junit
serenity.report.timeout.in.secs=300
serenity.story.timeout.in.secs=600

Thanks

Below are logs

[main] INFO net.thucydides.core.reports.html.HtmlAggregateStoryReporter - 1144 requirements loaded after 35.5 secs
[main] INFO net.thucydides.core.reports.html.HtmlAggregateStoryReporter - 1144 related requirements found after 38.9 secs
[main] INFO net.thucydides.core.reports.html.HtmlAggregateStoryReporter - Generating test outcome reports: false
[main] INFO net.thucydides.core.reports.html.HtmlAggregateStoryReporter - Starting generating reports after 126 secs
[main] INFO net.thucydides.core.reports.NumberOfThreads - Configured report threads: 10
[main] WARNING net.thucydides.core.reports.html.HtmlAggregateStoryReporter - Report generation timed out for Test Summary Report - java.util.concurrent.TimeoutException
java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
[main] WARNING net.thucydides.core.reports.html.HtmlAggregateStoryReporter - Report generation timed out for Requirements report 4aa2483c279e7e47809991c9709a3055121b1fbf03ad5e685d4894ae78f86567.html - java.util.concurrent.TimeoutException
java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
[main] WARNING net.thucydides.core.reports.html.HtmlAggregateStoryReporter - Report generation timed out for net.thucydides.core.reports.html.RequirementsTypeReportingTask@10a2c15e - java.util.concurrent.TimeoutException
java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
[main] WARNING net.thucydides.core.reports.html.HtmlAggregateStoryReporter - Report generation timed out for Requirements report capabilities.html - java.util.concurrent.TimeoutException
java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
[main] WARNING net.thucydides.core.reports.html.HtmlAggregateStoryReporter - SOME REPORT PAGES COULD NOT BE GENERATED

• Report generation timed out for Test Summary Report - java.util.concurrent.TimeoutException
  java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)

• Report generation timed out for Requirements report 4aa2483c279e7e47809991c9709a3055121b1fbf03ad5e685d4894ae78f86567.html - java.util.concurrent.TimeoutException
  java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)

[AbhineetSharmax]

similar issue i am facing while generating reports using,

npm run test:report

getting warnings as attached.

using serenity-cli2.1.10-all.jar

Thanks,
Abhineet Sharma

[nbarrett]

On my project we've recently upgraded to Serenity 2.3.33 and with Cucumber 6 and we've seen our report aggregation times go from around 1 minute to to 21 minutes and they consistently log the timeout exception in this issue. For instance, If we use report aggregation from our old version of serenity 2.0.70 we get this output and no timeouts:

HtmlAggregateStoryReporter - Test results for 7673 tests generated in 87.5 secs

But the new version produces this output: HtmlAggregateStoryReporter - Test results for 7671 tests generated in 2,276.2 secs

With report.timeout.threaddumps=true and verbose.reporting=true I can see that some reporting tasks are taking up to 300 seconds to complete each but not failing, so I suspect that there is sub excessive directory or classpath scanning repeatedly happening in each task, causing this extended aggregation time. I'll investigate more and report back, hopefully with a PR 👍

[nbarrett]

Here's an extract of the "long-tails" of report generation, where the 1st log item is fast/normal and the remainder are very slow:

2021-04-16 12:24:53.110 +0000 INFO  [pool-2-thread-60]ReportExecutor - Report ResultReportingTask{reportName='03b8e4a1dc3670f22acce5ffc560d7e0b5fee49dbca093106cd92c0501b0a86a.html'} generated in 137 ms
2021-04-16 12:24:59.802 +0000 INFO  [pool-2-thread-31]ReportExecutor - Report ResultReportingTask{reportName='a1645c9ee6a5ada90925c8c57022dae97bd7f382f681abf96d479337726cfaf7.html'} generated in 42007 ms
2021-04-16 12:25:01.442 +0000 INFO  [pool-2-thread-42]ReportExecutor - Report ResultReportingTask{reportName='ea310ede4550f325e193c0935db0e73f383402417160d0864b3a6506d3c41ae8.html'} generated in 25496 ms
2021-04-16 12:25:01.948 +0000 INFO  [pool-2-thread-5]ReportExecutor - Report ResultReportingTask{reportName='e17ab8f01ae3ff301218b213faa1c43eaa61a472686bafeb61e85b810f975738.html'} generated in 50403 ms
2021-04-16 12:25:10.820 +0000 INFO  [pool-2-thread-46]ReportExecutor - Report ResultReportingTask{reportName='e7b8b7a9aa6c6693674bdf1c5eb36ea6c05209520714d555b7ecba7b9f2113c0.html'} generated in 53030 ms
2021-04-16 12:25:20.160 +0000 INFO  [pool-2-thread-20]ReportExecutor - Report ResultReportingTask{reportName='eb1f63cff3551c81aed6b9c382e4ec9f3b881c3c1b0aa90b5b53194d6dc44c9e.html'} generated in 62367 ms
2021-04-16 12:25:22.640 +0000 INFO  [pool-2-thread-1]ReportExecutor - Report ResultReportingTask{reportName='74e1979724d2b698c246cf339fe3750d9675b4c1f345c25f91dc8910216b23c6.html'} generated in 87604 ms
2021-04-16 12:25:22.978 +0000 INFO  [pool-2-thread-70]ReportExecutor - Report TagReportingTask for test build rule number:Fork 05 generated in 97833 ms
2021-04-16 12:25:22.989 +0000 INFO  [pool-2-thread-68]ReportExecutor - Report TagReportingTask for test build rule number:Fork 01 generated in 260879 ms
2021-04-16 12:25:28.204 +0000 INFO  [pool-2-thread-22]ReportExecutor - Report ResultReportingTask{reportName='2379aa0e9d9445db2ed6c93b2f21ce4d3a026ded3dba6dd2230b5dc9d68431e8.html'} generated in 93067 ms
2021-04-16 12:25:31.297 +0000 INFO  [pool-2-thread-8]ReportExecutor - Report TagReportingTask for test build slice:Page Test generated in 111912 ms
2021-04-16 12:26:04.973 +0000 INFO  [pool-2-thread-4]ReportExecutor - Report ResultReportingTask{reportName='61d6ab5f97ea36ff1e45da2b64b3bedcef4d124a1916454f75d09a581f381cee.html'} generated in 107180 ms
2021-04-16 12:26:05.316 +0000 INFO  [pool-2-thread-72]ReportExecutor - Report ResultReportingTask{reportName='b5e3c1c6d2683d5f73cf319f927e4d9ec6f3ce66bff73f329b982b01763be73c.html'} generated in 130179 ms
2021-04-16 12:26:21.973 +0000 INFO  [pool-2-thread-41]ReportExecutor - Report ResultReportingTask{reportName='23eabfef2761fdf6d7a725fc76bc6d110b8ee9c47799db8646396fc9abb2050b.html'} generated in 90785 ms
2021-04-16 12:26:22.094 +0000 INFO  [pool-2-thread-28]ReportExecutor - Report ResultReportingTask{reportName='bfbcca49c6ad9310e915d4b7d02a895f8f04887307c2a5484951eda848303c71.html'} generated in 90902 ms
2021-04-16 12:26:43.171 +0000 INFO  [pool-2-thread-26]ReportExecutor - Report ResultReportingTask{reportName='2d1bb463564ab0559b9f661d3a13c03d9d0bf614279ddc44089af4861b44791b.html'} generated in 168034 ms
2021-04-16 12:26:52.025 +0000 INFO  [pool-2-thread-15]ReportExecutor - Report ResultReportingTask{reportName='7aeba9d5c4603b26ad632ed7e122b171343e5ff260e6ccb67d7c96795177c7ad.html'} generated in 176989 ms
2021-04-16 12:28:55.371 +0000 INFO  [pool-2-thread-57]ReportExecutor - Report TagReportingTask for test build slice:Web Test 01 generated in 649491 ms
2021-04-16 12:29:23.792 +0000 INFO  [pool-2-thread-18]ReportExecutor - Report TagReportingTask for tag:WEB_ACC_TESTS generated in 781059 ms
2021-04-16 12:29:30.735 +0000 INFO  [pool-2-thread-44]ReportExecutor - Report TagReportingTask for tag:SetUpAndCleanUp generated in 777308 ms
2021-04-16 12:29:40.394 +0000 INFO  [pool-2-thread-77]ReportExecutor - Report TagReportingTask for tag:SetUpAndCleanUp generated in 620159 ms
2021-04-16 12:30:18.611 +0000 INFO  [pool-2-thread-58]ReportExecutor - Report TagReportingTask for tag:WEB_ACC_TESTS generated in 501996 ms
2021-04-16 12:30:40.771 +0000 INFO  [pool-2-thread-61]ReportExecutor - Report TagReportingTask for test build slice:Web Test 01 generated in 439386 ms
2021-04-16 12:31:01.866 +0000 INFO  [pool-2-thread-80]ReportExecutor - Report TagReportingTask for tag:WEB_ACC_TESTS generated in 691837 ms
2021-04-16 12:31:06.919 +0000 INFO  [pool-2-thread-47]ReportExecutor - Report TagReportingTask for tag:SetUpAndCleanUp generated in 716466 ms
2021-04-16 12:31:20.681 +0000 INFO  [pool-2-thread-12]ReportExecutor - Report TagReportingTask for tag:WEB_ACC_TESTS generated in 667407 ms
2021-04-16 12:31:23.190 +0000 INFO  [pool-2-thread-23]ReportExecutor - Report TagReportingTask for tag:SetUpAndCleanUp generated in 569824 ms
2021-04-16 12:31:58.877 +0000 INFO  [pool-2-thread-45]ReportExecutor - Report ResultReportingTask{reportName='7be0f42121a39a8107cb79123f4b9b3986af68f49e9078c65d7c306cb057265e.html'} generated in 467332 ms
2021-04-16 12:31:59.105 +0000 INFO  [pool-2-thread-55]ReportExecutor - Report ResultReportingTask{reportName='ff19d7032b5d2a02727f2e7e8d1742bb959e132072e8fe31a643169e8a9dd7b9.html'} generated in 483068 ms
2021-04-16 12:33:20.750 +0000 INFO  [pool-2-thread-24]ReportExecutor - Report TagReportingTask for test build slice:Web Test 01 generated in 962317 ms
2021-04-16 12:33:53.858 +0000 INFO  [pool-2-thread-9]ReportExecutor - Report TagReportingTask for test build slice:Web Test 01 generated in 866080 ms
2021-04-16 12:34:22.115 +0000 INFO  [pool-2-thread-49]ReportExecutor - Report ResultReportingTask{reportName='da1cdf9767b0b54adad5e540d64dc30d1d17714e5e2aeec0bea17f5a222a4502.html'} generated in 627978 ms
2021-04-16 12:43:58.407 +0000 INFO  [pool-2-thread-35]ReportExecutor - Report Test Summary Report generated in 1662630 ms
2021-04-16 12:43:58.912 +0000 INFO  [pool-2-thread-32]ReportExecutor - Report net.thucydides.core.reports.html.AggregateReportingTask@6afb09ec generated in 1663134 ms
2021-04-16 12:45:07.326 +0000 INFO  [pool-2-thread-16]ReportExecutor - Report ResultReportingTask{reportName='01f5288b80adbd3af52a8ed68a4a616d3164f750229f80da1ef344382d948835.html'} generated in 1273931 ms
Finished in 46 min 4 sec

We are thinking that there might be a slow down in the creation of environment variables on a recent version of serenity which manifests unfavourably in projects where there may be many serenity.conf files on the classpath (Our project's monorepo has over 120 modules each with its own serenity.conf). Currently proving that at the moment and will report back soon...

[madalinaptj]

Having the same issue with version 3.9.8. Was this fixed? If so, in which version of serenity-core?

[wakaleo]

Try with 4.0.21

[madalinaptj]

Thank you very much for the quick answer! Made the update and issue is fixed in 4.0.21.