search

ktorio / ktor

Framework for quickly creating connected applications in Kotlin with minimal effort
https://ktor.io
Apache License 2.0
12.81k stars 1.04k forks source link

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

Open Syrou opened 5 years ago

Syrou commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

@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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

@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 commented 4 years ago

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

Stexxe commented 3 years ago

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