jjavery
commented
5 days ago Also there are some other exceptions in the log when the client disconnects e.g. browser navigates away from the page.
Closed jjavery closed 5 days ago
jjavery
commented
5 days ago Also there are some other exceptions in the log when the client disconnects e.g. browser navigates away from the page.
bclozel
commented
5 days ago Thanks for reaching out @jjavery
I'm reproducing this behavior and I had a look. I think there are several things to be considered here:
I think that we can solve 1) and 2) in this issue, improving the current GraphQlSseHandler implementation.
As for 3), I'm wondering what would be your expectations there. I saw that you prepared a tomcat configuration to extend the default async response timeout. Would you expect this to be configurable on the SSE handler directly for all subscriptions, without changing the application-wide default? We could tackle that in a different issue.
bclozel
commented
5 days ago I think I took care of both 1) and 2) with the change above. I'll wait for your feedback @jjavery before considering 3).
You can test this change with your repro application by adding the following to your build.gradle:
ext['spring-graphql.version'] = "1.3.3-SNAPSHOT"
repositories {
mavenCentral()
maven { url 'https://repo.spring.io/milestone' }
maven { url 'https://repo.spring.io/snapshot' }
}You'll need of course to completely remove your GraphQlSseHandler133 class.
jjavery
commented
4 days ago @bclozel Thanks! This is fantastic.
For 3), I don't know if this is possible (or advisable—I haven't put too much thought into it), but my preference is for subscriptions to have no timeout by default, with the ability to configure the timeout per each subscription. If that's not possible then yes, it could be configurable on the SSE handler for all subscriptions.
I'm still seeing some warnings in the logs for each async response timeout:
2024-10-17T13:23:22.023-05:00 WARN 62828 --- [nio-8080-exec-6] .w.s.m.s.DefaultHandlerExceptionResolver : Ignoring exception, response committed already: org.springframework.web.context.request.async.AsyncRequestTimeoutException
2024-10-17T13:23:22.024-05:00 WARN 62828 --- [nio-8080-exec-6] .w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.web.context.request.async.AsyncRequestTimeoutException]And exceptions when the client disconnects:
2024-10-17T13:38:18.597-05:00 ERROR 62828 --- [nio-8080-exec-3] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] threw exception
java.io.IOException: Broken pipe
at java.base/sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:na]
<...stack trace here...>
at java.base/java.lang.Thread.run(Thread.java:840) ~[na:na]
2024-10-17T13:38:18.601-05:00 ERROR 62828 --- [nio-8080-exec-3] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception
java.io.IOException: Broken pipe
at java.base/sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:na]
<...stack trace here...>
at java.base/java.lang.Thread.run(Thread.java:840) ~[na:na]Should I create separate issues for these?
bclozel
commented
4 days ago Thanks for your feedback. I will discuss our timeout options with the rest of the team.
As for the other logs:
No need to create a new issue for now.
rstoyanchev
commented
3 days ago We've had an initial discussion.
In the SSE handler, the operation with the subscription is just text that is not yet parsed by the GraphQL engine. There is no straight forward way to differentiate subscriptions. For the time being, we can expose a timeout on the SSE handler, and that should be easy to set with a property in Boot. I've created #1079.
I don't know if by "no timeout by default" you mean -1 (i.e.never timeout), or no timeout set (i.e. leave it to the underlying server, 30 seconds). Arguably 30 seconds is too short for an SSE stream, we could set that to 5 minutes perhaps.
For AsyncRequestTimeoutException, we can consider the same as what we did for AsyncRequestNotUsableException in https://github.com/spring-projects/spring-framework/issues/33225.
For the Broken Pipe, the exception seems to be logged by Tomcat there. We can't control that, but we'll check if it is easy to reproduce to understand why the exception remains not handled.
rstoyanchev
commented
21 hours ago I've had a look at the "Broken pipe" errors. Tomcat notifies us of the IOException that happened while writing, but as there is no error handling for that, it remains unhandled, and eventually logged by Tomcat.
I've created https://github.com/spring-projects/spring-framework/issues/33763 to improve that. In the mean you can add exception handling. For example in the demo:
@SpringBootApplication
public class DemoApplication {
public static void main(String[] args) {
SpringApplication.run(DemoApplication.class, args);
}
@Bean
WebMvcRegistrations webMvcRegistrations() {
return new WebMvcRegistrations() {
@Override
public ExceptionHandlerExceptionResolver getExceptionHandlerExceptionResolver() {
// Allow use of @ControllerAdvice for functional endpoints
ExceptionHandlerExceptionResolver resolver = new ExceptionHandlerExceptionResolver();
resolver.setMappedHandlerPredicate(handler -> true);
return resolver;
}
};
}
@ControllerAdvice
public static class GlobalExceptionHandler {
@ExceptionHandler
public Object handle(IOException ex) {
return (!DisconnectedClientHelper.isClientDisconnectedException(ex) ?
ResponseEntity.internalServerError().build() : null);
}
}
}For the default value of timeouts, we'are going to leave that without any setting in spring-graphql, but I've created https://github.com/spring-projects/spring-boot/issues/42807 where Boot can set some default.
I'm using
graphql-sseto connect to a basic Spring GraphQL@SubscriptionMappingthat returns aFlux<>. I'm seeing a Null Pointer Exception in the log every 30 seconds.Here's a Spring Initializr project demonstrating the problem:
https://github.com/jjavery/graphql-subscription-server-sent-events-npe
To reproduce: bootRun and open a browser to http://localhost:8080/ . Every 30 seconds you'll see the NPE in the log. Also there are unexpected warnings: "Ignoring exception, response committed already: org.springframework.web.context.request.async.AsyncRequestTimeoutException"
Includes the bug-fixed 1.3.3 version of GraphQlSseHandler.java copied from this commit: https://github.com/spring-projects/spring-graphql/commit/d3cd569e940479db7a2aab0a9b12aa81f1206ced
The 30 seconds comes from Tomcat's asyncTimeout. See TomcatConfiguration.java to change the asyncTimeout.
Log: