Premature connection close (the server doesn't appear to support request pipelining)

[iReNe VB]

Hi all!

I’m making a call to an API, but most of the time I keep getting an error: “Premature connection close (the server doesn't appear to support request pipelining)”. Like 90% of the time I get that error, meaning: in very rare occasions the query does return the data it supposed to.

To make sure this wasn’t the API’s server issue, I replicate the exact same query using Node.js (Express and Request libs) and it works every time. It makes me almost sure is a spray issue.

Here's an example of the code:

case class MyClass(user: String, pass: String)

class MyActor extends Actor {
  import spray.client.pipelining._
  import spray.http.BasicHttpCredentials
  import spray.http.{HttpRequest,HttpResponse}
  import scala.concurrent.Future

  import context.dispatcher

  def receive = {
    case myClass: MyClass => {
      val credentials: BasicHttpCredentials = BasicHttpCredentials(myClass.user, myClass.pass)
      val url: String = "https://myApi?params=values"
      val request: HttpRequest = Get(url) ~> addCredentials(credentials)
      val pipeline = sendReceive
      val response: Future[HttpResponse] = pipeline(request)
      val finalRes: Future[String] = response.map{ r =>
        println(r)
        r.entity.asString
      }
      finalRes pipeTo sender
    }
  } // end receive
} //end Actor

Error detail:

04/01 10:19:05 DEBUG[on-spray-can-akka.actor.default-dispatcher-8] a.i.TcpOutgoingConnection - Attempting connection to ...

04/01 10:19:05 DEBUG[on-spray-can-akka.actor.default-dispatcher-6] a.i.TcpOutgoingConnection - Connection established to ...

04/01 10:19:05 DEBUG[on-spray-can-akka.actor.default-dispatcher-6] s.c.c.HttpClientConnection - Connected to ...

04/01 10:19:05 DEBUG[on-spray-can-akka.actor.default-dispatcher-9] s.c.c.HttpHostConnectionSlot - Connection to ... established, dispatching 1 pending requests

04/01 10:19:05 DEBUG[on-spray-can-akka.actor.default-dispatcher-3] s.c.c.HttpClientConnection - now monitoring Actor[akka://on-spray-can/system/IO-TCP/selectors/$a/5]

04/01 10:19:05 DEBUG[on-spray-can-akka.actor.default-dispatcher-6] s.c.c.HttpHostConnectionSlot - Dispatching GET request to /myApi?params=values across connection Actor[akka://on-spray-can/user/IO-HTTP/group-0/4]

04/01 10:19:05 DEBUG[on-spray-can-akka.actor.default-dispatcher-6] s.c.c.HttpHostConnectionSlot - now monitoring Actor[akka://on-spray-can/user/IO-HTTP/group-0/4]

04/01 10:19:06 DEBUG[on-spray-can-akka.actor.default-dispatcher-3] s.c.c.HttpClientConnection - Dropping Close since the SSL connection is already closing

04/01 10:19:06 DEBUG[on-spray-can-akka.actor.default-dispatcher-3] s.c.c.HttpClientConnection - Connection was PeerClosed, awaiting TcpConnection termination...

04/01 10:19:06 DEBUG[on-spray-can-akka.actor.default-dispatcher-3] a.i.TcpOutgoingConnection - stopped

04/01 10:19:06 DEBUG[on-spray-can-akka.actor.default-dispatcher-3] s.c.c.HttpClientConnection - TcpConnection terminated, stopping

04/01 10:19:06 WARN [on-spray-can-akka.actor.default-dispatcher-3] s.c.c.HttpHostConnectionSlot - Premature connection close (the server doesn't appear to support request pipelining) in response to GET request to /myApi?params=values with 1 retries left, retrying...

04/01 10:19:06 DEBUG[on-spray-can-akka.actor.default-dispatcher-3] s.c.c.HttpClientConnection - stopped

I was able to reproduce the error in all of these versions:

spray 1.0.1; akka 2.0.5; scala 2.9.3
spray 1.2.1; akka 2.2.4; scala 2.10.1
spray 1.3.1; akka 2.3.0; scala 2.10.3
spray 1.3.2; akka 2.3.6; scala 2.11.4
spray 1.3.3; akka 2.3.9; scala 2.11.6

[iReNe VB]

Just to provide more details, here's my 'application.conf' file:

akka {
  loggers = ["akka.event.slf4j.Slf4jLogger"]
  # Options: OFF, ERROR, WARNING, INFO, DEBUG
  loglevel = "DEBUG"
  # Options: OFF, ERROR, WARNING, INFO, DEBUG
  stdout-loglevel = "DEBUG"

  actor {
    debug {
      receive = on
      autoreceive = on
      lifecycle = on
    }
  }
}

spray {
  routing {
    file-chunking-threshold-size = 30k
    file-chunking-chunk-size = 15k
  }
  can{
    server {
      request-timeout = 30 s
      idle-timeout = 40 s
      timeout-timeout = 2 s
    }
    client {
      response-chunk-aggregation-limit = 15m
    }
  }
}

Another "funny" facts:

1) The time response of the API I'm trying to call is really fast: 307ms - 1 sec approx (So, is not like I'm getting a request timeout)

2) I'm able to get the results when replicating the same call with any REST client (I even created a test app with Node.js and I get the results there too).

3) I tried changing my logic to "split" the original search into several calls to the same API: Since is based on "userIds", the original query sends total of 27, so now I make one query to get the first 20 "userIds" and another one to get the remaining 7... and like that I do get the results. (This makes me believe the original query must have something 'special' going on, that makes this error appear every-time. I have no idea what's going on.)

[Mathias Doenitz]

This does indeed sound strange and is certainly something that we should investigate a bit deeper.

My guess is that there is some kind of issue related to the SSL/TLS encryption on the connection.
For some reason the server closes the TLS stream (and then the connection) before having sent the response.

If reducing the request size indeed makes a difference and other clients don’t exhibit the same behavior
then this would point to an issue in our client-side encryption logic. However, since this part of our code is not
new and nobody has reported the same issue in that gravity I’m currently scratching my head.

Do you have any more info on the server?
What server software is it running?
Does is also offer a non-encrypted API?
Is it maybe even public so we could try to reproduce the problem ourselves?

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/c7bbefa7-2729-4ab1-9f8a-b25fac85c138%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[iReNe VB]

Hi Mathias!

I'm currently talking with the team in charge of the server to be able to get all those details for you.

Right now the only thing I can tell you is that the server runs Apache Tomcat.

[iReNe VB]

Hi Mathias!

Sorry for the delay, I finally got the details from the server team.

If I get even more details I'll post them as soon as possible. Please let me know if there is anything else you need to know:

- What is the java server software version?  Apache Tomcat 6.0.20  - What is the JVM version that it runs on?  OpenJDK Runtime Environment (IcedTea6 1.11.11.90)  - Is there any custom configuration for handling SSL connections on this server?  This Tomcat stack is frontend by an Amazon Elastic Load Balancer (ELB) that handles all inbound request including https(443) That is then passed to the Web Service layer handled by Apache/2.2.29 which then proxy request to the Tomcat Application Tier. - Is there any additional configuration made for handling client timeouts ?  I'm not sure if we can had any additional configurations between the the ELB and Apache but this is where we would want to do any tuning if necessary.

[Kevin Esler]

I seem to be seeing the same problem here. Here is the DEBUG log. I've removed details of the server but could share in private if it helps with debugging:

14:59:20.570 [PostingTestApp-akka.actor.default-dispatcher-3] DEBUG s.can.client.HttpHostConnectionSlot - Attempting new connection to XXXXXX.net:443
14:59:20.687 [PostingTestApp-akka.actor.default-dispatcher-5] DEBUG s.can.client.HttpClientConnection - Attempting connection to XXXXXX.net/NN.NN.NN.NN:443
14:59:20.731 [PostingTestApp-akka.actor.default-dispatcher-3] DEBUG akka.io.TcpOutgoingConnection - Attempting connection to [XXXXXX.net/NN.NN.NN.NN:443]
14:59:20.762 [PostingTestApp-akka.actor.default-dispatcher-3] DEBUG akka.io.TcpOutgoingConnection - Connection established to [XXXXXX.net/NN.NN.NN.NN:443]
14:59:20.812 [PostingTestApp-akka.actor.default-dispatcher-5] DEBUG s.can.client.HttpClientConnection - Connected to XXXXXX.net/NN.NN.NN.NN:443
14:59:20.813 [PostingTestApp-akka.actor.default-dispatcher-4] DEBUG s.can.client.HttpHostConnectionSlot - Connection to XXXXXX.net:443 established, dispatching 1 pending requests
14:59:20.813 [PostingTestApp-akka.actor.default-dispatcher-4] DEBUG s.can.client.HttpHostConnectionSlot - Dispatching POST request to /AAExtWebservices/GESchedulerNotifierService.svc/GetNotifierAppointment across connection Actor[akka://PostingTestApp/user/IO-HTTP/group-0/0#-384875374]
14:59:21.107 [PostingTestApp-akka.actor.default-dispatcher-2] WARN  s.can.client.HttpClientConnection - Received illegal response: Response reason phrase exceeds the configured limit of 64 characters
14:59:21.108 [PostingTestApp-akka.actor.default-dispatcher-2] DEBUG s.can.client.HttpClientConnection - Closing outbound SSL stream due to reception of Close
14:59:21.140 [PostingTestApp-akka.actor.default-dispatcher-3] DEBUG s.can.client.HttpClientConnection - Dropping Close since the SSL connection is already closing
14:59:21.141 [PostingTestApp-akka.actor.default-dispatcher-3] DEBUG s.can.client.HttpClientConnection - Connection was PeerClosed, awaiting TcpConnection termination...
14:59:21.141 [PostingTestApp-akka.actor.default-dispatcher-3] DEBUG s.can.client.HttpClientConnection - TcpConnection terminated, stopping
14:59:21.142 [PostingTestApp-akka.actor.default-dispatcher-4] WARN  s.can.client.HttpHostConnectionSlot - Premature connection close (the server doesn't appear to support request pipelining) in response to POST request to /AAExtWebservices/GESchedulerNotifierService.svc/GetNotifierAppointment with no retries left, dispatching error...
14:59:21.143 [PostingTestApp-akka.actor.default-dispatcher-4] DEBUG s.can.client.HttpHostConnectionSlot - Delivering Status.Failure for POST request to /AAExtWebservices/GESchedulerNotifierService.svc/GetNotifierAppointment
?????? FAILURE: https://XXXXXX.net/AAExtWebservices/GESchedulerNotifierService.svc/GetNotifierAppointment . Exception thrown: ConnectionException, Premature connection close (the server doesn't appear to support request pipelining)
spray.can.Http$ConnectionException: Premature connection close (the server doesn't appear to support request pipelining)
    at spray.can.client.HttpHostConnectionSlot.reportDisconnection(HttpHostConnectionSlot.scala:228)
    at spray.can.client.HttpHostConnectionSlot$$anonfun$connected$1.applyOrElse(HttpHostConnectionSlot.scala:161)
    at akka.actor.Actor$class.aroundReceive(Actor.scala:465)
    at spray.can.client.HttpHostConnectionSlot.aroundReceive(HttpHostConnectionSlot.scala:33)
    at akka.actor.ActorCell.receiveMessage(ActorCell.scala:516)
    at akka.actor.ActorCell.invoke(ActorCell.scala:487)
    at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:254)

[Kevin Esler]

Ah in my case raising the setting at spray.can.client.parsing.max-response-reason-length to 256 removes the problem.

[Mathias Doenitz]

Kevin,

interesting.
What status code and reason phrase does the response have in this case?

Cheers,
Mathias

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

> To view this discussion on the web visit https://groups.google.com/d/msgid/spray-user/8c3d8c83-4516-4813-869f-8bf4e5d929b3%40googlegroups.com.

[Kevin Esler]

Sorry Mathias I didn't get a chance to capture that. It was a production problem so we just went with that setting adjustment that fixed the problem. The server in question runs Windows I believe but don't know much more about it yet. I may learn more shortly.

[iReNe VB]

Hi Kevin,

Thanks for the tip, but I just tried it and it didn't help in my case. Still getting the same error.

[Johannes Rudolph]

Hi,

you can also try setting `akka.io.tcp.trace-logging = on` and `spray.can.client.ssl-tracing = on` which should add even more debug output.

Johannes

To view this discussion on the web visit https://groups.google.com/d/msgid/spray-user/9b489e27-b975-4322-a51e-c3c22452be7f%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Johannes

-----------------------------------------------
Johannes Rudolph
http://virtual-void.net

[Milica]

Hi,

Did anyone find a solution for the problem Irene reported? I'm facing identical problem when trying to connect to a third-party API.

Versions: scala 2.10.3, akka 2.3.9, spray 1.3.1