Async(timeout?) issue with spray-servlet

[Stanislav Palatnik]

I'm using spray-servlet to run spray on top of Tomcat. I have a route that serves (potentially large) files asynchronously. This week I noticed it errored out with the following: 

java.lang.IllegalStateException: The request associated with the AsyncContext has already completed processing.

at org.apache.catalina.core.AsyncContextImpl.check(AsyncContextImpl.java:535)

at org.apache.catalina.core.AsyncContextImpl.complete(AsyncContextImpl.java:92)

at spray.servlet.Servlet30ConnectorServlet$Responder.postProcess(Servlet30ConnectorServlet.scala:120)

at spray.servlet.Servlet30ConnectorServlet$Responder.handle(Servlet30ConnectorServlet.scala:155)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at akka.actor.ActorRef.tell(ActorRef.scala:125)

at spray.routing.RequestContext$$anon$2.handle(RequestContext.scala:72)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at spray.routing.RequestContext$$anon$1.handle(RequestContext.scala:84)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at spray.routing.RequestContext$$anon$1.handle(RequestContext.scala:84)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at spray.routing.RequestContext$$anon$1.handle(RequestContext.scala:84)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at spray.routing.RequestContext$$anon$1.handle(RequestContext.scala:84)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at spray.routing.RequestContext$$anon$3.handle(RequestContext.scala:102)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at spray.routing.RequestContext$$anon$3.handle(RequestContext.scala:102)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at spray.routing.RequestContext$$anon$3.handle(RequestContext.scala:102)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at spray.routing.RequestContext$$anon$3.handle(RequestContext.scala:102)

at akka.spray.UnregisteredActorRefBase.$bang(UnregisteredActorRefBase.scala:72)

at spray.httpx.marshalling.MetaMarshallers$ChunkingActor$$anonfun$receive$1$$anon$1.marshalTo(MetaMarshallers.scala:77)

at spray.httpx.marshalling.BasicMarshallers$$anonfun$byteArrayMarshaller$1.apply(BasicMarshallers.scala:32)

at spray.httpx.marshalling.BasicMarshallers$$anonfun$byteArrayMarshaller$1.apply(BasicMarshallers.scala:29)

at spray.httpx.marshalling.Marshaller$$anon$2.apply(Marshaller.scala:47)

at spray.httpx.marshalling.MetaMarshallers$ChunkingActor$$anonfun$receive$1.applyOrElse(MetaMarshallers.scala:86)

at akka.actor.ActorCell.receiveMessage(ActorCell.scala:498)

at akka.actor.ActorCell.invoke(ActorCell.scala:456)

at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:237)

at akka.dispatch.Mailbox.run(Mailbox.scala:219)

at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:386)

at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:262)

at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:975)

at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1478)

at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:104)

It erred out at approximately the same time the request should time out(3 minutes), however, a request timeout simply returns to the user, where this erred out directly on the server. 

Here is the code that handles the async request. I did not override the chunking threshold.  :

respondWithHeader( `Content-Type`( new ContentType( MediaTypes.`application/zip`, None ) ) ) {
  respondWithHeader( `Content-Disposition`( "attachment", Map( ( "filename", fileName + ext ) ) ) ) {
    implicit val bufferMarshaller = BasicMarshallers.byteArrayMarshaller( new ContentType( MediaTypes.`application/zip`, None ) )
    val smbInputStream = new SmbFileInputStream(smbPath)
    if ( 0 < settings.fileChunkingThresholdSize && settings.fileChunkingThresholdSize <= fileInfo.fileSize )
      complete( smbInputStream.toByteArrayStream( settings.fileChunkingChunkSize.toInt ) )
    else complete( smbInputStream.toByteArrayStream( 200000 ) )
  }
}

Versions: 

spray-servelt - 1.2.0 

Tomcat 7.0

[Stanislav Palatnik]

Just want to follow up that it definitely throws this error at the request-timeout setting in spray-servlet. However, the download in the browser keeps going for around 4 minutes after that. Then the network errors out. I assume it's just getting what was buffered? 

Is this expected behavior? It's returning a 200 OK immediately and then starting the chunked download, and errors out. I don't want to set the timeout unreasonably high to solve this, but at this rate, I cannot get large downloads to complete. Does anyone have any experience with this? Or am I doing something stupid?

[Mathias Doenitz]

Stanislav,

to me this looks like a problem in Tomcat.
For some reason the timeout is triggered even though the chunked response is still being produced.

From looking at the stack trace and the code there should be another error message being logged before the ISE that you showed.
It should be a message starting with "Could not write response chunk”.
Can you verify that?

Cheers,
Mathias

---
mat...@spray.io
http://spray.io

> --
> You received this message because you are subscribed to the Google Groups "spray.io User List" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to spray-user+...@googlegroups.com.
> Visit this group at http://groups.google.com/group/spray-user.
> To view this discussion on the web visit https://groups.google.com/d/msgid/spray-user/c6fd13fa-902d-4b10-9000-f0e52f03877b%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[Stanislav Palatnik]

Hey Mathias, 

Thanks for taking a look. It does not say "Could not write response chunk", the only thing above the ISE is an unknown exception log from the ServiceActor

2015-06-18 15:20:16,546 [MAPI-akka.actor.default-dispatcher-2680] ERROR com.ss.archiveapi.ServiceActor - Unknown exception

java.lang.IllegalStateException: The request associated with the AsyncContext has already completed processing.

at org.apache.catalina.core.AsyncContextImpl.check(AsyncContextImpl.java:535)

at org.apache.catalina.core.AsyncContextImpl.complete(AsyncContextImpl.java:92)

..

I see that it should have been thrown in Servlet30ConnectorServlet?  Anyway, I'm looking at the docs, and if I understand correctly, Tomcat will start the async timer as soon as the service initially responds with a 200?

"In spray-can it(request-timeout) designates the maximum time, in which a response must have been started (i.e. the first chunk received), while in spray-servlet it defines the time, in which the response must have been completed (i.e. the last chunk received)."

Additionally I found this Tomcat ticket which discusses this scenario: https://bz.apache.org/bugzilla/show_bug.cgi?id=55996

Ironically there was a bug in tomcat which was resetting the counter on write(according to the comments), but now it's been fixed :P

This leads me to believe that while this is not handled gracefully, is it the expected behavior? If so, what's the most efficient way for me to stream large files with spray-servlet? Sorry for throwing out so many questions at once, but this did hit me rather unexpectedly.

[Mathias Doenitz]

Stanislav,

> This leads me to believe that while this is not handled gracefully, is it the expected behavior?

Yeah, I guess so.
There doesn’t appear to be much we can do to alleviate the situation from our side.

> If so, what's the most efficient way for me to stream large files with spray-servlet?

Maybe the best way would be to, before starting a large response, set a really large (or even infinite) timeout with `SetRequestTimeout`.
This way you can have a reasonable timeout for non-streaming responses and still have streaming ones work correctly.

Cheers,
Mathias

---
mat...@spray.io
http://spray.io

> To view this discussion on the web visit https://groups.google.com/d/msgid/spray-user/cfa402a7-855d-48a3-8073-f960b94a37e5%40googlegroups.com.

[Stanislav Palatnik]

>Maybe the best way would be to, before starting a large response, set a really large (or even infinite) timeout with `SetRequestTimeout`. 

I think I introduced some confusion with a rather ambiguous question here: https://groups.google.com/forum/#!msg/spray-user/sHZo7wntfPA/A25fVFF_wggJ

I was referring if it was possible to set the timeout per connection, not the connection: close per connection. I looked at the code and the agreed upon method in that thread was to pass a command to spray-can through `SetRequestTimeout`, but I didn't see how this was handled on the spray-servlet side.

Or will I have to switch to spray-can for this?

[Mathias Doenitz]

Stanislav,

`SetRequestTimeout` also works with spray-servlet:
https://github.com/spray/spray/blob/master/spray-servlet/src/main/scala/spray/servlet/Servlet30ConnectorServlet.scala#L172

Cheers,
Mathias

---
mat...@spray.io
http://spray.io

> To view this discussion on the web visit https://groups.google.com/d/msgid/spray-user/45e07477-3cf4-484b-851b-6e6f2df74d34%40googlegroups.com.

[Stanislav Palatnik]

Ah I thought it was getting set globally. Thanks for clarifying Mathias!