GraphQL Timeout Error Message not clear

[robbi5]

When executing a GraphQL Query that runs into the (default) timeout of 30 seconds, an Error Response is returned that sadly doesn't reference the timeout (and such the reason why the query didn't succeed).
This caused a lot of confusion why our OTP instance didn't want to respond with stops for a GraphQL query and only cleared after we digged into the OTP code.

Expected behavior

The returned json contains an errorType or message that warns the user about the abortion of the query because of the timeout.

Observed behavior

In the returned json, there is nowhere a reference to a timeout found, instead a DataFetchingException with a null message appears:

{"data":{},"errors":[{"stack":[...]],"errorType":"DataFetchingException","locations":null,"message":"Exception while fetching data: null"}]}

Full Response

HTTP/1.1 500 Internal Server Error
Access-Control-Allow-Credentials: false
Content-Type: application/json
Date: Fri, 03 Apr 2020 20:46:44 GMT
Connection: close
Content-Length: 3072

{"data":{},"errors":[{"stack":["java.util.concurrent.FutureTask.report(FutureTask.java:121)","java.util.concurrent.FutureTask.get(FutureTask.java:192)","org.opentripplanner.index.ResourceConstrainedExecutorServiceExecutionStrategy.execute(ResourceConstrainedExecutorServiceExecutionStrategy.java:81)","graphql.execution.Execution.executeOperation(Execution.java:85)","graphql.execution.Execution.execute(Execution.java:44)","graphql.GraphQL.execute(GraphQL.java:201)","org.opentripplanner.routing.graph.GraphIndex.getGraphQLExecutionResult(GraphIndex.java:1055)","org.opentripplanner.routing.graph.GraphIndex.getGraphQLResponse(GraphIndex.java:1035)","org.opentripplanner.index.IndexAPI.getGraphQL(IndexAPI.java:657)","sun.reflect.GeneratedMethodAccessor56.invoke(Unknown Source)","sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)","java.lang.reflect.Method.invoke(Method.java:498)","org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)","org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)","org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)","org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)","org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)","org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)","org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)","org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)","org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326)","org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)","org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)","org.glassfish.jersey.internal.Errors.process(Errors.java:315)","org.glassfish.jersey.internal.Errors.process(Errors.java:297)","org.glassfish.jersey.internal.Errors.process(Errors.java:267)","org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)","org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)","org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)","org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.service(GrizzlyHttpContainer.java:384)","org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:224)","org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:591)","org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:571)","java.lang.Thread.run(Thread.java:745)"],"errorType":"DataFetchingException","locations":null,"message":"Exception while fetching data: null"}]}

Version of OTP used (exact commit hash or JAR name)

docker image: hsldevcom/opentripplanner:4325c2e143dcdc8c81ba36fb0f7f2e549667ed38

Steps to reproduce the problem

• Use a graph with lots and lots of stops (> 17.000), like verschwoerhaus/opentripplanner-data-container-vsh:2020-04-03-latest
• Allow maximum of 8GB RAM for the JVM, as set by default in the otp docker container: ENV JAVA_OPTS="-Xms8G -Xmx8G"
• Send a request to http://<otp-host>:8080/otp/routers/<router>/index/graphql with a long running query returning lots of objects, like the query hsl-map-server/tilelive-otp-stops issues for getting all the stops: https://github.com/HSLdevcom/tilelive-otp-stops/blob/3f0cac4ace1b6b506424ea0372c46ab190652914/index.js#L42-L62

Where does this come from?

In #94 (DT-607, DT-56) the TimedExecutorServiceExecutionStrategy (later ResourceConstrainedExecutorServiceExecutionStrategy) was introduced, to add a timeout to long running graphql queries to prevent a DOS.

[optionsome]

Sorry for the last response, again, but you have a valid point. I think the errors returned from OTP should in general have more information regarding the cause for the error. However, I think at this point we are starting to look more into adapting OTP 2 and doing these types of improvements to it.

We also face this timeout issue with the stop query. I think it should be possible to optimize the response time for fetching this type of data from the API. I'm not sure if the time is mostly spend going through the stops or in serializing them to the response. I think this is again something that will get hopefully get improved in OTP2. I think the current plan is that this fall a new version of the GraphQL API will be build for it which contains features from the hsldevcom fork API and from entur's (transmodel terminology based) API.