Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unexpected message id from the client (sync ids different) #12640

Open
thomaskiesl opened this issue Dec 27, 2021 · 53 comments
Open

Unexpected message id from the client (sync ids different) #12640

thomaskiesl opened this issue Dec 27, 2021 · 53 comments

Comments

@thomaskiesl
Copy link

thomaskiesl commented Dec 27, 2021

Description of the bug

I receive sometimes the same error message on my production system. But I do not have any idea when this happen:

2021-12-27 07:27:43,174 INFO | https-jsse-nio-18443-exec-10 | com.vaadin.flow.server.communication.ServerRpcHandler | Ignoring old duplicate message from the client. Expected: 1748, got: 1747

2021-12-27 07:28:01,354  WARN | https-jsse-nio-18443-exec-5 | de.app.ApplicationVaadinServiceInitListener         | Unexpected error
java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 1751, got 1752. more details logged on DEBUG level.
        at com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:310)
        at com.vaadin.flow.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:115)
        at com.vaadin.flow.server.SynchronizedRequestHandler.handleRequest(SynchronizedRequestHandler.java:40)
        at com.vaadin.flow.server.VaadinService.handleRequest(VaadinService.java:1565)
        at com.vaadin.flow.server.VaadinServlet.service(VaadinServlet.java:302)
        at com.vaadin.flow.spring.SpringServlet.service(SpringServlet.java:109)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
        at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:122)
        at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:116)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
        at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126)
        at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
        at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:109)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
        at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)

It seems it is the same bug as #9778

Minimal reproducible example

Unfortunately I'm not possible to reproduce the issue. I only find the messages in the logfile.

Versions

  • Vaadin / Flow version: 21.0.9
  • Java version: 17.0.1
  • OS version: CentOS
@thomaskiesl
Copy link
Author

Currently I find this issue ~10-20 per day in my logfile. Unfortunately I have no idea where this is coming from. The problem is that everytime a error message is shown to the user...

@thomaskiesl
Copy link
Author

thomaskiesl commented Jan 2, 2022

I activated the debug logging, and got the following (unfortunately no special information):

2022-01-02 20:25:10,673 DEBUG | https-jsse-nio-18443-exec-9 | com.vaadin.flow.server.communication.ServerRpcHandler | Unexpected message id from the client. Expected sync id: 2, got 1. Message start:

2022-01-02 20:25:10,685  WARN | https-jsse-nio-18443-exec-9 | de.app.AppVaadinServiceInitListener         | Unexpected error
java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 2, got 1. more details logged on DEBUG level.
        at com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:310)
        at com.vaadin.flow.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:115)
        at com.vaadin.flow.server.SynchronizedRequestHandler.handleRequest(SynchronizedRequestHandler.java:40)
        at com.vaadin.flow.server.VaadinService.handleRequest(VaadinService.java:1565)
        at com.vaadin.flow.server.VaadinServlet.service(VaadinServlet.java:302)
        at com.vaadin.flow.spring.SpringServlet.service(SpringServlet.java:109)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
        at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:122)
        at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:116)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
        at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126)
        at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
        at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:109)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
        at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
        at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)

@thomaskiesl
Copy link
Author

thomaskiesl commented Jan 2, 2022

Additional info: Once today I got the following message:

2022-01-02 20:25:09,626 INFO | https-jsse-nio-18443-exec-7 | com.vaadin.flow.server.communication.ServerRpcHandler | Ignoring old duplicate message from the client. Expected: 1, got: 0

and some milliseconds after "Unexpected message id from the client. Expected sync id: 2, got 1. more details logged on DEBUG level." the following:

2022-01-02 20:25:11,225 WARN | https-jsse-nio-18443-exec-7 | com.vaadin.flow.server.communication.ServerRpcHandler | Resynchronizing UI by client's request. Under normal operations this should not happen and may indicate a bug in Vaadin platform. If you see this message regularly please open a bug report at https://github.com/vaadin/flow/issues

@caalador
Copy link
Contributor

caalador commented Jan 4, 2022

Without only this information it would feel like one server message to the client is lost as the server should for each response send a syncId that it expects the client to have in the next request. In short:

The server generates a strictly increasing id for each response to each
request from the client. This ID is then replayed back to the server on
each request. This helps the server in knowing in what state the client
is, and compare it to its own state. In short, it helps with concurrent
changes between the client and server.

Without any way to reproduce this is really hard to investigate. @Legioth would you have any ideas on how @thomaskiesl could try to investigate the issue on their end?

@thomaskiesl
Copy link
Author

Does anyone have an idea how to find this out? I got this message every day multiple times? Additional logging?

@Legioth
Copy link
Member

Legioth commented Jan 26, 2022

There's supposed to be some additional information about the message payload after Message start: in the thing that is logged on the debug level. Looking at that data might reveal some pattern in the messages that cause the problem. Looking at the code, there is also a possibility that nothing is actually logged - this would happen in the theoretical case with an empty array in the message.

There are a couple of possible causes for why old sequence numbers would show up unexpectedly. Finding out the cause is usually very difficult without a good way of reproducing.

  • The browser might for some reason retry sending the message in case it didn't receive a response.
  • An HTTP proxy or similar in between might do the same.
  • There's a possibility that these aren't actually sequence mismatches, but instead somehow mixing up sessions or UI instances. It would on the other hand be expected to also see mismatches in the other direction then, i.e. messages where the received sequence number is greater than the expected number.

@thomaskiesl
Copy link
Author

@Legioth I recevie for example the following info within the debug file:

 Unexpected message id from the client. Expected sync id: 34, got 35. Message start: { type: event node: 1.0 feature: null }
 Unexpected message id from the client. Expected sync id: 34, got 35. more details logged on DEBUG level.

@giorgiac98
Copy link

I'm experiencing this issue too, same vaadin version
[com.vaadin.flow.server.DefaultErrorHandler] (default task-359) : java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 5, got 2. Message start: {"csrfToken":"ac311843-2839-4ffe-878c-256d7f69ae7a",rpc":[],"syncId":3,"clientId":2,"resynchronize":true}

@sergiupienar
Copy link

sergiupienar commented Apr 22, 2022

Also getting this on Vaadin 14.7.0. Upon getting this it leads to an internal error page on the UI.

Uncaught UI exception: java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 41, got 39. Message start: {"csrfToken":"7f83ca3d-e864-4362-9dda-a8af3e641780","rpc":[],"syncId":52,"clientId":39,"resynchronize":true}
	at com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:310)
	at com.vaadin.flow.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:92)

I was able to replicate it by setting up a Chrome network throttling profile with a Download of 100 kbits/s, Upload of 50 kbits/s and a latency of 500.

Then I quickly clicked on a paged table's paginator so that it would change pages and data being fetched and from time to time clicked on a row on the table. After a minute or so the UI went blank while the server log showed

[com.business.ui.MainLayout] (default task-74) Uncaught UI exception: java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 135, got 126. Message start: {"csrfToken":"e92cd975-d064-4551-9277-59b21ca057c1","rpc":[{"type":"publishedEventHandler","node":844,"templateEventMethodName":"deselect","templateEventMethodArgs":["215"],"promise":188},{"type":"publishedEventHandler","node":844,"templateEventMethodName":"setDetailsVisible","templateEventMethodArgs":[null],"promise":189},{"type":"event","node":844,"event":"item-click","data":{"event.detail.screenY":511,"event.detail.metaKey":false,"event.detail.button":0,"event.detail.shiftKey":false,"event.detail.screenX":1024,"event.detail.itemKey":"215","event.detail.internalColumnId":"col6","event.detail.altKey":false,"event.detail.clientX":1024,"event.detail.detail":1,"event.detail.clientY":408,"event.detail.ctrlKey":false}},{"type":"publishedEventHandler","node":844,"templateEventMethodName":"select","templateEventMethodArgs":["216"],"promise":190},{"type":"publishedEventHandler","node":844,"templateEventMethodName":"setDetailsVisible","templateEventMethodArgs":["216"],"promise":191},{"type":"e
	at com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:310)

Before that I also see some

2022-04-22 06:08:41,376 WARN  [com.vaadin.flow.server.communication.rpc.AbstractRpcInvocationHandler] (default task-74) Got an RPC for non-existent node: 844

messages in the logs.

Issue seems to be related to #9778

@funfried
Copy link

I'm using Vaadin 24.2.3 with Java 21, SpringBoot 3.2 and Spring Framework 6.1 (on macOS Ventura 13.5) and still see this issue:

java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 13, got 14. more details logged on DEBUG level.
	at com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:313)
	at com.vaadin.flow.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:114)
	at com.vaadin.flow.server.SynchronizedRequestHandler.handleRequest(SynchronizedRequestHandler.java:40)
	at com.vaadin.flow.server.VaadinService.handleRequest(VaadinService.java:1522)
	at com.vaadin.flow.server.VaadinServlet.service(VaadinServlet.java:398)
	at com.vaadin.flow.spring.SpringServlet.service(SpringServlet.java:106)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
	at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:642)
	at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:408)
	at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:313)
	at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:277)
	at org.springframework.web.servlet.mvc.ServletForwardingController.handleRequestInternal(ServletForwardingController.java:141)
	at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:178)
	at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:51)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1089)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:979)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:590)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
	at org.springframework.web.multipart.support.MultipartFilter.doFilterInternal(MultipartFilter.java:125)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
	at org.springframework.security.web.ObservationFilterChainDecorator$FilterObservation$SimpleFilterObservation.lambda$wrap$1(ObservationFilterChainDecorator.java:479)
	at org.springframework.security.web.ObservationFilterChainDecorator.lambda$wrapUnsecured$1(ObservationFilterChainDecorator.java:90)
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:219)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:191)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:352)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:268)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
	at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:109)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:340)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:391)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:896)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1744)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
	at java.base\/java.lang.VirtualThread.run(VirtualThread.java:311)

Any news on this?

Cheers,
Fabian

@uweschaefer
Copy link

Same problem here on JDK17, vaadin 24.1.11, SB3.1 - fairly trivial application. 20% of e2e-Tests fail randomly with something similar to

023-11-29T20:59:15.336Z ERROR 3414 --- [o-auto-1-exec-2] c.v.flow.server.DefaultErrorHandler      : 

java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 2, got 3. more details logged on DEBUG level.
	at com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:313) ~[flow-server-24.1.13.jar:24.1.13]
	at com.vaadin.flow.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:114) ~[flow-server-24.1.13.jar:24.1.13]
	at com.vaadin.flow.server.SynchronizedRequestHandler.handleRequest(SynchronizedRequestHandler.java:40) ~[flow-server-24.1.13.jar:24.1.13]
	at com.vaadin.flow.server.VaadinService.handleRequest(VaadinService.java:1529) ~[flow-server-24.1.13.jar:24.1.13]
	at com.vaadin.flow.server.VaadinServlet.service(VaadinServlet.java:398) ~[flow-server-24.1.13.jar:24.1.13]
	at com.vaadin.flow.spring.SpringServlet.service(SpringServlet.java:106) ~[vaadin-spring-24.1.13.jar:na]
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) ~[tomcat-embed-core-10.1.15.jar:6.0]

@manpreetsoftodia
Copy link

Same issue for me on vaadin version= 24.2.6 and springboot=3.0.6

2023-12-14T05:46:52.970Z ERROR 117 --- [http-nio-80-exec-9] c.v.flow.server.DefaultErrorHandler      :
java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 2, got 3. more details logged on DEBUG level.at com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:313) ~[flow-server-24.2.5.jar!/:24.2.5]at com.vaadin.flow.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:114) ~[flow-server-24.2.5.jar!/:24.2.5]at com.vaadin.flow.server.SynchronizedRequestHandler.handleRequest(SynchronizedRequestHandler.java:40) ~[flow-server-24.2.5.jar!/:24.2.5]at com.vaadin.flow.server.VaadinService.handleRequest(VaadinService.java:1522) ~[flow-server-24.2.5.jar!/:24.2.5]at com.vaadin.flow.server.VaadinServlet.service(VaadinServlet.java:398) ~[flow-server-24.2.5.jar!/:24.2.5]at com.vaadin.flow.spring.SpringServlet.service(SpringServlet.java:106) ~[vaadin-spring-24.2.5.jar!/:na]at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) ~[tomcat-embed-core-10.1.8.jar!/:na]at 

@leandropnto
Copy link

Same issue for me.
Vaadin=24.3.3
Spring boot=3.2.2
java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 1, got 2. more details logged on DEBUG level.

@ssindelar
Copy link

We have the same issue. It randomly occurs after logging in when opening the first UI after Login.
Vaadin: 24.3.5
Spring boot: 3.2.2

11:38:53.233 DEBUG [http-nio-8090-exec-6] c.v.f.server.communication.ServerRpcHandler:311    - Unexpected message id from the client. Expected sync id: 2, got 3. Message start: 
11:38:53.233 ERROR [http-nio-8090-exec-6] com.vaadin.flow.server.DefaultErrorHandler:105     - 
java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 2, got 3. more details logged on DEBUG level.

Interestingly the Message Start output ist empty. When debugging I see that the rpcArray is empty which causes the debug output to be empty.
The "changeMessage" is:

{"csrfToken":"40cf2444-6f3f-42a2-bc41-b7df9aa4d1bf","rpc":[],"syncId":2,"clientId":3,"UNLOAD":true}

It just happens on one application and I can't find the difference that causes it.

@SebastianDietrich
Copy link

We have the same issue.

Java: 17
Vaadin: 24.2.9
Spring boot: 3.2.0
Running on google cloud

java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 2, got 3. more details logged on DEBUG level.
at com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc ( com/vaadin.flow.server.communication/ServerRpcHandler.java:313 )

@difficult2connect
Copy link

Same Issue here, makes the Web basically unusable...
Java: 17
Vaadin: 24.3.7
Spring boot: 3.2.3
Azure Spring Apps

@thomaskiesl
Copy link
Author

Any updates on this? Many of my users are not happy with this situation!?

@mshabarov mshabarov moved this from 🔖 Normal Priority (P2) to 🔖 High Priority (P1) in Vaadin Flow bugs & maintenance (Vaadin 10+) Mar 27, 2024
@jorgheymans
Copy link

Thanks, we can rule out most of these items for our situation given that it's rather sporadic.

Naive thought: if server is at id 30 and client sends id 32, can it not be implemented so that the server in response can ask for a resend of 31? Slippery slope I know.

@Legioth
Copy link
Member

Legioth commented Oct 17, 2024

Naive thought: if server is at id 30 and client sends id 32, can it not be implemented so that the server in response can ask for a resend of 31? Slippery slope I know.

That's basically what we suspect we would have to end up doing with two additions:

  • should be used in both directions
  • old messages should also be discarded when no longer needed to avoid accumulating memory

@TatuLund
Copy link
Contributor

old messages should also be discarded when no longer needed to avoid accumulating memory

To be precise, the buffer would not fully eliminate the need for resync occasionally, but would reduce likelihood of the occurrence. I would assume it would reduce with great amount as what I have seen, in most typical cases it would be enough to retain just the previous one in the memory. Naturally, the size of buffer could be configurable.

@Legioth
Copy link
Member

Legioth commented Oct 18, 2024

No need to configure anything. The buffer can just contain everything that hasn't yet been "confirmed" through receiving another message from the other side with an incremented id. Maybe there should also be some upper bound to catch weird cases where more messages are produced without anyone handling but I still don't see why it would need to be configurable.

@vaithu
Copy link

vaithu commented Oct 22, 2024

After migrating from V24.3 to V24.5 I'm getting this error more frequently
java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 16, got 17. more details logged on DEBUG level.

It never occurred when I was in V24,3. Since it is more frequent but not always, I do not know what is causing this issue after the upgrade

@vaithu
Copy link

vaithu commented Oct 22, 2024

The complete error stakc is

java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 16, got 17. more details logged on DEBUG level. at com.vaadin.flow.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:317) at com.vaadin.flow.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:117) at com.vaadin.flow.server.SynchronizedRequestHandler.handleRequest(SynchronizedRequestHandler.java:40) at com.vaadin.flow.server.VaadinService.handleRequest(VaadinService.java:1647) at com.vaadin.flow.server.VaadinServlet.service(VaadinServlet.java:398) at com.vaadin.flow.spring.SpringServlet.service(SpringServlet.java:106) at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:642) at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:408) at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:313) at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:277) at org.springframework.web.servlet.mvc.ServletForwardingController.handleRequestInternal(ServletForwardingController.java:141) at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:178) at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:51) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1081) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:974) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1011) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914) at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:590) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885) at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:340) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:391) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:896) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1744) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.base/java.lang.Thread.run(Thread.java:833)

@jduan-highnote
Copy link

I'm trying to upgrade from 24.3.7 to 24.5.1 and this problem breaks the login page. I see something like reconnect to the server at the top of the UI (the actual text is hard to see). 24.3.7 doesn't have this problem at all.

caalador pushed a commit that referenced this issue Nov 12, 2024
…avigation (#19983)

Attempts to fix the synchronization issue related to the usage of the Login reported in #12640.
The Login component sends the UIDL request for the login event to the server and concurrently submits the form.
If processing the form submission performs a session ID change and a request redirect, the UIDL requests might fail with a session expiration response. The Flow client then can cancel the first redirect because it reloads the page due to the session expiration. Lastly, the beacon request hits again a valid session, but a resynchronization is triggered because the previous UIDL request was rejected.

This change delays a bit the session expiration handling on Flow client, to allow a potential redirect to complete without being cancelled. However, the client application is immediately set in TERMINATED state.
vaadin-bot pushed a commit that referenced this issue Nov 12, 2024
…avigation (#19983)

Attempts to fix the synchronization issue related to the usage of the Login reported in #12640.
The Login component sends the UIDL request for the login event to the server and concurrently submits the form.
If processing the form submission performs a session ID change and a request redirect, the UIDL requests might fail with a session expiration response. The Flow client then can cancel the first redirect because it reloads the page due to the session expiration. Lastly, the beacon request hits again a valid session, but a resynchronization is triggered because the previous UIDL request was rejected.

This change delays a bit the session expiration handling on Flow client, to allow a potential redirect to complete without being cancelled. However, the client application is immediately set in TERMINATED state.
vaadin-bot pushed a commit that referenced this issue Nov 12, 2024
…avigation (#19983)

Attempts to fix the synchronization issue related to the usage of the Login reported in #12640.
The Login component sends the UIDL request for the login event to the server and concurrently submits the form.
If processing the form submission performs a session ID change and a request redirect, the UIDL requests might fail with a session expiration response. The Flow client then can cancel the first redirect because it reloads the page due to the session expiration. Lastly, the beacon request hits again a valid session, but a resynchronization is triggered because the previous UIDL request was rejected.

This change delays a bit the session expiration handling on Flow client, to allow a potential redirect to complete without being cancelled. However, the client application is immediately set in TERMINATED state.
vaadin-bot added a commit that referenced this issue Nov 12, 2024
…avigation (#19983) (#20449)

Attempts to fix the synchronization issue related to the usage of the Login reported in #12640.
The Login component sends the UIDL request for the login event to the server and concurrently submits the form.
If processing the form submission performs a session ID change and a request redirect, the UIDL requests might fail with a session expiration response. The Flow client then can cancel the first redirect because it reloads the page due to the session expiration. Lastly, the beacon request hits again a valid session, but a resynchronization is triggered because the previous UIDL request was rejected.

This change delays a bit the session expiration handling on Flow client, to allow a potential redirect to complete without being cancelled. However, the client application is immediately set in TERMINATED state.

Co-authored-by: Marco Collovati <[email protected]>
vaadin-bot added a commit that referenced this issue Nov 12, 2024
…avigation (#19983) (#20448)

Attempts to fix the synchronization issue related to the usage of the Login reported in #12640.
The Login component sends the UIDL request for the login event to the server and concurrently submits the form.
If processing the form submission performs a session ID change and a request redirect, the UIDL requests might fail with a session expiration response. The Flow client then can cancel the first redirect because it reloads the page due to the session expiration. Lastly, the beacon request hits again a valid session, but a resynchronization is triggered because the previous UIDL request was rejected.

This change delays a bit the session expiration handling on Flow client, to allow a potential redirect to complete without being cancelled. However, the client application is immediately set in TERMINATED state.

Co-authored-by: Marco Collovati <[email protected]>
mcollovati added a commit that referenced this issue Nov 12, 2024
…avigation (#19983)

Attempts to fix the synchronization issue related to the usage of the Login reported in #12640.
The Login component sends the UIDL request for the login event to the server and concurrently submits the form.
If processing the form submission performs a session ID change and a request redirect, the UIDL requests might fail with a session expiration response. The Flow client then can cancel the first redirect because it reloads the page due to the session expiration. Lastly, the beacon request hits again a valid session, but a resynchronization is triggered because the previous UIDL request was rejected.

This change delays a bit the session expiration handling on Flow client, to allow a potential redirect to complete without being cancelled. However, the client application is immediately set in TERMINATED state.
mcollovati added a commit that referenced this issue Nov 12, 2024
…avigation (#19983)

Attempts to fix the synchronization issue related to the usage of the Login reported in #12640.
The Login component sends the UIDL request for the login event to the server and concurrently submits the form.
If processing the form submission performs a session ID change and a request redirect, the UIDL requests might fail with a session expiration response. The Flow client then can cancel the first redirect because it reloads the page due to the session expiration. Lastly, the beacon request hits again a valid session, but a resynchronization is triggered because the previous UIDL request was rejected.

This change delays a bit the session expiration handling on Flow client, to allow a potential redirect to complete without being cancelled. However, the client application is immediately set in TERMINATED state.
tepi pushed a commit that referenced this issue Nov 12, 2024
…avigation (#19983) (#20455)

Attempts to fix the synchronization issue related to the usage of the Login reported in #12640.
The Login component sends the UIDL request for the login event to the server and concurrently submits the form.
If processing the form submission performs a session ID change and a request redirect, the UIDL requests might fail with a session expiration response. The Flow client then can cancel the first redirect because it reloads the page due to the session expiration. Lastly, the beacon request hits again a valid session, but a resynchronization is triggered because the previous UIDL request was rejected.

This change delays a bit the session expiration handling on Flow client, to allow a potential redirect to complete without being cancelled. However, the client application is immediately set in TERMINATED state.
tepi pushed a commit that referenced this issue Nov 12, 2024
…avigation (#19983) (CP: 2.11) (#20456)

* fix: delay session expiration handling to prevent canceling ongoing navigation (#19983)

Attempts to fix the synchronization issue related to the usage of the Login reported in #12640.
The Login component sends the UIDL request for the login event to the server and concurrently submits the form.
If processing the form submission performs a session ID change and a request redirect, the UIDL requests might fail with a session expiration response. The Flow client then can cancel the first redirect because it reloads the page due to the session expiration. Lastly, the beacon request hits again a valid session, but a resynchronization is triggered because the previous UIDL request was rejected.

This change delays a bit the session expiration handling on Flow client, to allow a potential redirect to complete without being cancelled. However, the client application is immediately set in TERMINATED state.

* fix
@Manfred-on-github
Copy link
Contributor

We also see this in our production systems, and I want to share our findings.

It happens rarely, not reproducible, but since we have so many users, we see it several times per hour.

The bigger part comes during end of session, the RPC typically contains "UNLOAD":true (as written above by ssindelar). This is probably nothing which affects users.

But we also have a significant number of events when this happens in the middle of users' work. Server e.g. receives id=91, but expects id=90.

We have hacked code into ServerRpcHandler, when this situation is detected, we temporarily unlock the session, and let the thread wait (with some timeout) on a sync object.
Then processing continues, often a few milliseconds later we can process message #90. When this is processed we notify the sync object and the other thread awakes. It restores the lock on the session and processing continues. On client side everything seems to be ok, users apparently see no error in this situation.

So it looks like client does not strictly enforce sequential processing of messages, it sends out request #91 before answer for #90 has been received. We use XHR as communication mechanism.
If this is something that the client is allowed to do, due to the asynchronous nature of http requests it surely can happen that processing on server will be done in arbitrary sequence. Therefore code on server should handle this transparently (e.g. like we have tried)

@TatuLund
Copy link
Contributor

TatuLund commented Nov 28, 2024

@Manfred-on-github Yes, with WebSocket_XHR upstream is WebSocket and downstream HTTP, i.e. asymetric protocol, thus order of arrival not ensured by protocol. For this reason we have maxMessageSuspendTimeout configuration parameter, which is by default 5 seconds. You can configure it to be longer, as apparently your network infrastructure has some delay. This can be for example due firewall / VPN packet inspection slowing the communication. Check this comment for more info #12640 (comment) and documentation of maxMessageSuspendTimeout here: https://vaadin.com/docs/latest/flow/configuration/properties#properties

@oliveryasuna
Copy link
Contributor

We see this all the time and have determined it is due to poor connection on the client side. A lot of our users, across multiple of our webapps, have less-than-ideal internet connections.

It would be useful if a custom subclass of UnsupportedOperationException was thrown, instead of just UnsupportedOperationException. This would allow developers to properly handle the error without checking the exception's message, which many consider poor practice.

@Legioth
Copy link
Member

Legioth commented Jan 13, 2025

This would allow developers to properly handle the error without checking the exception's message

What does "properly handle" mean in you case? Just log and ignore or are you also carrying out some other action?

@TatuLund
Copy link
Contributor

We see this all the time and have determined it is due to poor connection on the client side. A lot of our users, across multiple of our webapps, have less-than-ideal internet connections.

Which kind of condition you have there. Is it just flaky, or is it bandwidth problem? If it is just flaky, the proposed caching mechanism #20348 could help. If it is bandwidth problem, then it requires application design changes to take the limited bandwidth into account.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Status: 🔖 High Priority (P1)
Development

No branches or pull requests