The SSE using SseEmitter of SpringBoot 2.6.3 is working well, but when there is a timeout, the following error appears :
org.apache.juli.logging.DirectJDKLog - : Changing async state from [STARTED] to [TIMING_OUT]
org.apache.juli.logging.DirectJDKLog - : Firing onTimeout() event for any AsyncListeners
org.springframework.web.context.request.async.WebAsyncManager - : Async error, dispatch to /api/v1/notification/stream-sse
org.apache.juli.logging.DirectJDKLog - : Req: 5853b03 CReq: 317e1a5a RP: 34cadcbc Stage: 3 Thread: http-nio-8081-exec-2 State: N/A Method: dispatch URI: /api/v1/notification/stream-sse
org.apache.juli.logging.DirectJDKLog - : Changing async state from [TIMING_OUT] to [DISPATCHING]
brave.internal.Platform - : X-B3-TraceId was null
org.springframework.core.log.LogAccessor - : Created a server receive span [NoopSpan(99f42cc61e441a20/99f42cc61e441a20)]
org.keycloak.adapters.PreAuthActionsHandler - 99f42cc61e441a20 : adminRequest http://localhost:8081/api/v1/notification/stream-sse
org.apache.juli.logging.DirectJDKLog - 99f42cc61e441a20 : Security checking request GET /api/v1/notification/stream-sse
org.apache.juli.logging.DirectJDKLog - 99f42cc61e441a20 : No applicable constraints defined
org.apache.juli.logging.DirectJDKLog - 99f42cc61e441a20 : Not subject to any constraint
org.keycloak.adapters.tomcat.AbstractAuthenticatedActionsValve - 99f42cc61e441a20 : AuthenticatedActionsValve.invoke /api/v1/notification/stream-sse
org.keycloak.adapters.AuthenticatedActionsHandler - 99f42cc61e441a20 : AuthenticatedActionsValve.invoke http://localhost:8081/api/v1/notification/stream-sse
org.keycloak.adapters.AuthenticatedActionsHandler - 99f42cc61e441a20 : Policy enforcement is disabled.
org.apache.juli.logging.DirectJDKLog - 99f42cc61e441a20 : Req: 5853b03 CReq: 317e1a5a RP: 34cadcbc Stage: 3 Thread: http-nio-8081-exec-2 State: N/A Method: intDispatch URI: /api/v1/notification/stream-sse
org.apache.juli.logging.DirectJDKLog - 99f42cc61e441a20 : Changing async state from [DISPATCHING] to [DISPATCHED]
org.springframework.security.web.FilterChainProxy - 99f42cc61e441a20 : Securing GET /api/v1/notification/stream-sse
org.springframework.security.web.context.SecurityContextPersistenceFilter - 99f42cc61e441a20 : Set SecurityContextHolder to empty SecurityContext
org.keycloak.adapters.PreAuthActionsHandler - 99f42cc61e441a20 : adminRequest http://localhost:8081/api/v1/notification/stream-sse
org.keycloak.adapters.PreAuthActionsHandler - 99f42cc61e441a20 : adminRequest http://localhost:8081/api/v1/notification/stream-sse
org.springframework.security.web.authentication.AnonymousAuthenticationFilter - 99f42cc61e441a20 : Set SecurityContextHolder to anonymous SecurityContext
org.springframework.security.web.FilterChainProxy$VirtualFilterChain - 99f42cc61e441a20 : Secured GET /api/v1/notification/stream-sse
org.springframework.core.log.LogFormatUtils - 99f42cc61e441a20 : "ASYNC" dispatch for GET "/api/v1/notification/stream-sse", parameters={}
org.springframework.core.log.LogFormatUtils - 99f42cc61e441a20 : Resume with async result [org.springframework.web.context.request.async.AsyncRequestTimeoutException]
org.springframework.web.servlet.mvc.support.DefaultHandlerExceptionResolver - 99f42cc61e441a20 : Async request timed out
org.springframework.web.servlet.handler.AbstractHandlerExceptionResolver - 99f42cc61e441a20 : Resolved [org.springframework.web.context.request.async.AsyncRequestTimeoutException]
org.springframework.web.servlet.FrameworkServlet - 99f42cc61e441a20 : Exiting from "ASYNC" dispatch, status 200
org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper - 99f42cc61e441a20 : Did not store anonymous SecurityContext
org.springframework.security.web.context.SecurityContextPersistenceFilter - 99f42cc61e441a20 : Cleared SecurityContextHolder to complete request
org.apache.juli.logging.DirectJDKLog - 99f42cc61e441a20 : Firing onComplete() event for any AsyncListeners
org.springframework.core.log.LogAccessor - : Handled send of span [NoopSpan(99f42cc61e441a20/99f42cc61e441a20)]
org.apache.juli.logging.DirectJDKLog - : Error state [CLOSE_CONNECTION_NOW] reported while processing request
java.io.IOException: Broken pipe
at java.base/sun.nio.ch.FileDispatcherImpl.write0(Native Method)
at java.base/sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:113)
at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:79)
at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:50)
at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:466)
at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:135)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1376)
at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:766)
at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:719)
at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:709)
at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.end(Http11OutputBuffer.java:568)
at org.apache.coyote.http11.filters.ChunkedOutputFilter.end(ChunkedOutputFilter.java:199)
at org.apache.coyote.http11.Http11OutputBuffer.end(Http11OutputBuffer.java:235)
at org.apache.coyote.http11.Http11Processor.finishResponse(Http11Processor.java:1222)
at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:389)
at org.apache.coyote.Response.action(Response.java:209)
at org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:262)
at org.apache.catalina.connector.Response.finishResponse(Response.java:443)
at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:260)
at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:241)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:889)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1735)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
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:834)
Which cause a lot of invasive errors in the logs.
Here is the backend SSE implementation:
@CrossOrigin
@PreAuthorize("hasPermission(ROLE,'')")
@GetMapping(value = "/api/v1/notification/stream-sse")
public SseEmitter streamEvents() {
SseEmitter sseEmitter = new SseEmitter(300000L);
ExecutorService sseExecutor = Executors.newCachedThreadPool();
sseExecutor.execute(
() -> {
sseEmitter.onTimeout(sseEmitter::complete);
sseEmitter.onError(
e -> {
sseEmitterMap.remove(username);
sseEmitter.complete();
});
try {
SseEmitter.SseEventBuilder event = SseEmitter.event()
.id(username)
.data(someData, MediaType.APPLICATION_JSON)
.name("messages");
sseEmitter.send(event);
} catch (Exception ex) {
sseEmitter.complete();
}
});
return sseEmitter;
}
Seems that calling .complete() does not stop gracefully the SSE connection.
The more stranger thing, is that when there is a timeout, the app tries to call the SSE endpoint again, and as there is no Token, the authentication fails
Any idea how to proper manage the timeout ?
Thank you
