CODEWITHSUNDEEP
playframeworkmultipartform-dataplayframework-2.4
jakob
jakob

Reputation: 6005

timeout when sending multipart form data in play2 2.4.6

I'm trying to move to play 2.4.6 but I'm struggling with updating my multipart/form data posting. The "old" code used: 

import com.ning.http.multipart._ libs

And was pretty straight forward:

val parts = Array[Part](
   new FilePart("file", currentFile)
)

val mpre = new MultipartRequestEntity(parts, new FluentCaseInsensitiveStringsMap)
val baos = new ByteArrayOutputStream
mpre.writeRequest(baos)
val bytes = baos.toByteArray
val contentType = mpre.getContentType     
// Now just send the data to the WS API
 WS.url(url)
    .post(bytes)(Writeable.wBytes, ContentTypeOf(Some(contentType))).map { response =>
    Logger.info("" + response.status)
//  Cool code here to handle stuff
}

Now ut seems that MultipartRequestEntity and all that good stuff is gone.. so I tried to rewrite it like this(sorry for ugly hacky code :)):

def uploadFileForOrder(id: Long) = Action {
    implicit request =>
    import com.ning.http.client.AsyncHttpClient
    import com.ning.http.client.multipart.FilePart
    import com.ning.http.client.multipart.StringPart
    import java.io.File
    import play.api.libs.ws._

  val asyncHttpClient: AsyncHttpClient = WS.client.underlying
  val postBuilder = asyncHttpClient.preparePost(url)
  val builder = postBuilder
  .addBodyPart(new FilePart("file.pdf", new  
  File("/Path/to/file/file.pdf")))
  .addHeader("Expect", "100-continue")

  val response = asyncHttpClient.executeRequest(builder.build()).get();
  Ok(""+response.getResponseBody())
 }

But what happens here is that the requests timesout after the default number of seconds. I have of course tried to curl to the api and that works like a charm:

curl --form file=@Path/to/file/file.pdf 'https://url'

I have probably missed something very trivial but what?

Stacktrace of timeout.

    [debug] - play.api.libs.ws.ning.NingAsyncHttpClientConfigBuilder - buildHostnameVerifier: enabling hostname verification using class play.api.libs.ws.ssl.DefaultHostnameVerifier
[debug] - org.jboss.netty.channel.DefaultChannelFuture - The dead lock checker in DefaultChannelFuture has been disabled as requested at your own risk.
[info] - application - parts[FilePart name=deevi-sthlm_1424182188313.pdf contentType=application/octet-stream charset=null tranferEncoding=binary contentId=null dispositionType=null filename=deevi-sthlm_1424182188313.pdf]
[debug] - org.jboss.netty.handler.ssl.SslHandler - [id: 0xe4b02f13, /192.168.1.197:50403 => cool.api.com/212.16.165.50:443] HANDSHAKEN: TLS_RSA_WITH_AES_128_CBC_SHA
[debug] - com.ning.http.client.providers.netty.request.NettyConnectListener - Request using non cached Channel '[id: 0xe4b02f13, /192.168.1.197:50403 => cool.api.com/212.16.165.50:443]':
DefaultHttpRequest(chunked: false)
POST /api/v2/7519/resources/upload/internal/order/23/?token=aaaaaaaa HTTP/1.1
Content-Length: 919937
Content-Type: multipart/form-data; boundary=pKuhU4cHh8J6RhA1tqOEeujTjvje06TC8AW8ZvZD
Connection: keep-alive
Host: cool.api.com
Accept: */*
User-Agent: AHC/1.0

[debug] - com.ning.http.client.providers.netty.channel.pool.DefaultChannelPool - Closed 0 connections out of 0 in 0ms
[debug] - com.ning.http.client.providers.netty.channel.pool.DefaultChannelPool - Closed 0 connections out of 0 in 0ms
[debug] - com.ning.http.client.providers.netty.request.timeout.TimeoutTimerTask - Request timed out to cool.api.com/212.16.165.50:443 of 120000 ms for NettyResponseFuture{currentRetry=0,
    isDone=false,
    isCancelled=false,
    asyncHandler=com.ning.http.client.AsyncCompletionHandlerBase@293e6e7c,
    nettyRequest=com.ning.http.client.providers.netty.request.NettyRequest@5b564b51,
    content=null,
    uri=https://cool.api.com/api/v2/7519/resources/upload/internal/order/23/?token=aaaaa,
    keepAlive=true,
    httpHeaders=null,
    exEx=null,
    redirectCount=0,
    timeoutsHolder=com.ning.http.client.providers.netty.request.timeout.TimeoutsHolder@51f45b89,
    inAuth=false,
    statusReceived=false,
    touch=845942276} after 120333 ms
[debug] - com.ning.http.client.providers.netty.channel.ChannelManager - Closing Channel [id: 0xe4b02f13, /192.168.1.197:50403 => cool.api.com/212.16.165.50:443] 
[debug] - com.ning.http.client.providers.netty.request.NettyRequestSender - Aborting Future NettyResponseFuture{currentRetry=0,
    isDone=false,
    isCancelled=false,
    asyncHandler=com.ning.http.client.AsyncCompletionHandlerBase@293e6e7c,
    nettyRequest=com.ning.http.client.providers.netty.request.NettyRequest@5b564b51,
    content=null,
    uri=https://cool.api.com/api/v2/7519/resources/upload/internal/order/23/?token=214141414,
    keepAlive=true,
    httpHeaders=null,
    exEx=null,
    redirectCount=0,
    timeoutsHolder=com.ning.http.client.providers.netty.request.timeout.TimeoutsHolder@51f45b89,
    inAuth=false,
    statusReceived=false,
    touch=845942276}

[debug] - com.ning.http.client.providers.netty.handler.Processor - Channel Closed: [id: 0xe4b02f13, /192.168.1.197:50403 :> cool.api.com/212.16.165.50:443] with attribute INSTANCE
[debug] - com.ning.http.client.providers.netty.request.NettyRequestSender - Request timed out to cool.api.com/212.16.165.50:443 of 120000 ms
java.util.concurrent.TimeoutException: Request timed out to cool.api.com/212.16.165.50:443 of 120000 ms
    at com.ning.http.client.providers.netty.request.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:47) [async-http-client-1.9.21.jar:na]
    at com.ning.http.client.providers.netty.request.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:48) [async-http-client-1.9.21.jar:na]
    at org.jboss.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:556) [netty-3.10.4.Final.jar:na]
    at org.jboss.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:632) [netty-3.10.4.Final.jar:na]
    at org.jboss.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:369) [netty-3.10.4.Final.jar:na]
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty-3.10.4.Final.jar:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
[debug] - com.ning.http.client.AsyncCompletionHandlerBase - Request timed out to cool.api.com/212.16.165.50:443 of 120000 ms
java.util.concurrent.TimeoutException: Request timed out to cool.api.com/212.16.165.50:443 of 120000 ms
    at com.ning.http.client.providers.netty.request.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:47) [async-http-client-1.9.21.jar:na]
    at com.ning.http.client.providers.netty.request.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:48) [async-http-client-1.9.21.jar:na]
    at org.jboss.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:556) [netty-3.10.4.Final.jar:na]
    at org.jboss.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:632) [netty-3.10.4.Final.jar:na]
    at org.jboss.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:369) [netty-3.10.4.Final.jar:na]
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty-3.10.4.Final.jar:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]

and

play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[TimeoutException: Request timed out to cool.api.com/212.16.165.50:443 of 120000 ms]]
    at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:265) ~[play_2.11-2.4.6.jar:2.4.6]
    at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:191) ~[play_2.11-2.4.6.jar:2.4.6]
    at play.api.GlobalSettings$class.onError(GlobalSettings.scala:179) [play_2.11-2.4.6.jar:2.4.6]
    at play.api.DefaultGlobal$.onError(GlobalSettings.scala:212) [play_2.11-2.4.6.jar:2.4.6]
    at play.api.http.GlobalSettingsHttpErrorHandler.onServerError(HttpErrorHandler.scala:94) [play_2.11-2.4.6.jar:2.4.6]
    at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:151) [play-netty-server_2.11-2.4.6.jar:2.4.6]
    at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:148) [play-netty-server_2.11-2.4.6.jar:2.4.6]
    at scala.runtime.AbstractPartialFunction.apply(AbstractPartialFunction.scala:36) [scala-library-2.11.7.jar:na]
    at scala.util.Failure$$anonfun$recover$1.apply(Try.scala:216) [scala-library-2.11.7.jar:na]
    at scala.util.Try$.apply(Try.scala:192) [scala-library-2.11.7.jar:na]
    at scala.util.Failure.recover(Try.scala:216) [scala-library-2.11.7.jar:na]
    at scala.concurrent.Future$$anonfun$recover$1.apply(Future.scala:324) [scala-library-2.11.7.jar:na]
    at scala.concurrent.Future$$anonfun$recover$1.apply(Future.scala:324) [scala-library-2.11.7.jar:na]
    at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32) [scala-library-2.11.7.jar:na]
    at play.api.libs.iteratee.Execution$trampoline$.executeScheduled(Execution.scala:109) [play-iteratees_2.11-2.4.6.jar:2.4.6]
    at play.api.libs.iteratee.Execution$trampoline$.execute(Execution.scala:71) [play-iteratees_2.11-2.4.6.jar:2.4.6]
    at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:40) [scala-library-2.11.7.jar:na]
    at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:248) [scala-library-2.11.7.jar:na]
    at scala.concurrent.Promise$class.complete(Promise.scala:55) [scala-library-2.11.7.jar:na]
    at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:153) [scala-library-2.11.7.jar:na]
    at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:23) [scala-library-2.11.7.jar:na]
    at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40) [akka-actor_2.11-2.3.13.jar:na]
    at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:397) [akka-actor_2.11-2.3.13.jar:na]
    at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) [scala-library-2.11.7.jar:na]
    at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) [scala-library-2.11.7.jar:na]
    at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) [scala-library-2.11.7.jar:na]
    at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [scala-library-2.11.7.jar:na]
Caused by: java.util.concurrent.TimeoutException: Request timed out to cool.api.com/212.16.165.50:443 of 120000 ms
    at com.ning.http.client.providers.netty.request.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:47) ~[async-http-client-1.9.21.jar:na]
    at com.ning.http.client.providers.netty.request.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:48) ~[async-http-client-1.9.21.jar:na]
    at org.jboss.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:556) ~[netty-3.10.4.Final.jar:na]
    at org.jboss.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:632) ~[netty-3.10.4.Final.jar:na]
    at org.jboss.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:369) ~[netty-3.10.4.Final.jar:na]
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) ~[netty-3.10.4.Final.jar:na]
    at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_45]
[debug] - play.core.netty.utils.ServerCookieDecoder - Skipping cookie because value '86030c54cfc1208b3a87ab3e0b3e3dd565940e8d0u07y2ap7kywplw*dqy.l*5uzexhfcv0_4nkev1w~p3cnk!(7d*4.)k_h(tbx3*v' contains invalid char '!'
[debug] - com.ning.http.client.providers.netty.channel.pool.DefaultChannelPool - Closed 0 connections out of 0 in 0ms

I also tried to post with:

.addHeader("Expect", "100-continue")
.addHeader("Content-Type","application/x-www-form-urlencoded")

but get a 413 Request Entity Too Large.

Request DefaultHttpRequest(chunked: false)
POST /api/v2/7519/resources/upload/internal/order/23/?token=aaaaaaa HTTP/1.1
Expect: 100-continue
Content-Length: 919931
Content-Type: application/x-www-form-urlencoded; boundary=pI11GyXoLyybJYI3pR9iMZDgu8D1ZaH_Y4Qmc
Connection: keep-alive
Host: power.upsales.com
Accept: */*
User-Agent: AHC/1.0

Response DefaultHttpResponse(chunked: false)
HTTP/1.1 413 Request Entity Too Large
Server: nginx/1.4.4
Date: Thu, 11 Feb 2016 08:12:50 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 1206
Connection: keep-alive
X-Content-Type-Options: nosniff

Upvotes: 0

Views: 1619

Answers (2)

jakob
jakob

Reputation: 6005

Stephane your previous answer(the one you deleted :))) made me think, maybe the server is expecting something but I'm missing it. So I dived into the curl request and scala request code and the solution was trivial. When adding the filepart the first param should be "file" otherwise the server wont process the file.

.addBodyPart(new FilePart("file", new File("/Path/to/file/file.pdf")))

So the code looks like this. I also implemented an async version to make it more Play2-esque:

def uploadFileForOrder(id: Long) = Action.async {
implicit request =>

    import com.ning.http.client._
    import com.ning.http.client.{Response => AHCResponse}
    import com.ning.http.client.AsyncHttpClient
    import com.ning.http.client.AsyncCompletionHandler
    import com.ning.http.client.multipart.FilePart
    import com.ning.http.client.multipart.StringPart
    import java.io.File
    import play.api.libs.ws._
    import play.api.libs.ws.ning.NingWSResponse
    import scala.concurrent.{Future, Promise}


    val asyncHttpClient: AsyncHttpClient = WS.client.underlying
    val postBuilder =
      asyncHttpClient.preparePost("https://cool.api.com/api/resources/upload/internal/order/23/?token=asdasdasdasda")
      val builder = postBuilder
      .addBodyPart(new FilePart("file", new File("/Path/to/file/file.pdf")))
      .addHeader("Expect", "100-continue")

      val request = builder.build()
      val result = Promise[NingWSResponse]()
      asyncHttpClient.executeRequest(request, new AsyncCompletionHandler[AHCResponse]() {
        override def onCompleted(response: AHCResponse) = {
          result.success(play.api.libs.ws.ning.NingWSResponse(response))
          response
        }
        override def onThrowable(t: Throwable) {
          result.failure(t)
        }
      })
      val postFuture = result.future
      postFuture.map { response =>
        Ok("status"+response.statusText)
      }.recover {
        case e: Throwable => {
          BadRequest("error" + e)
        }
      }
    }

Upvotes: 2

Stephane Landelle
Stephane Landelle

Reputation: 7038

You're probably hitting this issue that was fixed 4 months ago and released in AsyncHttpClient 1.9.32.

By default, Play2 2.4.6 ships with AsyncHttpClient 1.9.21 :(

Upgrade.

Upvotes: 0

Related Questions