Akka-http: Long-lived requests seem to be closed prematurely

[ktoso]

Reproducer posted on gitter by Dan Ellis @danellis, I've not yet reproduced with it yet;

---

Dan Ellis @danellis 00:23
@ktoso Alright, here's my repro: https://github.com/danellis/akka-entity-size-repro
Although in this case, I don't understand what's going on, because it appears to download the whole thing, then gives the EntityStreamSizeException when I ^C it.

Dan Ellis @danellis 00:23
(If I terminate the actor system when the download finishes, I get the same thing.)
I'm testing using a ~40M file.

 23:22:25.332 ERROR akka.actor.RepointableActorRef - Error during preStart in [akka.http.scaladsl.model.HttpEntity$Limitable@70518d2a]: EntityStreamSizeException: actual entity size (Some(41677837)) exceeded content length limit (8388608 bytes)! You can configure this by setting `akka.http.[server|client].parsing.max-content-length` or calling `HttpEntity.withSizeLimit` before materializing the dataBytes stream.
akka.http.scaladsl.model.EntityStreamSizeException: EntityStreamSizeException: actual entity size (Some(41677837)) exceeded content length limit (8388608 bytes)! You can configure this by setting `akka.http.[server|client].parsing.max-content-length` or calling `HttpEntity.withSizeLimit` before materializing the dataBytes stream.
    at akka.http.scaladsl.model.HttpEntity$Limitable$$anon$1.preStart(HttpEntity.scala:612)
    at akka.stream.impl.fusing.GraphInterpreter.init(GraphInterpreter.scala:293)
    at akka.stream.impl.fusing.GraphInterpreterShell.init(ActorGraphInterpreter.scala:553)
    at akka.stream.impl.fusing.ActorGraphInterpreter.tryInit(ActorGraphInterpreter.scala:675)
    at akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$postStop$2.apply(ActorGraphInterpreter.scala:795)
    at akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$postStop$2.apply(ActorGraphInterpreter.scala:795)
    at scala.collection.immutable.List.foreach(List.scala:392)
    at akka.stream.impl.fusing.ActorGraphInterpreter.postStop(ActorGraphInterpreter.scala:795)
    at akka.actor.Actor$class.aroundPostStop(Actor.scala:536)
    at akka.stream.impl.fusing.ActorGraphInterpreter.aroundPostStop(ActorGraphInterpreter.scala:666)
    at akka.actor.dungeon.FaultHandling$class.akka$actor$dungeon$FaultHandling$$finishTerminate(FaultHandling.scala:210)
    at akka.actor.dungeon.FaultHandling$class.terminate(FaultHandling.scala:172)
    at akka.actor.ActorCell.terminate(ActorCell.scala:370)
    at akka.actor.ActorCell.invokeAll$1(ActorCell.scala:468)
    at akka.actor.ActorCell.systemInvoke(ActorCell.scala:484)
    at akka.dispatch.Mailbox.processAllSystemMessages(Mailbox.scala:282)
    at akka.dispatch.Mailbox.run(Mailbox.scala:223)
    at akka.dispatch.Mailbox.exec(Mailbox.scala:234)
    at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
    at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
    at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)

[ktoso]

Made it a repo so does not get lost, too sleepy to check it right now... Thanks for reporting @danellis

[danellis]

I've added another commit to the reproducer. If I schedule the Ack with a delay instead of sending it right away (to simulate ingestion into a database), I get the exception during processing, which matches what happens in my application.

Using one second, it continues to completion after the exception. Using five seconds, it stops shortly (but not immediately) after the exception without completing the download:

00:43:17.447 DEBUG PullSupervisor - PullProgress(2752233,Some(41677837))
00:43:22.465 DEBUG PullSupervisor - PullProgress(2883305,Some(41677837))
00:43:27.376 WARN  a.h.impl.engine.client.PoolGateway - [0 (WaitingForEndOfResponseEntity)] Ongoing request [GET /random_1m.csv Empty] was dropped because pool is shutting down
00:43:27.380 ERROR akka.actor.RepointableActorRef - Error during preStart in [akka.http.scaladsl.model.HttpEntity$Limitable@388c554d]: EntityStreamSizeException: actual entity size (Some(41677837)) exceeded content length limit (8388608 bytes)! You can configure this by setting `akka.http.[server|client].parsing.max-content-length` or calling `HttpEntity.withSizeLimit` before materializing the dataBytes stream.
akka.http.scaladsl.model.EntityStreamSizeException: EntityStreamSizeException: actual entity size (Some(41677837)) exceeded content length limit (8388608 bytes)! You can configure this by setting `akka.http.[server|client].parsing.max-content-length` or calling `HttpEntity.withSizeLimit` before materializing the dataBytes stream.
    at akka.http.scaladsl.model.HttpEntity$Limitable$$anon$1.preStart(HttpEntity.scala:612)
    at akka.stream.impl.fusing.GraphInterpreter.init(GraphInterpreter.scala:293)
    at akka.stream.impl.fusing.GraphInterpreterShell.init(ActorGraphInterpreter.scala:553)
    at akka.stream.impl.fusing.ActorGraphInterpreter.tryInit(ActorGraphInterpreter.scala:675)
    at akka.stream.impl.fusing.ActorGraphInterpreter.finishShellRegistration(ActorGraphInterpreter.scala:717)
    at akka.stream.impl.fusing.ActorGraphInterpreter.akka$stream$impl$fusing$ActorGraphInterpreter$$shortCircuitBatch(ActorGraphInterpreter.scala:732)
    at akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$receive$1.applyOrElse(ActorGraphInterpreter.scala:757)
    at akka.actor.Actor$class.aroundReceive(Actor.scala:517)
    at akka.stream.impl.fusing.ActorGraphInterpreter.aroundReceive(ActorGraphInterpreter.scala:666)
    at akka.actor.ActorCell.receiveMessage(ActorCell.scala:527)
    at akka.actor.ActorCell.invoke(ActorCell.scala:496)
    at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)
    at akka.dispatch.Mailbox.run(Mailbox.scala:224)
    at akka.dispatch.Mailbox.exec(Mailbox.scala:234)
    at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
    at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
    at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
    at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
00:43:27.487 DEBUG PullSupervisor - PullProgress(3014377,Some(41677837))
00:43:32.506 DEBUG PullSupervisor - PullProgress(3145449,Some(41677837))
00:43:37.527 DEBUG PullSupervisor - PullProgress(3210796,Some(41677837))
[nothing more here]

[jrudolph]

Seems the reproducer is missing the server side? How do you run the reproducer exactly and what is the problem?

[danellis]

The server is just Fenix serving a 40MiB CSV file as http://localhost:8000/random_1m.csv. The problem is that it throws an EntityStreamSizeException instead of downloading the whole entity.

GZIP'd CSV file.

[radusw]

I encounter the same issue but using withoutSizeLimit():

[0 (WaitingForEndOfResponseEntity)] Ongoing request [GET <path> Empty] was dropped because pool is shutting down

[raboof]

It would be useful to also have a server side to go with this reproducer, since how the server behaves does influence what might happen, but I've been able to reproduce this and it looks like the akka.http.host-connection-pool.idle-timeout is triggering even though this response is still in progress.

[raboof]

This might not be trivial to fix since the pool idle-timeout handling is currently done in the PoolInterfaceActor, which sees the response but does not monitor how fast the response entity is consumed.

I'm not too comfortable adding that there as it is hard to say what the performance impact would be. For the new connection pool, however, HostConnectionPoolStage already monitors how fast the response entity is consumed, so it might fit in better there.

Before we start work on that, could you check whether indeed increasing akka.http.host-connection-pool.idle-timeout makes the problem (somewhat) go away?

[laszlovandenhoek]

I'm also running into this problem, downloading a 23GB file and streaming it to S3.

I have adapted the reproducer by @danellis to include an embedded HTTP server, making it fully self-contained. I have added a PR, you can find my branch here.

Using the adapted reproducer, I have played around with the akka.http.host-connection-pool.idle-timeout and akka.http.client.idle-timeout. Setting both to 30s makes the stream fail after about 70 seconds. Setting both to 120s, on the other hand, allows the test to continue running for the full 5 minutes allotted by the implicit ask timeout defined in Main.

I can confirm that this warning (also reported by @radusw earlier) always appears after about 30 seconds, _regardless of the idle-timeout settings_:

a.h.impl.engine.client.PoolGateway - [0 (WaitingForEndOfResponseEntity)] Ongoing request [GET /random_1m.csv Empty] was dropped because pool is shutting down

[laszlovandenhoek]

Perhaps the title of this issue should be changed? Because I also encounter this issue using withoutSizeLimit(). Rather, the problem is with long-lived HTTP client connections, I think.

[laszlovandenhoek]

FYI, using a cachedHostConnectionPool instead of singleRequest fixed my problems, without any additional tweaks (other than thoughtful Flow assembly). Also, I had some dependency injection issues locally causing spurious downloads to be materialized but not consumed, so that might have caused some of my issues.

[l15k4]

I'm getting this too :

a.h.impl.engine.client.PoolGateway - [0 (WaitingForEndOfResponseEntity)] Ongoing request [GET /random_1m.csv Empty] was dropped because pool is shutting down

Not sure that cachedHostConnectionPool would help, I'm using just a single connection, but long requests ... all limits possible are set to infinity ...

[xubofei1983]

Same here. Any walk-around?

[bilal-fazlani]

I am facing the same issue

[1mdc]

I have the same issue

2019-06-07 15:57:18,757 WARN  a.h.impl.engine.client.PoolGateway   - [0 (WaitingForEndOfResponseEntity)] Ongoing request [GET /feed Empty] was dropped because pool is shutting down
2019-06-07 15:57:18,980 WARN  a.h.impl.engine.client.PoolGateway   - [0 (WaitingForEndOfResponseEntity)] Ongoing request [GET /feed Empty] was dropped because pool is shutting down
2019-06-07 15:57:19,082 WARN  a.h.impl.engine.client.PoolGateway   - [0 (WaitingForEndOfResponseEntity)] Ongoing request [GET /feed Empty] was dropped because pool is shutting down

[xieyuheng]

I am facing the same issue

[xieyuheng]

@raboof

Before we start work on that, could you check whether indeed increasing akka.http.host-connection-pool.idle-timeout makes the problem (somewhat) go away?

Increasing akka.http.host-connection-pool.idle-timeout DOES NOT make the problem (somewhat) go away.

[jrudolph]

If you are experience the same issue, please still provide

• the version of akka-http and akka you are using
• relevant configuration lines
• the log output

[jrudolph]

A had a quick look at the latest reproducer at https://github.com/akka/akka-http/issues/1847#issuecomment-398069062. The problem there is that the wrong idle-timeout setting is used. If you set akka.http.host-connection-pool.idle-timeout (no client in there) then it indeed works as a workaround.

When we revisit this issue we should maybe deprecate the old setting name and rename it to pool-idle-timeout to get rid of that confusion at least.

[xieyuheng]

sorry, I was wrong, I confirm setting akka.http.host-connection-pool.idle-timeout is a workaround.

[jrudolph]

This is being addressed by #2630.

[jrudolph]

Fixed in #2630.

[pederpansen]

Hi, when will the fix be available? We are seeing this issue as well in production and workarounds (increasing either akka.http.host-connection-pool.idle-timeout or akka.http.host-connection-pool.client.idle-timeout) do not seem to have an effect.

EDIT: Just discovered some configs had no effect because they were loaded after the ActorSystem was already started. We will check increasing the timeouts as a workaround.

[raboof]

I don't think we have a projected release date for 10.1.10 yet - it might be some weeks away as we're currently focusing on Akka 2.6. Until that time you could consider running a nightly snapshot from https://bintray.com/akka/snapshots/akka-http