onFinally() callback called too early, before the GraphQL query has finished executing

[lburja]

Describe the bug

Due to changes made in #259, the onFinally() callback of GraphQLServletListener is called before the GraphQL query has finished executing. This affects releases 10.1.0 and 11.0.0.

More exactly, in AbstractGraphQLHttpServlet, we have the place where onFinally() callback is called:

private void doRequest(HttpServletRequest request, HttpServletResponse response) {
    List<GraphQLServletListener.RequestCallback> requestCallbacks = runListeners(
        l -> l.onRequest(request, response));

    try {
      getConfiguration().getHttpRequestHandler().handle(request, response);
      runCallbacks(requestCallbacks, c -> c.onSuccess(request, response));
    } catch (Exception t) {
      log.error("Error executing GraphQL request!", t);
      runCallbacks(requestCallbacks, c -> c.onError(request, response, t));
    } finally {
      runCallbacks(requestCallbacks, c -> c.onFinally(request, response));
    }
  }

In previous versions, the line getConfiguration().getHttpRequestHandler().handle(request, response) would block until the GraphQL query was finished. But nowadays, it just starts the query without blocking, as can be seen in HttpRequestInvokerImpl, where the execution is started using CompletableFutures, without blocking the flow:

public void execute(GraphQLInvocationInput invocationInput, HttpServletRequest request,
      HttpServletResponse response) {
    if (request.isAsyncSupported()) {
      AsyncContext asyncContext = request.isAsyncStarted()
          ? request.getAsyncContext()
          : request.startAsync(request, response);
      asyncContext.setTimeout(configuration.getAsyncTimeout());
      invoke(invocationInput, request, response)
          .thenAccept(result -> writeResultResponse(invocationInput, result, request, response))
          .exceptionally(t -> writeErrorResponse(t, response))
          .thenAccept(aVoid -> asyncContext.complete());
    } else {
      ...
    }
  }

(please note that under Spring Boot, request.isAsyncSupported() is by default true)

To Reproduce
Put a breakpoint (or a logging statement) in AbstractGraphQLHttpServlet at the line where onFinally() is called, and another one in HttpRequestInvokerImpl, inside the method writeResultResponse(). You'll notice that onFinally() is called before the GraphQL query has finished executing (i.e. before writeResultResponse() has been called).

Expected behavior
This is a regression. The expectation is that onFinally() is called after the GraphQL query has finished. This is useful for example, in order to release resources used by GraphQL

[oliemansm]

@lburja I updated the example-graphql-tools spring boot in this branch https://github.com/graphql-java-kickstart/graphql-spring-boot/tree/listener-finally-test to try to reproduce it with current version of servlet (11.1.0). I added some breakpoints and log statements to try to reproduce this before upgrading to my PR fix to verify this fixes the issue. To my surprise however the current version is calling the callbacks at the moments I was expecting. I even included a delay in the Post Resolver of a second to make sure it blocks the flow a bit, but it just calls it at the right time, while async is indeed enabled.

So judging by the code and your explanation I would in fact expect what you are reporting, but for some reason my example project is working as expected. See the logs I'm seeing in which you can clearly see the correct order:

2021-05-01 23:07:43.816  INFO 213164 --- [nio-9001-exec-9] c.g.s.b.GraphQLToolsSampleApplication    : Start request
2021-05-01 23:07:44.820  INFO 213164 --- [nio-9001-exec-9] com.graphql.sample.boot.PostResolver     : Return comments
2021-05-01 23:07:44.826  INFO 213164 --- [nio-9001-exec-9] c.g.s.b.GraphQLToolsSampleApplication    : Success
2021-05-01 23:07:44.826  INFO 213164 --- [nio-9001-exec-9] c.g.s.b.GraphQLToolsSampleApplication    : Finally

Are you still experiencing problems with this? Am I doing something wrong in the example project? Any help in this area is appreciated to determine if this is indeed still an issue that needs fixing.

The PR #338 in this project moves the listener handling into the invoker itself, so it's handled inside the CompletableFuture instead. I'm getting the same log output and order as pasted above, so that's looking good. I think it's actually the better location in the code for it. I just don't understand why I'm not able to reproduce your original report.

[lburja]

Indeed, this PR seems to fix the issue. I can reproduce the bug with 11.0.0, but on the branch bugfix/293-async-call-listeners, the problem is fixed!

…

On Sat, May 1, 2021 at 11:23 PM Michiel Oliemans ***@***.***> wrote: @lburja <https://github.com/lburja> I updated the example-graphql-tools spring boot in this branch https://github.com/graphql-java-kickstart/graphql-spring-boot/tree/listener-finally-test to try to reproduce it with current version of servlet (11.1.0). I added some breakpoints and log statements to try to reproduce this before upgrading to my PR fix to verify this fixes the issue. To my surprise however the current version is calling the callbacks at the moments I was expecting. I even included a delay in the Post Resolver of a second to make sure it blocks the flow a bit, but it just calls it at the right time, while async is indeed enabled. So judging by the code and your explanation I would in fact expect what you are reporting, but for some reason my example project is working as expected. See the logs I'm seeing in which you can clearly see the correct order: 2021-05-01 23:07:43.816 INFO 213164 --- [nio-9001-exec-9] c.g.s.b.GraphQLToolsSampleApplication : Start request 2021-05-01 23:07:44.820 INFO 213164 --- [nio-9001-exec-9] com.graphql.sample.boot.PostResolver : Return comments 2021-05-01 23:07:44.826 INFO 213164 --- [nio-9001-exec-9] c.g.s.b.GraphQLToolsSampleApplication : Success 2021-05-01 23:07:44.826 INFO 213164 --- [nio-9001-exec-9] c.g.s.b.GraphQLToolsSampleApplication : Finally Are you still experiencing problems with this? Am I doing something wrong in the example project? Any help in this area is appreciated to determine if this is indeed still an issue that needs fixing. The PR #338 <#338> in this project moves the listener handling into the invoker itself, so it's handled inside the CompletableFuture instead. I'm getting the same log output and order as pasted above, so that's looking good. I think it's actually the better location in the code for it. I just don't understand why I'm not able to reproduce your original report. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#293 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADQDT22EKBPW57V5JOMQJTTLRWLHANCNFSM4V4VXQBQ> .

[sgrannan]

@oliemansm So we were using version 11 but I am trying to upgrade to newer version. This change (#338 in the AbstractGraphQLHttpServlet seems to have broken our code, and I don't understand why or where I can fix it. I'm just using kickstart OOB with servlet enabled.

Currently we have some Custom Context that is being built and populated with objects and information by using some information retrieved from the HttpRequest. I have error handling in the GraphQLServletContextBuilder.build method that used to hit this block of code that was removed:

catch (Exception t) { log.error("Error executing GraphQL request!", t); runCallbacks(requestCallbacks, c -> c.onError(request, response, t));

That no longer works and my tests produce a 400 error with empty body because the handler just swallows the error thrown during build and throws its own GraphQLError that I cannot seem to control. What is the way forward for this situation?

Here is the stacktrace for reference:

[lburja]

For error handling, you can customize the default behavior by providing your own DataFetcherExceptionHandler: GraphQL.Builder graphQLBuilder = ... graphQLBuilder.defaultDataFetcherExceptionHandler(...)

…

On Fri, Apr 15, 2022 at 4:10 PM sgrannan ***@***.***> wrote: So we were using version 11 but I am trying to upgrade to newer version. This change in the AbstractGraphQLHttpServlet seems to have broken our code, and I don't understand why or where I can fix it. I'm just using kickstart OOB with servlet enabled. Currently we have some Custom Context that is being built and populated with objects and information by using some information retrieved from the HttpRequest. I have error handling in the GraphQLServletContextBuilder.build method that used to hit this block of code that was removed: catch (Exception t) { log.error("Error executing GraphQL request!", t); runCallbacks(requestCallbacks, c -> c.onError(request, response, t)); That no longer works and my tests produce a 400 error with empty body because the handler just swallows the error during build and throws its own GraphQLError that I cannot seem to control. What is the way forward for this situation? — Reply to this email directly, view it on GitHub <#293 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADQDTZGQ5UINF3TV2AN5UTVFF2D5ANCNFSM4V4VXQBQ> . You are receiving this because you were mentioned.Message ID: ***@***.*** com>

[sgrannan]

GraphQL.Builder graphQLBuilder = ...
graphQLBuilder.defaultDataFetcherExceptionHandler(...)

I appreciate the quick response. However I don't understand because that doesn't seem to solve the problem I'm having though?

The callbacks were removed completely and my error handling is inside the ContextBuilder. I prefer to have the GraphQLBuilder auto configure given all the things that happen there. So you're telling me I now have to have a custom GraphQLBuilder now just to catch these specific errors along with my already implemented GraphQLExceptionHandler?

When upgrading and debugging my tests I never see code go through the HttpRequestInvokerImpl.java. If you're going to handle errors this way, shouldn't a custom error thrown during Context Build be caught as that exception by any GraphQLExceptionHandler -> @ExceptionHandler(MyCustomException.class) because that is not happening due to the behavior I described in my original comment.