ktor connection is closed for a long polling requests (ConnectionClosedException)

[dtolstyi]

Ktor Version

1.1.3

Ktor Engine Used(client or server and name)

Apache Client

JVM Version, Operating System and Relevant Context

1.8

Feedback

I'm coming to this issue here after I initially thought that the problem is in underlying client (AsyncHttpClient): https://issues.apache.org/jira/browse/HTTPCLIENT-1980

After many investigations it looks like the problem is not in AsyncHttpClient but in ktor.
I've made a small reproducers that just perform constant GET requests to the same URL every 5 seconds. These reproducers were done using: HttpClient, AsyncHttpClient, Netty, vert.x Web Client and ktor.
All clients except ktor are working fine for multiple days (~4 days). Whereas ktor is stopping after some hours with ConnectionClosedException:

Exception in thread "main" org.apache.http.ConnectionClosedException: Connection closed
        at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.endOfInput(HttpAsyncRequestExecutor.java:345)
        at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:261)
        at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
        at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
        at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:121)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
        at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
        at java.lang.Thread.run(Thread.java:748)

Do you need any logs to be done or how can I help you to find the cause?

Thank you!

[dtolstyi]

Just in case, here's the code that was used:

val client = HttpClient(Apache)

var attempt = 0

while(true) {
    val response = client.call("https://tickets.fcbayern.com/Internetverkauf/EventList.aspx") {
        method = HttpMethod.Get
    }.response

    println("[${++attempt}] Status Code: [${response.status.value}]")

    delay(5000)
}

[e5l]

Hi @dtolstyi, thanks for the report.
There are 2 problems here:

1. response object wasn't closed, so the connections are leaking alive.
2. Ktor use some different defaults for the connection properties: https://api.ktor.io/1.1.3/io.ktor.client.engine.apache/-apache-engine-config/index.html

Probably you should repeat it with response.close()

[dtolstyi]

Thank you @e5l for you help and reply. I will try with response.close() and come back with results!

[dtolstyi]

Just 1 note: I checked netstat -p for my process without closing response and I don't see any connections leaking (there are 3 connections all the time). But, anyway, I will try with closing response.

[dtolstyi]

Hi @e5l, I'm back.
Unfortunately, the issue is still present even when closing the response:

Exception in thread "main" org.apache.http.ConnectionClosedException: Connection closed
        at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.endOfInput(HttpAsyncRequestExecutor.java:345)
        at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:261)
        at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
        at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
        at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:121)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
        at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
        at java.lang.Thread.run(Thread.java:748)

At the same time HttpAsyncClient reproducer runs without any issues for 5 days.

How can we investigate this issue?

[dtolstyi]

The issue happens after about 2 hours of constant polling.

[dtolstyi]

@e5l Can we do something about this?

[e5l]

I'm trying to reproduce and update you asap.

[dtolstyi]

Thank you Leonid!

Kind regards,
Dmytro TOLSTYI

чт, 18 апр. 2019 г. в 13:25, Leonid Stashevsky [e-mail]:

I'm trying to reproduce and update you asap.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/ktorio/ktor/issues/1066#issuecomment-484463080, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AB6OA5F67IWJ7XZE7WEKRYDPRBLCDANCNFSM4HFJOM6Q
.

[dtolstyi]

Hi @e5l. Are there any news? AsyncHttpClient instance is running fine for more than 3 weeks and ktor is failing after some hours.
Is there anything we can do about this?

[dtolstyi]

I've tried setting default values like in AsyncHttpClient:

        engine {
            customizeClient {
                setMaxConnPerRoute(0)
                setMaxConnTotal(0)
            }
        }

After some time reproducer failed with a new error:

xception in thread "main" io.ktor.client.features.SendCountExceedException: Max send count 20 exceeded
        at io.ktor.client.features.HttpSend$DefaultSender.execute(HttpSend.kt:83)
        at io.ktor.client.features.HttpRedirect$Feature.handleCall(HttpRedirect.kt:34)
        at io.ktor.client.features.HttpRedirect$Feature$handleCall$1.invokeSuspend(HttpRedirect.kt)
        at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:32)
        at io.ktor.util.pipeline.SuspendFunctionGun.resumeRootWith(PipelineContext.kt:211)
        at io.ktor.util.pipeline.SuspendFunctionGun.loop(PipelineContext.kt:168)
        at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(PipelineContext.kt:63)
        at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(PipelineContext.kt:118)
        at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:45)
        at kotlinx.coroutines.DispatchedKt.resumeCancellable(Dispatched.kt:185)
        at kotlinx.coroutines.ResumeModeKt.resumeMode(ResumeMode.kt:22)
        at kotlinx.coroutines.DispatchedKt.resume(Dispatched.kt:272)
        at kotlinx.coroutines.DispatchedKt.dispatch(Dispatched.kt:261)
        at kotlinx.coroutines.CancellableContinuationImpl.dispatchResume(CancellableContinuationImpl.kt:218)
        at kotlinx.coroutines.CancellableContinuationImpl.resumeImpl(CancellableContinuationImpl.kt:227)
        at kotlinx.coroutines.CancellableContinuationImpl.resumeWith(CancellableContinuationImpl.kt:168)
        at kotlinx.coroutines.ResumeAwaitOnCompletion.invoke(JobSupport.kt:1262)
        at kotlinx.coroutines.JobSupport.notifyCompletion(JobSupport.kt:1373)
        at kotlinx.coroutines.JobSupport.completeStateFinalization(JobSupport.kt:298)
        at kotlinx.coroutines.JobSupport.tryFinalizeFinishingState(JobSupport.kt:230)
        at kotlinx.coroutines.JobSupport.tryMakeCompleting(JobSupport.kt:799)
        at kotlinx.coroutines.JobSupport.makeCompleting$kotlinx_coroutines_core(JobSupport.kt:722)
        at kotlinx.coroutines.CompletableDeferredImpl.complete(CompletableDeferred.kt:70)
        at io.ktor.client.engine.apache.ApacheHttpRequestKt$sendRequest$consumer$1.invoke(ApacheHttpRequest.kt:38)
        at io.ktor.client.engine.apache.ApacheHttpRequestKt$sendRequest$consumer$1.invoke(ApacheHttpRequest.kt)
        at io.ktor.client.engine.apache.ApacheResponseConsumer.onResponseReceived(ApacheResponseConsumer.kt:30)
        at org.apache.http.nio.protocol.AbstractAsyncResponseConsumer.responseReceived(AbstractAsyncResponseConsumer.java:134)
        at org.apache.http.impl.nio.client.MainClientExec.responseReceived(MainClientExec.java:315)
        at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.responseReceived(DefaultClientExchangeHandlerImpl.java:151)
        at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.responseReceived(HttpAsyncRequestExecutor.java:304)
        at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:255)
        at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
        at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
        at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:121)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
        at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
        at java.lang.Thread.run(Thread.java:748)

[e5l]

Could you tell me if you try to set config timeouts to 0?
https://api.ktor.io/1.1.5/io.ktor.client.engine.apache/-apache-engine-config/index.html

[dtolstyi]

No, they are 10 seconds. Should I try 0? @e5l

[e5l]

Yes, for socketTimeout

[dtolstyi]

I will try and update this thread with results

[dtolstyi]

I'm back. Results are very strange with SocketTimeout set to 0.
After 2nd request reproducer hangs forever and never sends another request.
After restarting, the same behavior occurs. It means that on the 3rd request socket cannot be open (or something similar) and this freezes the execution forever.

[e5l]

Interesting. Does it happen on 1.2.0-rc?

[dtolstyi]

@e5l, no. It's 1.1.3. Should I try 1.2.0-rc?

[e5l]

Yep. It could be fixed bug with freeze

[dtolstyi]

@e5l nice. Freezing is fixed with 1.2.0-rc. I will try to launch it for a long run.

[e5l]

Awesome :) Wait for your reply

[dtolstyi]

@e5l Unfortunately, the same issue appears with the latest version of ktor-client-apache and updated configs:

Exception in thread "main" org.apache.http.ConnectionClosedException: Connection closed
        at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.endOfInput(HttpAsyncRequestExecutor.java:345)
        at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:261)
        at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
        at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
        at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:121)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
        at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
        at java.lang.Thread.run(Thread.java:748)

[dtolstyi]

I also tried setting default values of ktor into Apache HTTP Async Client and it's running fine for more than 5 days...

[dtolstyi]

@e5l I can provide a reproducer if you want.

[e5l]

Sure. It would be nice.

[dtolstyi]

https://github.com/dtolstyi/ktor-issue-1066-reproducer

[dtolstyi]

If I can help you in any way I would be glad to provide further assistance. Thank you Leonid!

[e5l]

Could you tell me how long it takes to reproduce the exception? I'm running your example on e5l/develop branch, and it seems to be okay.

[dtolstyi]

Unfortunately, it takes some time. Usually, it happens for me around the 1500th request (~1-2 hours of run).

[e5l]

Ok, I'll keep it running for a couple of days :)

[dtolstyi]

I've updated my comment) It should take several hours (the longest run was for about 1 day).
Thank you Leonid!

[dtolstyi]

Hi @e5l. Did you manage to reproduce the issue or should I make another reproducer?

[e5l]

Thanks, the issue reproduced, and I'm looking for a fix.

[dtolstyi]

Oh, it's so nice! Thank you so much Leonid!

[dtolstyi]

Hi Leonid @e5l. Are there any news regarding the issue or possible milestones when it can be fixed? Thank you.

[Anton3]

Hi! Is there any hope for a fix?

[e5l]

Hi @dtolstyi, could you try reproducing it with 1.3.2? We fixed some problems near the Apache consumer recently, so I can't reproduce it now.

[dtolstyi]

Hi @e5l . With a great pleasure! I'll get back to you as soon as I got results.

[dtolstyi]

@e5l. I'm having issues reproducing the issue because reproducer doesn't work anymore. Actually, target website has completely moved to HTTP/2 and httpasyncclient doesn't support HTTP/2, am I right?

[e5l]

Yep. Closed until confirmation.