Large responses, ex: java exception stack, seems to not get handled

[Syrou]

Ktor Version

1.2.0-alpha-2

Ktor Engine Used(client or server and name)

Client

JVM Version, Operating System and Relevant Context

ktor-client-logging

Feedback

On non HttpStatusCode 200 even while using sl4j or a logging system that supports large content buffers, it seems like large response bodies is not correctly handled but gets stuck with "BODY START" and then several minutes later shows "A resource failed to call response.body().close()."

In this particular case the error response is a json object

[e5l]

Hi @Syrou, thanks for the report. The body logging freeze is fixed in develop branch, could you provide the example to create a test?

[Syrou]

@e5l This is the error coming back from the backend, and which seems to freeze up everything

com.domain.api.exception.NoSuchFeatureException: com.google.appengine.api.datastore.EntityNotFoundException: No entity was found matching the key: Feature(6446510218149888)
	at com.domain.appe.db.FeatureDBgae.getFeature(FeatureDBgae.java:663)
	at com.domain.appe.logic.FeatureLogic.getFeature(FeatureLogic.java:306)
	at com.domain.appe.logic.FeatureLogic.adjustBalance(FeatureLogic.java:1305)
	at com.domain.appe.logic.AnotherFeature.AnotherFeatureLogic.registerAnotherFeature(AnotherFeatureLogic.java:83)
	at com.domain.appe.servlets.rest.AnotherFeatureEndpoint.registerAnotherFeature(AnotherFeatureEndpoint.java:60)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.domain.microservices.gae.rest.RESTEndpoint.service(RESTEndpoint.java:488)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1772)
	at com.domain.appe.servlets.GumblerFilter.doFilter(GumblerFilter.java:45)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
	at com.google.apphosting.utils.servlet.JdbcMySqlConnectionCleanupFilter.doFilter(JdbcMySqlConnectionCleanupFilter.java:60)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
	at com.google.apphosting.runtime.jetty9.ParseBlobUploadHandler.handle(ParseBlobUploadHandler.java:119)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1182)
	at com.google.apphosting.runtime.jetty9.AppEngineWebAppContext.doHandle(AppEngineWebAppContext.java:183)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at com.google.apphosting.runtime.jetty9.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:293)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
	at org.eclipse.jetty.server.Server.handle(Server.java:539)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333)
	at com.google.apphosting.runtime.jetty9.RpcConnection.handle(RpcConnection.java:212)
	at com.google.apphosting.runtime.jetty9.RpcConnector.serviceRequest(RpcConnector.java:81)
	at com.google.apphosting.runtime.jetty9.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:123)
	at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchServletRequest(JavaRuntime.java:692)
	at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchRequest(JavaRuntime.java:655)
	at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:625)
	at com.google.apphosting.runtime.JavaRuntime$NullSandboxRequestRunnable.run(JavaRuntime.java:817)
	at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:269)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.google.appengine.api.datastore.EntityNotFoundException: No entity was found matching the key: Feature(6446510218149888)
	at com.google.appengine.api.datastore.BaseAsyncDatastoreServiceImpl$2.wrap(BaseAsyncDatastoreServiceImpl.java:221)
	at com.google.appengine.api.datastore.BaseAsyncDatastoreServiceImpl$2.wrap(BaseAsyncDatastoreServiceImpl.java:216)
	at com.google.appengine.api.utils.FutureWrapper.wrapAndCache(FutureWrapper.java:60)
	at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:101)
	at com.google.appengine.api.datastore.FutureHelper.getInternal(FutureHelper.java:69)
	at com.google.appengine.api.datastore.FutureHelper.quietGet(FutureHelper.java:56)
	at com.google.appengine.api.datastore.DatastoreServiceImpl.get(DatastoreServiceImpl.java:43)
	at com.domain.appe.db.FeatureDBgae.getFeature(FeatureDBgae.java:658)
	... 42 more

Status code is 500, if that for some reason matters.

[Syrou]

Another case would be where we get a response which is properly handled in the backend, but also freezes the response. This is currently our case where the response is of json with status code 500

{
    "errorTag": "not_found",
    "stacktrace": [
        "com.domain.api.exception.NoSuchFeatureException: com.google.appengine.api.datastore.EntityNotFoundException: No entity was found matching the key: Feature(6446510218149888) at com.domain.appe.db.FeatureDBgae.getFeature(FeatureDBgae.java:663) at com.domain.appe.logic.FeatureLogic.getFeature(FeatureLogic.java:306) at com.domain.appe.logic.FeatureLogic.adjustBalance(FeatureLogic.java:1305) at com.domain.appe.logic.AnotherFeature.AnotherFeatureLogic.registerAnotherFeature(AnotherFeatureLogic.java:83) at com.domain.appe.servlets.rest.AnotherFeatureEndpoint.registerAnotherFeature(AnotherFeatureEndpoint.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.domain.microservices.gae.rest.RESTEndpoint.service(RESTEndpoint.java:488) at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1772) at com.domain.appe.servlets.GumblerFilter.doFilter(GumblerFilter.java:45) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759) at com.google.apphosting.utils.servlet.JdbcMySqlConnectionCleanupFilter.doFilter(JdbcMySqlConnectionCleanupFilter.java:60) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) at com.google.apphosting.runtime.jetty9.ParseBlobUploadHandler.handle(ParseBlobUploadHandler.java:119) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1182) at com.google.apphosting.runtime.jetty9.AppEngineWebAppContext.doHandle(AppEngineWebAppContext.java:183) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at com.google.apphosting.runtime.jetty9.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:293) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) at org.eclipse.jetty.server.Server.handle(Server.java:539) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) at com.google.apphosting.runtime.jetty9.RpcConnection.handle(RpcConnection.java:212) at com.google.apphosting.runtime.jetty9.RpcConnector.serviceRequest(RpcConnector.java:81) at com.google.apphosting.runtime.jetty9.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:123) at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchServletRequest(JavaRuntime.java:692) at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchRequest(JavaRuntime.java:655) at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:625) at com.google.apphosting.runtime.JavaRuntime$NullSandboxRequestRunnable.run(JavaRuntime.java:817) at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:269) at java.lang.Thread.run(Thread.java:748) Caused by: com.google.appengine.api.datastore.EntityNotFoundException: No entity was found matching the key: Feature(6446510218149888) at com.google.appengine.api.datastore.BaseAsyncDatastoreServiceImpl$2.wrap(BaseAsyncDatastoreServiceImpl.java:221) at com.google.appengine.api.datastore.BaseAsyncDatastoreServiceImpl$2.wrap(BaseAsyncDatastoreServiceImpl.java:216) at com.google.appengine.api.utils.FutureWrapper.wrapAndCache(FutureWrapper.java:60) at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:101) at com.google.appengine.api.datastore.FutureHelper.getInternal(FutureHelper.java:69) at com.google.appengine.api.datastore.FutureHelper.quietGet(FutureHelper.java:56) at com.google.appengine.api.datastore.DatastoreServiceImpl.get(DatastoreServiceImpl.java:43) at com.domain.appe.db.FeatureDBgae.getFeature(FeatureDBgae.java:658) ... 42 more"
    ],
    "service": "default-service",
    "extra": {},
    "description": "An unknown error occurred, please try again or see over your input parameters.",
    "status": "error"
}

[cy6erGn0m]

What is com.domain.microservices.gae.rest.RESTEndpoint ? It doesn't look like a ktor handler. Does it contain ktor client invocations? The stacktrace complains about some missing key in GAE datastore while ktor itself does never interact with it. However an exception could somehow cause ktor client to hang.

[Syrou]

@cy6erGn0m That is just an example of the message trying to get printed with the feature logger, but it gets stuck when the backend ktor is communicating with sends the above message back

[oleg-larshin]

Please check the following ticket on YouTrack for follow-ups to this issue. GitHub issues will be closed in the coming weeks.

[Stexxe]

@Syrou could you please share the exact steps to reproduce your problem?