vaadin
Unexpected message id from the client with Vaadin 24.7.3
Description of the bug
Since upgrading from Vaadin 24.5.3 to 24.7.3 I receive a UnsupportedOperationException: Unexpected message id from the client during the execution of automated tests using Vaadin's Testbench.
The tests are running in parallel using a dynamic Selenium Grid that spawns new Firefox / Chrome containers for each individual test execution.
Similar bug reports have been made in the past (such as https://github.com/vaadin/flow/issues/12640) and according to https://github.com/vaadin/flow/issues/12640#issuecomment-2850005150 it should have been fixed in Vaadin 24.7+. For me it looks like the new logic introduced a new bug since my tests broke after updating the Vaadin version.
Expected behavior
The push mechanism should work without throwing exceptions
Minimal reproducible example
This seems to happen every time I execute the tests since upgrading to Vaadin 24.7.3 but my application is too big and complex to upload a reproducible example. In the logs I can see the following:
2025-05-22 11:45:04,434 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-18) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-05-22 11:45:04,605 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-18) Unexpected message id from the client. Expected client id: 16, got 15. Message start: { type: event node: 71.0 feature: null }
2025-05-22 11:45:04,607 ERROR [com.motives.pulsepro.ui.infrastructure.UncaughtExceptionHandler] (default task-18) error: Caught <class java.lang.UnsupportedOperationException>:
Exception-Msg: <Unexpected message id from the client. Expected client id: 16, got 15. more details logged on DEBUG level.>
Add. Info: <Uncaught exception!>
java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected client id: 16, got 15. more details logged on DEBUG level.
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:365)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:138)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.SynchronizedRequestHandler.handleRequest(SynchronizedRequestHandler.java:63)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.VaadinService.handleRequest(VaadinService.java:1664)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.VaadinServlet.service(VaadinServlet.java:398)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.cdi.CdiVaadinServlet.service(CdiVaadinServlet.java:66)
at [email protected]//jakarta.servlet.http.HttpServlet.service(HttpServlet.java:614)
at [email protected]//io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at [email protected]//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at [email protected]//io.undertow.websockets.jsr.JsrWebSocketFilter.doFilter(JsrWebSocketFilter.java:172)
at [email protected]//io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
at [email protected]//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at [email protected]//io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at [email protected]//io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at [email protected]//io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at [email protected]//io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at [email protected]//org.wildfly.elytron.web.undertow.server.ElytronRunAsHandler.lambda$handleRequest$1(ElytronRunAsHandler.java:68)
at [email protected]//org.wildfly.security.auth.server.FlexibleIdentityAssociation.runAsFunctionEx(FlexibleIdentityAssociation.java:103)
at [email protected]//org.wildfly.security.auth.server.Scoped.runAsFunctionEx(Scoped.java:161)
at [email protected]//org.wildfly.security.auth.server.Scoped.runAs(Scoped.java:73)
at [email protected]//org.wildfly.elytron.web.undertow.server.ElytronRunAsHandler.handleRequest(ElytronRunAsHandler.java:67)
at [email protected]//io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
at [email protected]//io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:117)
at [email protected]//io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at [email protected]//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at [email protected]//io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at [email protected]//io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at [email protected]//io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at org.wildfly.security.elytron-web.undertow-server-servlet@4.1.0.Final//org.wildfly.elytron.web.undertow.server.servlet.CleanUpHandler.handleRequest(CleanUpHandler.java:38)
at [email protected]//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at [email protected]//org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:44)
at [email protected]//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at [email protected]//org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:51)
at [email protected]//io.undertow.servlet.handlers.SendErrorPageHandler.handleRequest(SendErrorPageHandler.java:52)
at [email protected]//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at [email protected]//io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:276)
at [email protected]//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
at [email protected]//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:132)
at [email protected]//io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at [email protected]//io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at [email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
at [email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
at [email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
at [email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
at [email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
at [email protected]//io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:256)
at [email protected]//io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:101)
at [email protected]//io.undertow.server.Connectors.executeRootHandler(Connectors.java:393)
at [email protected]//io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:859)
at [email protected]//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at [email protected]//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
at [email protected]//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
at [email protected]//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
at [email protected]//org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282)
at java.base/java.lang.Thread.run(Thread.java:1583)
Versions
- Vaadin / Flow version: 24.7.3
- Java version: 21
- OS version: Windows 11
- Browser version (if applicable): Chrome 134.0.6998.35, Firefox 136.0
- Application Server (if applicable): Wildfly 32
- IDE (if applicable):
After updating to Vaadin 24.7.4 the bug still occurs.
I've also noticed that running the tests in sequence instead of fully parallelized seems to reduce the likelihood of triggering this bug.
Can you please share some additional details?
Which transport are you using with PUSH?
Do you call push() manually or are you simply executing background updates from a UI.access() block?
Is there anything between the browser and the application server?
If guess every single test is running on a dedicated window/tab, so in a new UI instance.
I've configured the push mechanism by adding the annotation @Push on a class that inherits from AppShellConfigurator without specifying anything explicitly, so it should use the default values(PushMode.AUTOMATIC and Transport.WEBSOCKET_XHR)
Yes, every single test is running in a new browser tab (in a new docker container).
The errors occurs after a button in the UI is clicked. When that button is clicked, a new component instance is instantiated and attached in the UI. This component creation is supposed to happen lazily by adding a slim dummy component to the UI that only holds a loading overlay. When the slim dummy component is attached, it will then load the "heavy" component using the AsyncManager and after creating the actual content the loading overlay will be replaced. The code looks like this:
addAttachListener { event ->
AsyncManager.register(this) { task ->
task.push {
// trigger "heavy" instance creation (in UI context)
instance
}
// replace displayed content once the instance has been created
task.push {
remove(overlayLayout)
add(instance ?: run {
logger.error { "LazyView instance creation failed" }
Span(getTranslation("ErrorDialog.ApplicationUnavailable.Message"))
})
}
}
event.unregisterListener()
}
Now after looking into this, I've noticed that sometimes the "heavy" component instance seems to be created via an unexpected call stack:
2025-05-22 13:41:47,725 WARN [com.motives.pulsepro.ui.tabs.LazyView] (default task-15) instance_delegate$lambda$5: The lazy instance creation wasn't triggered via the AsyncManager. Please check the caller structure: java.base/java.lang.Thread.getStackTrace(Thread.java:2450)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.motives.pulsepro.ui.tabs.LazyView.instance_delegate$lambda$5(LazyView.kt:65)
deployment.SynapticaOS.ear//kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:74)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.motives.pulsepro.ui.tabs.LazyView.getInstance(LazyView.kt:61)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.motives.pulsepro.ui.tabs.PulseProApplicationTabs.navigateAsync$lambda$7(PulseProApplicationTabs.kt:88)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.motives.pulsepro.ui.tabs.PulseProApplicationTabs.navigateAsync(PulseProApplicationTabs.kt:114)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.motives.pulsepro.ui.tabs.PulseProApplicationTabs.navigateAsync(PulseProApplicationTabs.kt:87)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.motives.pulsepro.ui.tilebuttonview.ModulesView.updateFilter$lambda$1$lambda$0(ModulesView.kt:46)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.component.ComponentEventBus.fireEventForListener(ComponentEventBus.java:239)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.component.ComponentEventBus.handleDomEvent(ComponentEventBus.java:488)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.component.ComponentEventBus.lambda$addDomTrigger$dd1b7957$1(ComponentEventBus.java:298)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.internal.nodefeature.ElementListenerMap.lambda$fireEvent$2(ElementListenerMap.java:475)
java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.internal.nodefeature.ElementListenerMap.fireEvent(ElementListenerMap.java:475)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.communication.rpc.EventRpcHandler.handleNode(EventRpcHandler.java:62)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.communication.rpc.AbstractRpcInvocationHandler.handle(AbstractRpcInvocationHandler.java:79)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.communication.ServerRpcHandler.handleInvocationData(ServerRpcHandler.java:568)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.communication.ServerRpcHandler.lambda$handleInvocations$6(ServerRpcHandler.java:549)
java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.communication.ServerRpcHandler.handleInvocations(ServerRpcHandler.java:549)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:376)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:138)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.SynchronizedRequestHandler.handleRequest(SynchronizedRequestHandler.java:63)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.VaadinService.handleRequest(VaadinService.java:1664)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.server.VaadinServlet.service(VaadinServlet.java:398)
deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.cdi.CdiVaadinServlet.service(CdiVaadinServlet.java:66)
[email protected]//jakarta.servlet.http.HttpServlet.service(HttpServlet.java:614)
[email protected]//io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
[email protected]//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
[email protected]//io.undertow.websockets.jsr.JsrWebSocketFilter.doFilter(JsrWebSocketFilter.java:172)
[email protected]//io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
[email protected]//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
[email protected]//io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
[email protected]//io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
[email protected]//io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
[email protected]//io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
[email protected]//org.wildfly.elytron.web.undertow.server.ElytronRunAsHandler.lambda$handleRequest$1(ElytronRunAsHandler.java:68)
[email protected]//org.wildfly.security.auth.server.FlexibleIdentityAssociation.runAsFunctionEx(FlexibleIdentityAssociation.java:103)
[email protected]//org.wildfly.security.auth.server.Scoped.runAsFunctionEx(Scoped.java:161)
[email protected]//org.wildfly.security.auth.server.Scoped.runAs(Scoped.java:73)
[email protected]//org.wildfly.elytron.web.undertow.server.ElytronRunAsHandler.handleRequest(ElytronRunAsHandler.java:67)
[email protected]//io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
[email protected]//io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:117)
[email protected]//io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
[email protected]//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[email protected]//io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
[email protected]//io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
[email protected]//io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
org.wildfly.security.elytron-web.undertow-server-servlet@4.1.0.Final//org.wildfly.elytron.web.undertow.server.servlet.CleanUpHandler.handleRequest(CleanUpHandler.java:38)
[email protected]//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[email protected]//org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:44)
[email protected]//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[email protected]//org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:51)
[email protected]//io.undertow.servlet.handlers.SendErrorPageHandler.handleRequest(SendErrorPageHandler.java:52)
[email protected]//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[email protected]//io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:276)
[email protected]//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
[email protected]//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:132)
[email protected]//io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
[email protected]//io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
[email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
[email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
[email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
[email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
[email protected]//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1421)
[email protected]//io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:256)
[email protected]//io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:101)
[email protected]//io.undertow.server.Connectors.executeRootHandler(Connectors.java:393)
[email protected]//io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:859)
[email protected]//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
[email protected]//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
[email protected]//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
[email protected]//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
[email protected]//org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282)
java.base/java.lang.Thread.run(Thread.java:1583)
I'll look into this a bit more and try to find out if this lazy loading behavior is affected by the updated Vaadin version or if this is just a coincidence.
I've further analyzed the lazy loading behavior. There was a small bug in our code that triggered the eager instance creation. I've fixed that.
The Unexpected message id from the client error still occurs, so it doesn't seem to be linked to the previously faulty lazy instance creation.
Edit: To answer your other question: The application server (Wildfly 32) is running on my laptop while browser instances are spawned dynamically by Selenium Grid on a VM that is hosted on a server in our office. My laptop is connected via Wi-Fi to the VM's network.
Forgive the question, but just to confirm, your code is never calling UIInternals.incrementServerId(), right?
What's strange here is that it seems the same message is sent from the client to the server three times.
- Client sent message 15 sent, server replied
- Client sent message 15 again, most likely because it did not receive the previous response. The server returned the pre-processed response for 15
- Client sent message 15 again, but this time with a different payload. The server throws the exception.
2025-05-22 11:45:04,434 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-18) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-05-22 11:45:04,605 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-18) Unexpected message id from the client. Expected client id: 16, got 15. Message start: { type: event node: 71.0 feature: null }
The weird thing, as @caalador pointed out, is that 2) and 3) happen at almost the same time, with a difference of less than 200 milliseconds.
It would be great to have also the browser console logs to check what is happening on the client side.
We made a small change on the Flow client that should prevent potential updates on a queued message. It should be available soon as SNAPHOT release if you mind giving it a try.
I don't mind testing it with a prerelease version, but I'm not sure if I can get the console logs. The only reliable way to trigger this bug was to run the tests in the fully automated test setup using a dynamic Selenium Grid. That means the browser instances are short-lived and exist only in a temporary docker container, that is automatically deleted once the test finishes.
But if the bug isn't fixed with the new version I'll do my best to get the console logs. Maybe I can increase the test timeout so the container is kept alive until I can retrieve the logs.
What are you using for E2E tests?
Selenium, for example, should allow you to access browser logs using the driver.manage().logs() tool, so you can dump them after a test run.
BTW, the Flow 24.7 snapshots have been released. To test it, you should add the Vaadin pre-releases repository (https://maven.vaadin.com/vaadin-prereleases) to your build and make sure you use com.vaadin:flow-bom:24.7-SNAPSHOT to manage Flow dependencies.
In addition, you should enable frontendHotdeploy flag to make sure the updated Flow client gets used (e.g. <frontendHotdeploy> in maven plugin config).
We are using the Vaadin Testbench with Selenium for E2E tests. I didn't know about the driver.manage().logs() API, so thanks for the pointer!
The frontendHotdeploy doesn't work with our setup where we deploy the UI as a WAR packaged inside an EAR to WildFly. We can only use production builds.
Wouldn't it be enough to run the clean-frontend goal of the Vaadin Maven plugin to force using the latest imported versions after updating the vaadin-bom?
Wouldn't it be enough to run the clean-frontend goal of the Vaadin Maven plugin to force using the latest imported versions after updating the vaadin-bom?
Yes, forcing a production bundle should be enough (<forceProductionBuild>true</forceProductionBuild> in maven config).
Unfortunately, with production builds, there will be fewer logs on the client side.
I've executed the tests a few times by now. I do not receive the Unexpected message id from the client exception anymore, but some warnings remain. Here is an excerpt from the log file:
2025-05-28 10:13:20,369 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-13) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-05-28 10:13:20,664 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-13) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-05-28 10:13:21,016 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-13) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-05-28 10:13:21,491 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-13) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-05-28 10:13:22,114 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-13) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-05-28 10:13:22,431 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-13) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-05-28 10:13:24,252 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-13) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-05-28 10:13:25,393 WARN [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-13) Resynchronizing UI by client's request. A network message was lost before reaching the client and the client is reloading the full UI state. This typically happens because of a bad network connection with packet loss or because of some part of the network infrastructure (load balancer, proxy) terminating a push (websocket or long-polling) connection. If you are using push with a proxy, make sure the push timeout is set to be smaller than the proxy connection timeout
2025-05-28 10:13:25,689 WARN [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-16) Resynchronizing UI by client's request. A network message was lost before reaching the client and the client is reloading the full UI state. This typically happens because of a bad network connection with packet loss or because of some part of the network infrastructure (load balancer, proxy) terminating a push (websocket or long-polling) connection. If you are using push with a proxy, make sure the push timeout is set to be smaller than the proxy connection timeout
2025-05-28 10:13:26,037 WARN [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-7) Resynchronizing UI by client's request. A network message was lost before reaching the client and the client is reloading the full UI state. This typically happens because of a bad network connection with packet loss or because of some part of the network infrastructure (load balancer, proxy) terminating a push (websocket or long-polling) connection. If you are using push with a proxy, make sure the push timeout is set to be smaller than the proxy connection timeout
2025-05-28 10:13:26,524 WARN [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-6) Resynchronizing UI by client's request. A network message was lost before reaching the client and the client is reloading the full UI state. This typically happens because of a bad network connection with packet loss or because of some part of the network infrastructure (load balancer, proxy) terminating a push (websocket or long-polling) connection. If you are using push with a proxy, make sure the push timeout is set to be smaller than the proxy connection timeout
2025-05-28 10:13:27,130 WARN [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-3) Resynchronizing UI by client's request. A network message was lost before reaching the client and the client is reloading the full UI state. This typically happens because of a bad network connection with packet loss or because of some part of the network infrastructure (load balancer, proxy) terminating a push (websocket or long-polling) connection. If you are using push with a proxy, make sure the push timeout is set to be smaller than the proxy connection timeout
2025-05-28 10:13:27,445 WARN [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-18) Resynchronizing UI by client's request. A network message was lost before reaching the client and the client is reloading the full UI state. This typically happens because of a bad network connection with packet loss or because of some part of the network infrastructure (load balancer, proxy) terminating a push (websocket or long-polling) connection. If you are using push with a proxy, make sure the push timeout is set to be smaller than the proxy connection timeout
2025-05-28 10:13:29,273 WARN [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-22) Resynchronizing UI by client's request. A network message was lost before reaching the client and the client is reloading the full UI state. This typically happens because of a bad network connection with packet loss or because of some part of the network infrastructure (load balancer, proxy) terminating a push (websocket or long-polling) connection. If you are using push with a proxy, make sure the push timeout is set to be smaller than the proxy connection timeout
2025-05-28 10:16:13,013 INFO [com.motives.pulsepro.ui.test.infrastructure.junit.ScreenshotOnFailureIfBrowserVisibleExtension] (default task-26) printBrowserLogs: Log entries for browser:
[2025-05-28T08:12:29.198Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=b97b11380a28da0f1cd219c52007e54228b8b53e27c2fb54b0488a99911b6347 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
[2025-05-28T08:14:04.277Z] [SEVERE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:43395 Uncaught Error: Client is resynchronizing
[2025-05-28T08:14:04.278Z] [SEVERE] javascript 2:90 Uncaught TypeError: Cannot set properties of null (setting 'frozen')
[2025-05-28T08:14:04.278Z] [SEVERE] javascript 2:90 Uncaught TypeError: Cannot set properties of null (setting 'frozen')
[2025-05-28T08:14:45.693Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=b97b11380a28da0f1cd219c52007e54228b8b53e27c2fb54b0488a99911b6347 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
2025-05-28 10:16:13,133 INFO [com.motives.pulsepro.ui.test.infrastructure.junit.ScreenshotOnFailureIfBrowserVisibleExtension] (default task-26) printBrowserLogs: Log entries for browser:
[2025-05-28T08:12:29.183Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=b97b11380a28da0f1cd219c52007e54228b8b53e27c2fb54b0488a99911b6347 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
[2025-05-28T08:13:56.173Z] [SEVERE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:43395 Uncaught Error: Client is resynchronizing
[2025-05-28T08:13:56.175Z] [SEVERE] javascript 2:90 Uncaught TypeError: Cannot set properties of null (setting 'frozen')
[2025-05-28T08:13:56.175Z] [SEVERE] javascript 2:90 Uncaught TypeError: Cannot set properties of null (setting 'frozen')
[2025-05-28T08:14:46.759Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=b97b11380a28da0f1cd219c52007e54228b8b53e27c2fb54b0488a99911b6347 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
2025-05-28 10:16:15,140 INFO [com.motives.pulsepro.ui.test.infrastructure.junit.ScreenshotOnFailureIfBrowserVisibleExtension] (default task-26) printBrowserLogs: Log entries for browser:
[2025-05-28T08:12:29.200Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=b97b11380a28da0f1cd219c52007e54228b8b53e27c2fb54b0488a99911b6347 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
[2025-05-28T08:13:55.274Z] [SEVERE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:43395 Uncaught Error: Client is resynchronizing
[2025-05-28T08:13:55.274Z] [SEVERE] javascript 2:90 Uncaught TypeError: Cannot set properties of null (setting 'frozen')
[2025-05-28T08:13:55.275Z] [SEVERE] javascript 2:90 Uncaught TypeError: Cannot set properties of null (setting 'frozen')
[2025-05-28T08:14:46.274Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=b97b11380a28da0f1cd219c52007e54228b8b53e27c2fb54b0488a99911b6347 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
2025-05-28 10:16:16,391 INFO [com.motives.pulsepro.ui.test.infrastructure.junit.ScreenshotOnFailureIfBrowserVisibleExtension] (default task-13) printBrowserLogs: Log entries for browser:
[2025-05-28T08:12:29.047Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=b97b11380a28da0f1cd219c52007e54228b8b53e27c2fb54b0488a99911b6347 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
[2025-05-28T08:13:58.583Z] [SEVERE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:43395 Uncaught Error: Client is resynchronizing
[2025-05-28T08:13:58.583Z] [SEVERE] javascript 2:90 Uncaught TypeError: Cannot set properties of null (setting 'frozen')
[2025-05-28T08:13:58.584Z] [SEVERE] javascript 2:90 Uncaught TypeError: Cannot set properties of null (setting 'frozen')
[2025-05-28T08:14:49.538Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=b97b11380a28da0f1cd219c52007e54228b8b53e27c2fb54b0488a99911b6347 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
I'm not sure if this is related (or relevant at all) but during the test execution some of the tests fail due to this error (when running the tests in parallel, no matter what Vaadin version - 24.7.3 or 24.7-snapshot):
java.lang.IllegalArgumentException: The column with key 'MaterialLocator.Column.Manufacturer.text' is not owned by this Grid
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.component.grid.Grid.ensureOwner(Grid.java:3578)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.component.grid.GridColumnOrderHelper.setColumnOrder(GridColumnOrderHelper.java:74)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.component.grid.Grid.setColumnOrder(Grid.java:5107)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.motives.pulsepro.ui.framework.userinterfaces.component.table.AbstractFilteredSortedGrid.applyColumnConfig(AbstractFilteredSortedGrid.kt:797)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.motives.pulsepro.ui.framework.userinterfaces.component.table.AbstractFilteredSortedGrid.onAttach(AbstractFilteredSortedGrid.kt:726)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.component.ComponentUtil.onComponentAttach(ComponentUtil.java:290)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.component.ComponentUtil.onComponentAttach(ComponentUtil.java:280)
at deployment.SynapticaOS.ear.SynapticaOSUI.war//com.vaadin.flow.internal.nodefeature.ComponentMapping.lambda$onAttach$0(ComponentMapping.java:104)
If you require further information, logs from test runs with a different Vaadin version or anything else, don't hesitate to ask.
Also: Do you think https://github.com/vaadin/flow/issues/21102 could be related and possibly be fixed by https://github.com/vaadin/flow/pull/21545?
About the old duplicate message there's definitely something wrong here, because it seems that the client never processes response to message 15, so it continues to send it to the server. And after a couple of attempts, it gives up and asks for a full resynchronization.
The question is why it behaves like that: is the message lost before reaching the client? Is the client failing to process it but it does not handle the failure correctly?
Hard to say without more information about what happens on the client side.
EDIT: I notice some logs in your previous comment, but they did not track everything happening on the client side, most likely becuase the app is running in production mode.
About the Grid issue, it could be something in your code that causes a Column to be shared between different Grid instances; for example, using static variables.
Or it could be something in the component. Again, hard to say without seeing the code.
But if you manage to create a small reproducer, please create a ticket on the flow-components repository.
And I don't think that #21545 can fix #21102. It seems a different issue.
About the
old duplicate messagethere's definitely something wrong here, because it seems that the client never processes response to message 15, so it continues to send it to the server. And after a couple of attempts, it gives up and asks for a full resynchronization. The question is why it behaves like that: is the message lost before reaching the client? Is the client failing to process it but it does not handle the failure correctly? Hard to say without more information about what happens on the client side.EDIT: I notice some logs in your previous comment, but they did not track everything happening on the client side, most likely becuase the app is running in production mode.
As I've mentioned, we are forced to use production builds by our infrastructure, so if the client logging is omitted there, I can't do much.
However, I can easily provide server logs. During the previous test runs I had the com.vaadin.flow.server.communication logger level set to debug. This is the full output of that logger:
If logs from other packages would be helpful I could activate those loggers and rerun the tests. Other than that, I'm not sure how I can further assist the investigation of this bug.
Unfortunately, server logs are not enough for investigation.
Would you be able to add the following VaadinServiceInitListener to your application, just for testing?
The class must be registered in META-INF/services/com.vaadin.flow.server.VaadinServiceInitListener.
This should enable console logs even if the application is built for production.
public class EnableClientDebug implements VaadinServiceInitListener {
@Override
public void serviceInit(ServiceInitEvent event) {
event.addRequestHandler(new JavaScriptBootstrapHandler() {
@Override
protected JsonObject getInitialJson(VaadinRequest request, VaadinResponse response, VaadinSession session) {
JsonObject json = super.getInitialJson(request, response, session);
json.getObject("appConfig").put("debug", true);
return json;
}
});
}
}
After adding the snippet above, I can see the following entries in the log file:
[2025-06-02T06:13:37.611Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8192 "Gave up waiting for message 19 from the server"
[2025-06-02T06:13:37.611Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 2:44209 "Resynchronizing from server"
[2025-06-02T06:14:05.097Z] [SEVERE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8273 "Assertion error: undefined"
[2025-06-02T06:14:05.345Z] [SEVERE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:43395 Uncaught Error: Client is resynchronizing
More details can be found here: browserDebug.log
Does this help?
Unfortunately, the browser console info messages are not displayed.
You should enable ALL level for browser log type. I don't remember right now how to do it with Testbench, but it should be something like
LoggingPreferences loggingPrefs = new LoggingPreferences();
loggingPrefs.enable(LogType.BROWSER, Level.ALL);
chromeOptions.setCapability(ChromeOptions.LOGGING_PREFS, loggingPrefs);
As an alternative, you can try to set -Dwebdriver.chrome.verboseLogging=true -Dwebdriver.chrome.logfile=/tmp/chrome-test.log to dump all messages to a file, but it could produce a huge log file.
Thank you for bearing with me.
Here are the complete browser logs: browser.log
And the ServerRpcHandler logs: ServerRpcHandler.log
Thanks, the latest logs are indeed useful for the investigation. I couldn't still find the source of this issue but here are my findings.
It looks like to me that there is a recurrent pattern that sometimes ends in the resynchronization:
a vaadin-tabs selection changed listener seems to schedule an async task executed (syncId=8) before the current sync request completes (syncId=9), but it pushes the changes after the sync request. In most of the cases message 9 handling is postponed until 8 is reached and everything works fine.
[2025-06-02T11:26:31.043Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Sending xhr message to server: {\"csrfToken\":\"79c1b105-127c-4919-b0d4-f96c15ddcefc\",\"rpc\":[{\"type\": \"event\",\"node\":71,\"event\":\"selected-changed\",\"data\":{}}],\"syncId\":6,\"clientId\":6}"
...
[2025-06-02T11:26:31.151Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Received xhr message: for(;;);[{\"clientId\":7,\"syncId\":9}]"
[2025-06-02T11:26:31.151Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Received message with server id 9 but expected 8. Postponing handling until the missing message(s) have been received"
...
[2025-06-02T11:26:31.171Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Received push (websocket) message: for(;;);[{\"clientId\":6,\"meta\":{\"async\":true},\"LAZY\":[{\"url\": ..... or)})}catch(error){$4(''+error)}\"]],\"syncId\":8}]"
However, sometimes it seems that the selected-changed request is pending for a long time and the websocket client is disconnected and reconnected. In this situation, there's an additional message generated on the server that never reaches the client.
- vaadin-tabs selected-changed event
[2025-06-02T11:26:39.081Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Sending xhr message to server: {\"csrfToken\":\"79c1b105-127c-4919-b0d4-f96c15ddcefc\",\"rpc\":[{\"type\": \"event\",\"node\":71,\"event\":\"selected-changed\",\"data\":{}}],\"syncId\":18,\"clientId\":15}" - client postpones other requests
[2025-06-02T11:26:39.100Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Postpone sending invocations to server because of active request" - after 1 minute a message is received by the websocket client (heartbeat ping? body is not visible)
[2025-06-02T11:27:38.382Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:27:38 GMT+0000 (Coordinated Universal Time) Atmosphere: websocket.onmessage" - after another 12 seconds, the websocket connection is closed
[2025-06-02T11:27:52.494Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:27:52 GMT+0000 (Coordinated Universal Time) Atmosphere: websocket.onclose" [2025-06-02T11:27:52.494Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false" [2025-06-02T11:27:52.495Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:27:52 GMT+0000 (Coordinated Universal Time) Atmosphere: Firing onClose (closed case)" [2025-06-02T11:27:52.496Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 2:69879 "Push connection closed" - Flow attempts a reconnect websocket
[2025-06-02T11:27:52.498Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:39750 "Reopening push connection" [2025-06-02T11:27:52.498Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:27:52 GMT+0000 (Coordinated Universal Time) Atmosphere: Firing onReconnect" [2025-06-02T11:27:57.502Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Invoking executeWebSocket, using URL: ws://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/push?v-r=push&v-uiId=0&v-pushId=628a776d-2057-4e08-957b-5a097956bfdb&X-Atmosphere-tracking-id=48b073e5-951f-4446-b318-6058fd7a2c3a&X-Atmosphere-Framework=4.0.1&X-Atmosphere-Transport=websocket&X-Atmosphere-TrackMessageSize=true&Content-Type=application/json; charset=UTF-8&X-atmo-protocol=true&X-Vaadin-LastSeenServerSyncId=18" [2025-06-02T11:27:57.524Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:27:57 GMT+0000 (Coordinated Universal Time) Atmosphere: websocket.onopen" [2025-06-02T11:27:57.524Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Websocket successfully opened" - Reconnection happens after 47 seconds
[2025-06-02T11:28:44.866Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:28:44 GMT+0000 (Coordinated Universal Time) Atmosphere: websocket.onmessage" [2025-06-02T11:28:44.867Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:28:44 GMT+0000 (Coordinated Universal Time) Atmosphere: Firing onReopen" [2025-06-02T11:28:44.867Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Push connection re-established using websocket" [2025-06-02T11:28:44.867Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:28:44 GMT+0000 (Coordinated Universal Time) Atmosphere: Firing onReopen" - A response for XHR requests arrives, but with a syncId of 21 instead of 19. During the two minutes
incrementServerId()has been invoked 3 times.[2025-06-02T11:28:44.897Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Received xhr message: for(;;);[{\"clientId\":16,\"syncId\":21}]" [2025-06-02T11:28:44.898Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Received message with server id 21 but expected 19. Postponing handling until the missing message(s) have been received" - After websocket reconnection message 20 is received, but 19 is still missing. This seems to be the response to the the
selected-changedevent[2025-06-02T11:28:44.936Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 0:8245 "Received push (websocket) message: for(;;);[{\"clientId\":15,\"meta\":{\"async\":true},\"LAZY\":[{\"url\": \"return window.Vaadin.Flow.loadOnDemand('d8cb4a1a12d5f7ee7f53d634e0f3853b38b758af4c5d925905fa00895018c557');\",\"type\":\"DYNAMIC_IMPORT\",\"mode\":\"LAZY\"},{\"url\":\"return window.Vaadin.Flow. ..... [[0,1213],1652,\"return $0.$connector.generateItems($1)\"],[[0,1213],\"return (async function() { this.$connector.generateItems()}).apply($0)\"],[[0,1199],\"return $0.recalculateColumnWidths()\"],[[0,1199],\"return $0.recalculateColumnWidths()\"]],\"syncId\":20}]"
Can you please describe what the Tabs selection change listener does and possibly show the code? Is there perhaps a UI.push() call in a UI.access(...) block executed in a background thread?
To further investigate, we need to understand what happens on the server side when the message disappears.
Could you please set the following log levels on the server (the log will be verbose)? They should tell us all messages that are supposed to be pushed to the server and all the code paths that cause an increment of the syncId.
- com.vaadin.flow.component.internal.UIInternals=TRACE
- org.atmosphere.cache=TRACE
- org.atmosphere.cpr.DefaultBroadcaster=TRACE
Thank you for your in-depth analysis. I'll try to explain what happens in the application.
We use the Tabs component to manage multiple concurrent "views" to allow the user to quickly switch between different content. When the user navigates to a view that hasn't been initialized yet, we create a dummy view ("LazyView") that only contains a loading screen.
Once the dummy view is attached, we trigger the creation of the actual view instance using the AsyncManager. Once the view instance is created, we remove the loading screen from the dummy view and add the actual content as a child to the lazy view.
Here is the relevant code snippet from the LazyView:
val instance: T? by lazy {
try {
logger.debug { "Creating instance..." }
val result = supplier.get() // supplier is a SerializableSupplier<T>, where T extends Component
isInitialized = true
logger.debug { "Created instance of ${result.javaClass.simpleName}" }
result
} catch (e: Exception) {
logger.log(e, "Failed to create instance")
null
}
}
init {
[...]
add(overlayLayout)
addAttachListener { event ->
AsyncManager.register(this) { task ->
task.push {
// trigger instance creation (in UI context so we can load localized texts etc)
instance
}
// replace displayed content once the instance has been created
task.push {
remove(overlayLayout)
add(instance ?: run {
logger.error { "LazyView instance creation failed" }
Span(getTranslation("ErrorDialog.ApplicationUnavailable.Message"))
})
}
}
event.unregisterListener()
}
}
The supplier is a lambda expression that calls CDI.current().select(clazz).get(), where clazz is the class of the view the user wants to navigate to.
The duration how long it takes to create the actual view instance varies greatly. Some views are very simple and can be instantiated within milliseconds
2025-06-02 13:26:30,838 DEBUG [com.motives.pulsepro.ui.tabs.LazyView] (pool-18-thread-2) [S-1359733450-UI0] instance_delegate$lambda$5: Creating instance...
2025-06-02 13:26:30,842 DEBUG [com.motives.pulsepro.ui.tabs.LazyView] (pool-18-thread-2) [S-1359733450-UI0] instance_delegate$lambda$5: Created instance of ModulesView
2025-06-02 13:26:34,897 DEBUG [com.motives.pulsepro.ui.tabs.LazyView] (pool-18-thread-4) [S-1359733450-UI0] instance_delegate$lambda$5: Creating instance...
2025-06-02 13:26:34,922 DEBUG [com.motives.pulsepro.ui.tabs.LazyView] (pool-18-thread-4) [S-1359733450-UI0] instance_delegate$lambda$5: Created instance of ApplicationsView
Other views, such as our MaterialLocatorView, require some data from the database where we stored user-specific display preferences. This can take a while due to a blocking access when creating related entities for freshly created users (which is the case when running the integration tests on an empty database).
2025-06-02 13:26:38,999 DEBUG [com.motives.pulsepro.ui.tabs.LazyView] (pool-18-thread-6) [S-1359733450-UI0] instance_delegate$lambda$5: Creating instance...
2025-06-02 13:28:31,754 DEBUG [com.motives.pulsepro.ui.tabs.LazyView] (pool-18-thread-6) [S-1359733450-UI0] instance_delegate$lambda$5: Created instance of MaterialLocatorView
After accounting for the local time zone (UTC+2), it's clear that the reconnect happens during the creation of the MaterialLocatorView:
[2025-06-02T11:27:52.494Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:27:52 GMT+0000 (Coordinated Universal Time) Atmosphere: websocket.onclose"
[2025-06-02T11:27:52.494Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
[2025-06-02T11:27:52.495Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=3e083fc6628fe1bd66195502bb8865263a55d4116bc26e3383aa08d4b17e77b8 0:42451 "Mon Jun 02 2025 11:27:52 GMT+0000 (Coordinated Universal Time) Atmosphere: Firing onClose (closed case)"
[2025-06-02T11:27:52.496Z] [FINE] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/build/FlowClient-DyMGXbet.js 2:69879 "Push connection closed"
So it looks like the slow instance creation triggers a reconnect...? The server should be executing this code while the reconnect happens:
task.push {
instance
}
This is the relevant code in the AsyncManager:
public void push(Command command) {
if (getUI() == null) {
return;
}
boolean mustPush = missedPolls.get() == PUSH_ACTIVE && getUI().getPushConfiguration().getPushMode() == PushMode.MANUAL;
getUI().accessSynchronously(() -> {
try {
command.execute();
if (mustPush) {
getUI().push();
}
} catch (UIDetachedException ignore) {
// Do not report
// How could this even happen?
} catch (Exception e) {
// Dump
getAsyncManager().handleException(this, e);
}
});
}
Since we're using automatic push mode, it should be somewhat equivalent to this (when replacing lambdas with their content multiple times):
getUI().accessSynchronously(() -> { CDI.current().select(MaterialLocatorView.class).get(); })
As mentioned above, during the creation of the MaterialLocatorView instance we load some settings from the database and create components (mostly Grids, TextFields and Buttons).
Do you need additional details what exactly happens in the constructor of the MaterialLocatorView?
I've added the requested loggers and ran the tests multiple times. Unfortunately, the behavior seems to be influenced by adding those loggers. In browser_limited.log (without the additional logging) I can see multiple log entries like
2025-06-03 09:49:59,442 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-20) Received old duplicate message from the client. Expected: 16, got: 15. Resending previous response.
2025-06-03 09:50:01,966 WARN [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-20) Resynchronizing UI by client's request. A network message was lost before reaching the client and the client is reloading the full UI state. This typically happens because of a bad network connection with packet loss or because of some part of the network infrastructure (load balancer, proxy) terminating a push (websocket or long-polling) connection. If you are using push with a proxy, make sure the push timeout is set to be smaller than the proxy connection timeout
In browser_verbose.log (with the additional loggers), there's only a single entry that points to a potential problem:
2025-06-03 09:40:45,927 DEBUG [com.vaadin.flow.server.communication.ServerRpcHandler] (default task-19) Received old duplicate message from the client. Expected: 34, got: 33. Resending previous response.
I've experimented a bit more with the loggers. com.vaadin.flow.component.internal.UIInternals is the one that unintentionally prevents the problem from occurring. It's probably also the one that you would be the most interested in...
Nevertheless, here is a log file with the atmosphere loggers: browser_atmosphere.log
Do you need additional details what exactly happens in the constructor of the
MaterialLocatorView?
Yes, it would be nice to see what happens there and if there could be something that triggers an "unexpected" push.
One potential issue I see here is that the creation of MaterialLocatorView, that from the above logs seems to take about 1.5~2 minutes, happens with a VaadinSession lock acquired. I wonder if the heavy part (loading data?) could be separated by the component creation, reducing the lock time significantly.
I also notice that the websocket disconnection happens after 30 seconds from the last message received
Time) Atmosphere: websocket.onmessage"
[2025-06-03T08:16:19.123Z] [FINE] http://10.10.1.2:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=48ee941ff7b7f1aa6e5846889a785b4d72078ea1eab01c95419f2f4b41222c31 0:42451 "Tue Jun 03 2025 08:16:19 GMT+0000 (Coordinated Universal Time) Atmosphere: websocket.onmessage"
[2025-06-03T08:16:49.481Z] [FINE] http://10.10.1.2:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=48ee941ff7b7f1aa6e5846889a785b4d72078ea1eab01c95419f2f4b41222c31 0:42451 "Tue Jun 03 2025 08:16:49 GMT+0000 (Coordinated Universal Time) Atmosphere: websocket.onclose"
[2025-06-03T08:16:49.482Z] [WARNING] http://10.10.1.2:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=48ee941ff7b7f1aa6e5846889a785b4d72078ea1eab01c95419f2f4b41222c31 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
This makes me wonder if the websockets IDLE timeout (30 seconds?) is less than the default Atmophere heartbeat interval (60 seconds), causing the disconnection.
By default, Vaadin sets the Atmosphere WEBSOCKET_IDLETIME paramter to 5 minutes, but I wonder if the container is maybe overwriting this value? Or did you have by any chance customized the setting?
I did a quick test on our CDI starter project using wildfly 35, and I can see that the websocket client is disconnected about every 30 seconds if there is no activity.
Since Wildfly 28, the default read timeout has been set to 90 seconds (https://issues.redhat.com/browse/WFLY-14980) and this seems to cause a org.xnio.channels.ReadTimeoutException: UT000199: Read timed out after 90031 milliseconds. caught by the JSR356Endpoint. As a consequence, the websocket session is closed.
Setting org.atmosphere.interceptor.HeartbeatInterceptor.clientHeartbeatFrequencyInSeconds=60 (init parameter) activate the client heartbeat and prevents the websocket from being closed.
But I did not investigate how this client-to-server communication can impact, for example, the session expiration.
This is our web.xml:
<session-config>
<!--in minutes-->
<session-timeout>30</session-timeout>
<!--Session timeout occurs when the browser window is closed and no Vaadin UI instances exist anymore.
The Vaadin session will be destroyed after the configured timeout-->
</session-config>
<context-param>
<!--Heartbeats keep the UI alive if no user interaction happens. This is needed for dashboard views.
UIs without heartbeat are eventually removed (loss of connection)-->
<param-name>heartbeatInterval</param-name>
<!--in seconds-->
<param-value>600</param-value>
</context-param>
<context-param>
<param-name>closeIdleSessions</param-name>
<param-value>false</param-value>
</context-param>
We do not specify any other values than that.
I have to go through a few thousand lines of code to provide a detailed description of everything that happens during the creation of the MaterialLocatorView, but I'll try to find the time to do that within the next few days.
Can you try to set org.atmosphere.interceptor.HeartbeatInterceptor.clientHeartbeatFrequencyInSeconds=60 as context param to see if it prevents the websocket disconnection?
Using org.atmosphere.interceptor.HeartbeatInterceptor.clientHeartbeatFrequencyInSeconds=60 seems to make things worse: The websocket still gets disconnected (from browser.log):
[2025-06-05T09:08:31.740Z] [WARNING] http://[IP (removed by FKamp)]:8080/SynapticaOS/VAADIN/static/push/vaadinPush-min.js?v=93c1c8f45461bbc836f7ce40f37cc8e6eaf1a2db100cdec1515ac2fb1cb4a7ed 0:42451 "Websocket closed, reason: Connection was closed abnormally (that is, with no close frame being sent). - wasClean: false"
And additionally the remote test runner's connection seems to get forcefully closed:
[ERROR] com.motives.pulsepro.ui.browser.MlPerLocationTabBrowserIT.verify material lots are moved to storage unit in batch within LocationSearch tab()[2] -- Time elapsed: 286.7 s <<< ERROR!
jakarta.ejb.EJBException: IO channel timed out or closed. Check server endpoint read or write timeout settings
at org.jboss.ejb.protocol.remote.EJBClientChannel$MethodInvocation.handleClosed(EJBClientChannel.java:1288)
at org.jboss.remoting3.util.InvocationTracker.connectionClosed(InvocationTracker.java:222)
at org.jboss.remoting3.util.InvocationTracker.lambda$new$0(InvocationTracker.java:70)
at org.jboss.remoting3.spi.SpiUtils.safeHandleClose(SpiUtils.java:50)
at org.jboss.remoting3.spi.AbstractHandleableCloseable$CloseHandlerTask.run(AbstractHandleableCloseable.java:520)
at org.jboss.remoting3.spi.AbstractHandleableCloseable.runCloseTask(AbstractHandleableCloseable.java:425)
at org.jboss.remoting3.spi.AbstractHandleableCloseable.closeComplete(AbstractHandleableCloseable.java:286)
at org.jboss.remoting3.remote.RemoteConnectionChannel.closeAction(RemoteConnectionChannel.java:510)
at org.jboss.remoting3.spi.AbstractHandleableCloseable.closeAsync(AbstractHandleableCloseable.java:368)
at org.jboss.remoting3.remote.RemoteConnectionHandler.closeAllChannels(RemoteConnectionHandler.java:623)
at org.jboss.remoting3.remote.RemoteConnectionHandler.receiveCloseRequest(RemoteConnectionHandler.java:226)
at org.jboss.remoting3.remote.RemoteConnectionHandler.handleConnectionClose(RemoteConnectionHandler.java:123)
at org.jboss.remoting3.remote.RemoteReadListener.lambda$null$0(RemoteReadListener.java:67)
at org.jboss.remoting3.EndpointImpl$TrackingExecutor.lambda$execute$0(EndpointImpl.java:993)
at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282)
at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: java.nio.channels.ClosedChannelException