vaadin
Vaadin 24.x logging Broadcaster messages repeatedly
Description of the bug
I just upgraded my Vaadin app from 23.x to 24.0.x making the necessary javax to jakarta changes and correspondingly upgrading my runtime environment to Tomcat 10.1.8.
I'm using @Push(PushMode.AUTOMATIC) and my Servlet uses the following
@Route("")
@PWA(name = "MyApp", shortName = "MyApp")
@Push(value = PushMode.AUTOMATIC)
public class Main extends AppLayout implements AppShellConfigurator {
I am getting the following WARN repeatedly logged and my UI is sluggish. is there something else I need to configure or need to change for the upgrade to Vaadin 24.x to fix this issue or is this a bug?
Atmosphere-Shared-0] WARN org.atmosphere.cpr.DefaultBroadcaster - This message Entry{message=com.vaadin.flow.server.communication.AtmospherePushConnection$PushMessage@65df019a, type=RESOURCE, future=org.atmosphere.cpr.BroadcasterFuture@4dfa5742} will be lost
[Atmosphere-Shared-0] WARN org.atmosphere.cpr.DefaultBroadcaster - Failed to submit broadcast handler runnable to for Broadcaster/*
java.lang.IllegalStateException: The request object has been recycled and is no longer associated with this facade
at org.apache.catalina.connector.RequestFacade.checkFacade(RequestFacade.java:856)
at org.apache.catalina.connector.RequestFacade.getHeader(RequestFacade.java:505)
at jakarta.servlet.http.HttpServletRequestWrapper.getHeader(HttpServletRequestWrapper.java:82)
at org.atmosphere.cpr.AtmosphereRequestImpl.getHeader(AtmosphereRequestImpl.java:351)
at org.atmosphere.cpr.AtmosphereRequestImpl.getHeader(AtmosphereRequestImpl.java:336)
at com.vaadin.flow.server.communication.LongPollingCacheFilter.filter(LongPollingCacheFilter.java:56)
at org.atmosphere.cpr.BroadcasterConfig.filter(BroadcasterConfig.java:452)
at org.atmosphere.cpr.DefaultBroadcaster.perRequestFilter(DefaultBroadcaster.java:818)
at org.atmosphere.cpr.DefaultBroadcaster.deliverPush(DefaultBroadcaster.java:691)
at org.atmosphere.cpr.DefaultBroadcaster.push(DefaultBroadcaster.java:568)
at org.atmosphere.cpr.DefaultBroadcaster$1.run(DefaultBroadcaster.java:423)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1395)
at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)
at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)
at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)
at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.
Expected behavior
This did not happen in V23 or earlier.
Minimal reproducible example
try {
this.getUI().get().access(() -> {
if (changeCode == null) {
gridMonitoredItem.getDataProvider().refreshAll();
return;
}
if (theObserved instanceof String && changeCode instanceof String) {
txtLastUpdate.setValue(changeCode.toString());
return;
}
if (changeCode instanceof List) {
for (Object object : (List) changeCode) {
gridMonitoredItem.getDataProvider().refreshItem((CActiveUser) object);
}
} else {
gridMonitoredItem.getDataProvider().refreshItem((CActiveUser) changeCode);
}
txtLastUpdate.setValue(I18n.getValue("Last Updated") + ": " + LocalDateTime.now().format(DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss")));
});
} catch (UIDetachedException e) {
CCommon.logItem("UIDetachedException::MainView", "Update: Failed. Removing Observer", e);
ThreadProcessServiceEvents.getInstance().deleteIObserver(this);
}
Versions
- Vaadin / Flow version: 24.0.3
- Java version: 17
- OS version: Linux
- Browser version (if applicable): N/A
- Application Server (if applicable): Tomcat 10.1.8
- IDE (if applicable): N/A
A patch can be applied to LongPollingCacheFilter when getting the header value.
However, Atmosphere will still fail to broadcast the message
ava.lang.IllegalStateException: The request object has been recycled and is no longer associated with this facade
at org.apache.catalina.connector.RequestFacade.checkFacade(RequestFacade.java:856) ~[tomcat-embed-core-10.1.8.jar:10.1.8]
at org.apache.catalina.connector.RequestFacade.removeAttribute(RequestFacade.java:419) ~[tomcat-embed-core-10.1.8.jar:10.1.8]
at org.apache.catalina.core.ApplicationHttpRequest.removeAttribute(ApplicationHttpRequest.java:266) ~[tomcat-embed-core-10.1.8.jar:10.1.8]
at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) ~[tomcat-embed-core-10.1.8.jar:6.0]
at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) ~[tomcat-embed-core-10.1.8.jar:6.0]
at org.atmosphere.cpr.AtmosphereRequestImpl.removeAttribute(AtmosphereRequestImpl.java:679) ~[atmosphere-runtime-3.0.3.slf4jvaadin1.jar:3.0.3.slf4jvaadin1]
at org.atmosphere.cpr.DefaultBroadcaster.executeAsyncWrite(DefaultBroadcaster.java:911) ~[atmosphere-runtime-3.0.3.slf4jvaadin1.jar:3.0.3.slf4jvaadin1]
at org.atmosphere.cpr.DefaultBroadcaster$2.run(DefaultBroadcaster.java:477) ~[atmosphere-runtime-3.0.3.slf4jvaadin1.jar:3.0.3.slf4jvaadin1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
I am facing this problem on a production server, when it will be resolved and is there any workaround i can apply
A fix for the LongPollingCacheFilter class will be released soon.
But, as mentioned above, Atmosphere may still fail with similar exceptions
I found a way to stop the excessive logging. In the simplelogger.properties file change the atmosphere setting from warn to off.
org.slf4j.simpleLogger.defaultLogLevel = info org.slf4j.simpleLogger.log.org.atmosphere = off
@madhu1830 no updates so far, but we will revisit this during next development iteration (week 36-37).
@madhu1830 what Vaadin version are you using? Can you please post the error stacktrace?
i am using Vaadin version: 24.1.1
Stack trace:
2023-09-14T06:12:44.684Z WARN 422190 --- [Atmosphere-Shared-5] org.atmosphere.cpr.DefaultBroadcaster : This message com.vaadin.flow.server.communication.AtmospherePushConnection$PushMessage@75820fab will be lost for AtmosphereResource e796706a-3aba-4e08-b5f6-47d531665daf, adding it to the BroadcasterCache 2023-09-14T06:12:44.684Z WARN 422190 --- [Atmosphere-Shared-5] org.atmosphere.cpr.DefaultBroadcaster : Failed to execute a write operation for Broadcaster /*
java.lang.IllegalStateException: The request object has been recycled and is no longer associated with this facade at org.apache.catalina.connector.RequestFacade.checkFacade(RequestFacade.java:856) at org.apache.catalina.connector.RequestFacade.removeAttribute(RequestFacade.java:419) at org.apache.catalina.core.ApplicationHttpRequest.removeAttribute(ApplicationHttpRequest.java:266) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at org.atmosphere.cpr.AtmosphereRequestImpl.removeAttribute(AtmosphereRequestImpl.java:679) at org.atmosphere.cpr.DefaultBroadcaster.executeAsyncWrite(DefaultBroadcaster.java:911) at org.atmosphere.cpr.DefaultBroadcaster$2.run(DefaultBroadcaster.java:477) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:833)
2023-09-14T06:12:44.685Z WARN 422190 --- [Atmosphere-Shared-5] org.atmosphere.cpr.DefaultBroadcaster : This message com.vaadin.flow.server.communication.AtmospherePushConnection$PushMessage@3a78f550 will be lost for AtmosphereResource e796706a-3aba-4e08-b5f6-47d531665daf, adding it to the BroadcasterCache 2023-09-14T06:12:44.685Z WARN 422190 --- [Atmosphere-Shared-5] org.atmosphere.cpr.DefaultBroadcaster : Failed to execute a write operation for Broadcaster /*
java.lang.IllegalStateException: The request object has been recycled and is no longer associated with this facade at org.apache.catalina.connector.RequestFacade.checkFacade(RequestFacade.java:856) at org.apache.catalina.connector.RequestFacade.removeAttribute(RequestFacade.java:419) at org.apache.catalina.core.ApplicationHttpRequest.removeAttribute(ApplicationHttpRequest.java:266) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at jakarta.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:246) at org.atmosphere.cpr.AtmosphereRequestImpl.removeAttribute(AtmosphereRequestImpl.java:679) at org.atmosphere.cpr.DefaultBroadcaster.executeAsyncWrite(DefaultBroadcaster.java:911) at org.atmosphere.cpr.DefaultBroadcaster$2.run(DefaultBroadcaster.java:477) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:833)
The initial issue has been resolved, by not accessing the request header in LongPollingCacheFilter.
For the other case reported, I cannot reproduce the problem locally.
@madhu1830, @awillerding, @hawaii883, @alexanoid, would someone of you be able to create and share a working example project that we could use to reproduce the issue?
Closed because of no responses within 2 weeks. Please comment or create a new issue with reproducible example if this is still valid for you.
Still valid for my case. Using Vaadin 24.5.5, spring boot 3.4.0, tomcat 10.1.33, java 21, long-polling transport mode. Now and then, this error appears in the logs.
The last provided stack trace is slightly different from the one in the ticket description.
It seems the issue is happening in two different places after HTTP session is invalidated:
Vaadin closes and removes the UIs and the associated push connections, calling AtmospherePushConnection.disconnect() that tries to close the AtmosphereResource, but Tomcat already recycled the instance.
Because of the failure, the UI push connection is not nullified, and a push operation is probably performed again when VaadinSession is unlocked, causing the second exception.
I think there is no way for flow to recover from Tomcat recycling request objects, so the potential fix is just to catch the IllegalStateException when closing AtmosphereResource; to be noted that Flow already catches and ignores potential IOExceptions.
try {
resource.close();
} catch (IOException e) {
getLogger().info("Error when closing push connection", e);
}
@TatuLund Thanks for the link.
Probably I did not get correctly the comment, but I wouldn't have Vaadin to tweak Tomcat internals to disable the "discard facade" functionality. However, end-users can apply the mentioned tomcat configuration on their own if they think it is a suitable solution for them (even it seems to be discouraged)
Since the atmosphere resource will anyway be unavailable, I think we can safely ignore the exception and log it, perhaps at debug level.
These warnings can be seen also with other Vaadin versions. I actually just was using Vaadin 8, when I ran the application in Docker cluster using Nginx proxy and Tomcat 9, these warnings are rather frequent. When I added "-Dorg.apache.catalina.connector.RECYCLE_FACADES=false" in my JAVA_OPTS, the warnings are gone. So this is not a Vaadin bug, but a Tomcat configuration issue.
I have heard of two customer which had similar issue like this with V24.8+ for them only thing that really helped was setting @Push(transport = Transport.LONG_POLLING).
In many places it is not recommended to set RECYCLE_FACADES false since it is not as secure as the current default (Tomcat9+) of true
