Infinite timeout when using convenience functions like restrict, restrictOr, etc.
Closed this issue · 6 comments
I have a Play Framework Java app that has been growing in users and now I am starting to see some errors that I am having trouble resolving. I am using SmartMeter.io (uses jMeter) to load test and what I find is that these errors occur when I increase my users (simulated users during load testing) from 10 to 50.
The errors all seem to point to where and when I use Deadbolt's template convenience functions, such as restrict, restrictOr, subjectPresentOr, pattern, among others. When I remove these view function helpers or when I only run with 1-10 users, I no longer see the issues, however, once I have 25+ simultaneous users, I start to get these Java errors reported below. The errors hang my app and I need to reboot, which is undesirable. What I am seeing seems to be an infinite loop that makes the server unresponsive.
My test scenario that reports these issues is simple: login, access my home page which makes MySQL calls to get data, then log out. If all I do is remove all these Deadlbolt functions from my view, I no longer get these issues. I have tried increasing my deadbolt.java settings, but nothing seems to help.
Can anyone offer any suggestions on how to troubleshoot this? What other information can I provide to help support my situation? Thank you for any help.
I am using:
Play Framework 2.5
Deadbolt Jave 2.5.0
Deadbolt Core 2.4.3
Play Authenticate 0.8.3
Jooq 3.7.3
MySQL 5.7.19
I have not upgraded to the latest Play 2.6 because I am waiting on Play Authenticate to update.
# ------- Deadbolt -------
deadbolt {
java {
handler=security.MyDeadboltHandler,
cache-user=true,
view-timeout=10000, # Default 1000
blocking-timeout=10000 # Default 1000
}
}
Below are some sample errors at different timeout settings (10s in this case).
[error] b.o.d.j.ViewSupport - Timeout when attempting to complete future within [10000]ms. Denying access to resource.
java.util.concurrent.TimeoutException: null
at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
at be.objectify.deadbolt.java.ViewSupport.viewRestrict(ViewSupport.java:104)
at be.objectify.deadbolt.java.views.html.restrict_Scope0$restrict_Scope1$restrict.apply(restrict.template.scala:41)
at views.html.main_Scope0$main_Scope1$main.apply(main.template.scala:97)
at views.html.player.list.players_Scope0$players_Scope1$players.apply(players.template.scala:43)
at views.html.player.list.players_Scope0$players_Scope1$players.render(players.template.scala:60)
at views.html.player.list.players.render(players.template.scala)
at controllers.player.ListController.list(ListController.java:86)
at router.Routes$$anonfun$routes$1$$anonfun$applyOrElse$29$$anonfun$apply$29.apply(Routes.scala:1800)
[error] b.o.d.j.ViewSupport - Timeout when attempting to complete future within [10000]ms. Denying access to resource.
java.util.concurrent.TimeoutException: null
at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
at be.objectify.deadbolt.java.ViewSupport.viewRestrict(ViewSupport.java:104)
at be.objectify.deadbolt.java.views.html.restrict_Scope0$restrict_Scope1$restrict.apply(restrict.template.scala:41)
at views.html.main_Scope0$main_Scope1$main.apply(main.template.scala:97)
at views.html.player.list.players_Scope0$players_Scope1$players.apply(players.template.scala:43)
at views.html.player.list.players_Scope0$players_Scope1$players.render(players.template.scala:60)
at views.html.player.list.players.render(players.template.scala)
at controllers.player.ListController.list(ListController.java:86)
at router.Routes$$anonfun$routes$1$$anonfun$applyOrElse$29$$anonfun$apply$29.apply(Routes.scala:1800)
[error] b.o.d.j.ViewSupport - Timeout when attempting to complete future within [10000]ms. Denying access to resource.
java.util.concurrent.TimeoutException: null
at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
at be.objectify.deadbolt.java.ViewSupport.viewRestrict(ViewSupport.java:104)
at be.objectify.deadbolt.java.views.html.restrict_Scope0$restrict_Scope1$restrict.apply(restrict.template.scala:41)
at views.html.player.list.players_Scope0$players_Scope1$players$$anonfun$apply$2.apply(players.template.scala:548)
at views.html.player.list.players_Scope0$players_Scope1$players$$anonfun$apply$2.apply(players.template.scala:542)
at views.html.helper.form_Scope0$form.apply(form.template.scala:35)
at views.html.player.list.players_Scope0$players_Scope1$players.apply(players.template.scala:542)
at views.html.player.list.players_Scope0$players_Scope1$players.render(players.template.scala:616)
at views.html.player.list.players.render(players.template.scala)
[error] b.o.d.j.ViewSupport - Timeout when attempting to complete future within [10000]ms. Denying access to resource.
java.util.concurrent.TimeoutException: null
at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
at be.objectify.deadbolt.java.ViewSupport.viewPattern(ViewSupport.java:231)
at be.objectify.deadbolt.java.views.html.pattern_Scope0$pattern_Scope1$pattern.apply(pattern.template.scala:40)
at views.html.player.list._table_Scope0$_table_Scope1$_table$$anonfun$apply$9$$anonfun$apply$22$$anonfun$apply$23.apply(_table.template.scala:534)
at views.html.player.list._table_Scope0$_table_Scope1$_table$$anonfun$apply$9$$anonfun$apply$22$$anonfun$apply$23.apply(_table.template.scala:530)
at play.twirl.api.TemplateMagic$.defining(TemplateMagic.scala:13)
at views.html.player.list._table_Scope0$_table_Scope1$_table$$anonfun$apply$9$$anonfun$apply$22.apply(_table.template.scala:530)
at views.html.player.list._table_Scope0$_table_Scope1$_table$$anonfun$apply$9$$anonfun$apply$22.apply(_table.template.scala:529)
at play.twirl.api.TemplateMagic$.defining(TemplateMagic.scala:13)
----- Update One Day Later -----
I took a different approach and tried to determine what information each Deadbolt convenience function was trying to access for restrict, subjectNotPresent, and pattern, as these were the three I was using liberally in my one view. This one view consisted of a main.scala.html, plus three more views. I may have had 20-30 usages of restrict, restricOr, pattern, and subject. I then created a view model object that I pass down into my view from my controller. I am able to run with 50 concurrent users without any timeout issues.
Perhaps this is better use of data retrieval in general and perhaps I was abusing Deadbolt by using it too much. I would think each time a restrict or pattern is executed, it takes some time to run, and each instance runs that same amount of time, and when you have more concurrent users, timeouts happen? With my view model approach, I access the information I need and each request to it gets the already calculated data.
@restrict(roles = anyOf(allOf("admin"))) { } now becomes @if(globalViewModel.isAdmin) { }.
Just because this is working for me, doesn't mean it is a better approach. Any suggestions are welcome. Thank you.
I think the problem is caused by concurrent renders * number of Deadbolt template restrictions. Because all underlying code is executed asynchronously (hence the view-timeout value), you suddenly have a lot of contention. I think it's worthwhile creating a version of the templates that only execute synchronously in the same thread; I'll get on this as soon as I have some free time, for both Deadbolt 2.5 and 2.6.
Incidentally, you don't need Deadbolt Core; that was discontinued after 2.4, when all common code between the Java and Scala versions was removed.
If you switch to v2.5.6, released today, you should find this issue solved.
Great, let us know if the error occurs again.
I also encountered this problem.
the error:
Timeout when attempting to complete future within [1000]ms. Denying access to resource.I use 2.6.4