search

vaadin / flow

Vaadin Flow is a Java framework binding Vaadin web components to Java. This is part of Vaadin 10+.
Apache License 2.0
618 stars 167 forks source link

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

Open thomaskiesl opened 2 years ago

thomaskiesl commented 2 years ago

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 https://github.com/vaadin/flow/issues/9778

Minimal reproducible example

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

Versions

thomaskiesl commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

Legioth commented 2 years ago

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.

thomaskiesl commented 2 years ago

@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 commented 2 years ago

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 commented 2 years ago

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 https://github.com/vaadin/flow/issues/9778

funfried commented 11 months ago

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 commented 11 months ago

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 commented 10 months ago

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 commented 8 months ago

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 commented 8 months ago

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 commented 7 months ago

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 commented 7 months ago

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

thomaskiesl commented 7 months ago

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

TatuLund commented 7 months ago

That error is actually reported multiple times and has been discussed on many tickets. The error itself is not a bug as is, but logged as part of the failsafe mechanism in Vaadin.

When packets are sent back and forth between server and browser, they include serial number so that both parties can verify that no packet is being lost.

There are natural reasons for packet loss

When communication goes un-sync Vaadin detects that and does resynchronize. That is done on purpose in order to restore the operation.

When you see this error, one should observe does it happen in correlation with some usage pattern of the application, frequency, when it is happening etc. All these can give some hints whether it is due some natural cause of the error.

As you see the list of the natural causes are all flaky, hence deterministic re-production may be difficult.

The cases where it has been a bug in Vaadin have been difficult to debug, but with rigorous attempt of following the statistics, close collaboration with the reporter, ruling out natural causes we have been able to find those and fixed them. Naturally we would like to hope that we have identified all of them, and only the natural causes remain.

ssindelar commented 7 months ago

I see the error on my development machine from time to time. So I can exclude 1,2,4,5. We actually switched from Sophos to SentinelOne in the mean time so I guess I can also rule out 3. The only patterns that I see is that is happening when logging in and it is always request 2 that is missing. Everything after this seems fine. But the Logincode and most of the spring security code is located in a shared project and in the other application I wasn't able to reproduce the error. I will be away for 2 weeks but after that I would love to schedule a meeting, where we could try to find the cause on my machine.

mshabarov commented 7 months ago

Thanks everyone who commented and thanks @ssindelar for the feedback and willing be up for the meeting. This is that I was going to propose: have a video call and investigate the issue together. What I'm afraid of is that this may be not only limited to logging, but to a resync issue in Vaadin that may cause broken UI, e.g. empty page and page load freezing.

Based on the observations, we may need to implement more robust logic for resync and UIDL overall. I've prioritised this issue for the Vaadin Flow dev team.

Any volunteers are appreciated who can meet with us and show us the problem. Feel free to ping me, e.g. in our Discord (mikhailshabarov) , then we can schedule a meeting.

jfarjona commented 7 months ago

Happening to me too. Running vaadin 24.3.8 on JDK 21, all dependencies for springboot as defined by vaadin-bom. In my case, it happens if I am using Firefox:

Only way to login again is by closing the browser and start clean again. I haven't seen this case while using Chrome.

Hope this helps for debugging.

Legioth commented 7 months ago
  • I logout
  • I try to login again
  • BOOOM.

This sounds like there's something with the security configuration that causes messages to be eaten after logging in again or maybe that some of the tracking state is not reset.

guygoldwasser commented 6 months ago

Same java 17 vaadin 24.1.10 Azure

seems to be tentative issue

java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 0, got 1. more details logged on DEBUG level.

After investigations base on @TatuLund inputs: Azure WAF was set into prevent mode without filtering unnecessary groups of rules. ~1 of 7 heartbeat calls was rejected, and some of updates calls were rejected too. all of those are false positives of some SQL injection rules. there is no way to exploits any of those sql injections, and optional solutions are:

  1. Ensure only relevant group of rules are allow.
  2. Change WAF not to be in prevent mode.

from my POV I am happy that app crash due to those blockers on waf, otherwise it would have been even harder to follow other bugs that might come...

ssindelar commented 5 months ago

Currently it's not happening anymore.

vaadin 24.3.12

ssindelar commented 5 months ago

I think I tracked down the problem. Yesterday in the late afternoon the problem resurfaced with a nearly 100% reproduceability long enough so I could do some debugging before disappearing again a couple of minutes later.

I think the cause of the problem is a request with the "wrong" session id. The expection with the "Unexpected message id from the client" is a result of this but not the cause of the problem. Sadly it couldn't test my findings because it error disappeared so suddenly it reoccured.

What I found:

login requests

The first thing I noticed was that the second request after clicking the Login Button was recieving a session expired response.

for(;;);[{"meta":{"sessionExpired":true}}]

To understand whats happening we need to do a short deep dive into Spring Security and Tomcats session handling. During the login Spring Security rotates the session id to prevent a Session Fixation Attack. With a couple of tracepoints I was able to see this happening in the ManagerBase classs of Tomcat.

1717652790911: ManagerBase.findSession(): id: ED94756E4B357CE0DB87679830DFD345
1717652790998: ManagerBase.findSession(): id: ED94756E4B357CE0DB87679830DFD345
1717652791138: ManagerBase.rotateSessionId(): IDs ED94756E4B357CE0DB87679830DFD345->B017D99CC310854CB9C3F84C77471FAA
1717652791255: ManagerBase.remove(): ED94756E4B357CE0DB87679830DFD345
1717652791385: ManagerBase.add() id: B017D99CC310854CB9C3F84C77471FAA
1717652791475: ManagerBase.findSession(): id: B017D99CC310854CB9C3F84C77471FAA
1717652791835: ManagerBase.findSession(): id: B017D99CC310854CB9C3F84C77471FAA

When the response of the first request arrives the cookie is updated with the new session id. The second request is send most of the time before the first one returns. So it get's send with the "old" session id. This usually works because the login takes some time and the second request has got the session before the id is changed.

With a breakpoint in ManagerBase.findSession I was able to reproduce the exception by stopping both threads and letting the login update the session id before continueing the second request:

1717665414928: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B
1717665415501: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B
1717665415576: ManagerBase.rotateSessionId(): IDs 2142A520BADA3B2C14AA8A987FB2E57B->895B54763431012ED472F7BFAD811018
1717665415667: ManagerBase.remove(): 2142A520BADA3B2C14AA8A987FB2E57B
1717665415744: ManagerBase.add() id: 895B54763431012ED472F7BFAD811018
1717665416631: ManagerBase.findSession(): id: 895B54763431012ED472F7BFAD811018
1717665417831: ManagerBase.findSession(): id: 895B54763431012ED472F7BFAD811018
11:16:57.838 ERROR [http-nio-8090-exec-13] 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.
    [...]
1717665425751: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B
1717665425818: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B
1717665425887: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B
1717665425959: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B
1717665427857: ManagerBase.findSession(): id: 895B54763431012ED472F7BFAD811018
1717665429452: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B
1717665429528: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B
1717665429601: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B
1717665429672: ManagerBase.findSession(): id: 2142A520BADA3B2C14AA8A987FB2E57B

While it's currently not happening without the breakpoints and manual continuation, I'm very confident I would see a request with the outdated session id that can't find it's session. When a VaadinRequest can't find the session a reconnect is triggered. Now it depends on the timing of the reconnect if the user ends up at the Login or the page after. A reconnect on the page after the login usually goes unnoticed because it looks like a refresh or a little longer load time.

mcollovati commented 5 months ago

@ssindelar thank you very much for the thorough investigation! This is really helpful!

ssindelar commented 5 months ago

I found a good way to reproduce it. Setting the tomcat max threads to 1 forces a serial processing of the requests and now the second request always gets the sessionExpired:true response.

Spring boot:

server.tomcat.threads.max=1

The bug only occurs when using the vaadin login component.

Session id usage of a "failed" login

1717670183366: ManagerBase.findSession(): id: 0BDB1E5F301316D24C23BAEE59CF6390
1717670187420: ManagerBase.findSession(): id: 0BDB1E5F301316D24C23BAEE59CF6390
1717670187624: ManagerBase.findSession(): id: 0BDB1E5F301316D24C23BAEE59CF6390
1717670187753: ManagerBase.rotateSessionId(): IDs 0BDB1E5F301316D24C23BAEE59CF6390->098A188C5AD6D307166CBB939DE4A586
1717670187902: ManagerBase.remove(): 0BDB1E5F301316D24C23BAEE59CF6390
1717670188044: ManagerBase.add() id: 098A188C5AD6D307166CBB939DE4A586
1717670188138: ManagerBase.findSession(): id: 0BDB1E5F301316D24C23BAEE59CF6390
1717670188222: ManagerBase.findSession(): id: 0BDB1E5F301316D24C23BAEE59CF6390
1717670188306: ManagerBase.findSession(): id: 0BDB1E5F301316D24C23BAEE59CF6390
1717670188385: ManagerBase.findSession(): id: 0BDB1E5F301316D24C23BAEE59CF6390
1717670188473: ManagerBase.findSession(): id: 098A188C5AD6D307166CBB939DE4A586
1717670188589: ManagerBase.findSession(): id: 098A188C5AD6D307166CBB939DE4A586
1717670188785: ManagerBase.findSession(): id: 098A188C5AD6D307166CBB939DE4A586
12:36:28.803 ERROR [http-nio-8092-exec-1] 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.
    [...]
1717670188872: ManagerBase.findSession(): id: 098A188C5AD6D307166CBB939DE4A586
1717670188967: ManagerBase.findSession(): id: 098A188C5AD6D307166CBB939DE4A586
1717670189037: ManagerBase.findSession(): id: 098A188C5AD6D307166CBB939DE4A586

I'm no Javascript expert but waiting for the first request to finish before sending out the second should fix it.

A possible (bad) workaround would be to make the login slower, so the second request is started after the Session ID is updated. That also explains why we only get the issue on one application because this application has the fastest Login. The others are doing a REST Request to another service for the login.

SebastianDietrich commented 4 months ago

Shouldn't this bug be moved to github.com/vaadin/vaadin-login/issues ?

diantonio85 commented 3 months ago

Hi, we are also facing this issue randomly.

Forcing Chrome to Low-end mobile profile increases chances to hit the bug.

We are on vaadin 24.3.12

slawalata commented 3 months ago

Hi, I am facing the same issue. In my case, it always happens during login. Vaadin 24.4.6 = vaadin LoginForm. JDK amazoncorretto:21.

It dont appear during local development but when uploaded to cloud, it returns same errors.

many thanks,

mperktold commented 2 months ago

We also have this issue in production. It's great that finally, there is some way to reproduce it, thanks @ssindelar!

However, I don't think login is the only place where this can happen. We have screenshots of customers where this apparently happens in the middle of a working session.

Therefore, I wonder, what is it that login does "wrong" that leads to this issue? How can we be sure that our custom components don't make the same mistakes?

mcollovati commented 1 month ago

An update on the login issue.

The problem seems to be that when you submit the form, Spring Security changes the sessionId, but at the same time the client also sends a UIDL login event with the "old" session cookie. The UIDL requests then sends back a "Session expired" message, and this could be fine, since we will get a new UI after for submission because of the redirect issued by Spring Security. However, when the browser is going to be redirected, it also sends an UNLOAD UIDL message with the new session ID, and this is the request that fails because it has clientId=3, but the clientId=2 message was previously rejected because of session expiration.

timomeinen commented 3 weeks ago

In my applications, this error appears more often when end user device is mobile Safari on iPad with mobile connections.

TatuLund commented 3 weeks ago

@timomeinen , then you should check this issue instead: https://github.com/vaadin/flow/issues/20010

timomeinen commented 3 weeks ago

Thank you, @TatuLund. I also suspected that the push might be causing the issue, so I disabled @Push in the AppShell since our applications don’t use it (except for the Viritin DynamicDownloadButton, which falls back to polling). However, this didn’t lead to any improvement.

Interestingly, I have a similar application used exclusively by backoffice users on desktop clients, and it doesn’t exhibit these issues.

Note: Our MDM prevents iOS18 until now. So all clients use iOS17.

jorgheymans commented 3 weeks ago

Our users are also seeing this sporadically, result is a rather ugly 'invalid json response from server' on the screen. No login form involved, desktop/laptop devices on internal corporate network. Push disabled. Latest 24.4.x

TatuLund commented 3 weeks ago

@jorgheymans 'invalid json response from server' is not usually related to synchronization as that error is more often related to unexpected closing of the session while client is still running. Then when there is next request, Vaadin does bootstraping and severs the index page, which is naturally a invalid json. This invalid json error can be avoided if there is Vaadin-Refresh token in the content served. Then client will notice this and also restart itself.

mperktold commented 2 weeks ago

An update on the login issue...

@mcollovati Your explanation makes sense to me. How does this apply when you invalidate the session manually using VaadinSession.close or WrappedSession.invalidate? We do that in certain situations when we find that the session is not active, and I suspect that in our case, the warnings discussed here come from those rather than login.

Is your draft going to improve things for these situations of things as well?

mcollovati commented 2 weeks ago

The draft change on Flow would help in the case of concurrent requests, when one of those invalidates the session and also triggers a redirect. Not sure about your case. If there are no concurrent requests, the cause of the warnings may be different.

jorgheymans commented 2 weeks ago

Not wanting to add noise as i may be behind on the discussion, but since the error message says this System exception:java.lang.UnsupportedOperationException: Unexpected message id from the client. Expected sync id: 243, got 244. more details logged on DEBUG level.. Any logging categories we can enable DEBUG logging for in order to get more details? Would JFR dumps help, or the output of a static AOP weave on com.vaadin and/or some other packages? It's happening around 5-10 times per day in our production logs. In our much less busy non-prod environments we see it 1-2 times per week.

We are going to deploy Vaadin Observability in the coming months, would something helpful be visible there?

(EDIT no login form in our situation, it's all pre-authenticated principals, spring-security)

TatuLund commented 2 weeks ago

@jorgheymans , if you are new to party, the essential read is this comment: https://github.com/vaadin/flow/issues/12640#issuecomment-2022380134

jorgheymans commented 2 weeks ago

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 commented 2 weeks ago

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:

TatuLund commented 2 weeks ago

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 commented 2 weeks ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 4 days ago

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.