Output with full logging

[info] Compiling 1 Scala source to /Users/age/Development/src/agemooij/riak-scala-client/target/scala-2.10/test-classes...
01/19 23:59:09 DEBUG [akka://default/user/test-server]: SERVER: Starting akka://default/user/test-server on localhost/127.0.0.1:17249
01/19 23:59:09 INFO  [akka://default/user/io-bridge]: akka://default/user/io-bridge started
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: SERVER: Executing Bind(localhost/127.0.0.1:17249,100,LogMark(SERVER))
01/19 23:59:09 INFO  [akka://default/user/test-server]: SERVER: akka://default/user/test-server started on localhost/127.0.0.1:17249
01/19 23:59:09 DEBUG [akka://default/user/http-client/$a]: Opening connection 1 to localhost:17249
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: Executing Connect(localhost/127.0.0.1:17249,None,())
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: Connection request registered
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: SERVER: New connection accepted on localhost/127.0.0.1:17249
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: Connection established to localhost/127.0.0.1:17249
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: SERVER: Registering connection, enabling reads
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: Registering connection, enabling reads
01/19 23:59:09 DEBUG [akka://default/user/http-client/$a]: Connection 0 established, dispatching 1 pending requests
01/19 23:59:09 DEBUG [akka://default/user/http-client/$a]: Dispatching GET request to http://localhost:17249/abc across connection 0
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: Scheduling 139 bytes in 1 buffers for writing (ack: None)
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: Writing to connection
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: Wrote 139 bytes
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: SERVER: Reading from connection
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: SERVER: Read 139 bytes
01/19 23:59:09 DEBUG [akka://default/user/test-server/c1]: SERVER: Dispatching HttpRequest(GET, /abc, List(content-length: 13, content-type: text/plain, user-agent: spray-can/1.1-20130115, host: localhost:17249), HttpBody(ContentType(MediaType(text/plain),None),Great Content...), HTTP/1.1) to handler Actor[akka://default/user/handler]
01/19 23:59:09 DEBUG [akka://default/user/handler]: Responding with HttpRequest(GET, /abc, List(content-length: 13, content-type: text/plain, user-agent: spray-can/1.1-20130115, host: localhost:17249), HttpBody(ContentType(MediaType(text/plain),None),Great Content...), HTTP/1.1)
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: SERVER: Scheduling 156 bytes in 1 buffers for writing (ack: None)
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: SERVER: Writing to connection
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: SERVER: Wrote 156 bytes
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: Reading from connection
01/19 23:59:09 DEBUG [akka://default/user/io-bridge]: Read 156 bytes
01/19 23:59:09 DEBUG [akka://default/user/http-client/$a]: Dispatching HttpResponse(StatusCode(200, OK),HttpBody(ContentType(MediaType(text/plain),None),GET|/abc|Great Content...),List(content-length: 22, content-type: text/plain, date: Sat, 19 Jan 2013 22:59:09 GMT, server: spray-can/1.1-20130115),HTTP/1.1) for GET request to http://localhost:17249/abc
01/19 23:59:19 DEBUG [akka://default/user/http-client/$a/$a]: Closing connection due to idle timeout...
01/19 23:59:19 DEBUG [akka://default/user/io-bridge]: Closing connection due to IdleTimeout
01/19 23:59:19 DEBUG [akka://default/user/io-bridge]: SERVER: Reading from connection
01/19 23:59:19 DEBUG [akka://default/user/io-bridge]: SERVER: Closing connection due to PeerClosed
01/19 23:59:19 DEBUG [akka://default/user/http-client/$a/$a]: Stopping connection actor, connection was closed due to IdleTimeout
01/19 23:59:19 DEBUG [akka://default/user/test-server/c1]: SERVER: Stopping connection actor, connection was closed due to PeerClosed
01/19 23:59:19 DEBUG [akka://default/user/handler]: Received Closed event with reason PeerClosed
01/19 23:59:20 DEBUG [akka://default/user/http-client/$a]: Dispatching GET request to http://localhost:17249/abc across connection 0
01/19 23:59:20 WARN  [akka://default/user/event-stream-logger]: DeadLetter(HttpRequest(GET, /abc, List(Host: localhost:17249), HttpBody(ContentType(MediaType(text/plain),None),Great Content...), HTTP/1.1),Actor[akka://default/temp/$a],Actor[akka://default/user/http-client/$a/$a])
01/19 23:59:25 INFO  [akka://default/user/io-bridge]: akka://default/user/io-bridge stopped
[DEBUG] [01/19/2013 23:59:25.896] [default-akka.actor.default-dispatcher-4] [EventStream] shutting down: StandardOutLogger started
[DEBUG] [01/19/2013 23:59:25.899] [default-akka.actor.default-dispatcher-4] [EventStream] all default loggers stopped
[DEBUG] [01/19/2013 23:59:25.907] [default-akka.actor.default-dispatcher-2] [ActorSystem(default)] Could not reschedule message to be sent because receiving actor Actor[akka://default/user/http-client] has been terminated.
[info] HttpClientSpec
[info] 
[info] The HttpClient should
[error] ! not fail with a timeout when there is more then 10 seconds between
[error]     TimeoutException: Futures timed out after [5 seconds] (Promise.scala:96)
[error] spray.util.pimps.PimpedFuture.await(PimpedFuture.scala:29)
[error] HttpClientSpec$$anonfun$5$$anonfun$apply$2$$anonfun$apply$5.apply(SprayClientBugReproduction.scala:76)
[error] HttpClientSpec$$anonfun$5$$anonfun$apply$2$$anonfun$apply$5.apply(SprayClientBugReproduction.scala:76)
[error] HttpClientSpec$$anonfun$5$$anonfun$apply$2.apply(SprayClientBugReproduction.scala:76)
[error] HttpClientSpec$$anonfun$5$$anonfun$apply$2.apply(SprayClientBugReproduction.scala:69)
[info]  
[info]  
[info] Total for specification HttpClientSpec
[info] Finished in 16 seconds, 176 ms
[info] 1 example, 0 failure, 1 error
[info] 
[error] Error: Total 1, Failed 0, Errors 1, Passed 0, Skipped 0
[error] Error during tests:
[error]   HttpClientSpec
[trace] Stack trace suppressed: run last test:test-only for the full output.
[error] (test:test-only) Tests unsuccessful
[error] Total time: 20 s, completed Jan 19, 2013 11:59:26 PM

SprayclientBugreproduction.scala

/*
 * Copyright (C) 2011-2012 spray.io
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 * http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */

import scala.concurrent.duration._
import org.specs2.mutable.Specification
import akka.pattern.ask
import akka.util.Timeout
import akka.actor._
import spray.can.server.HttpServer
import spray.httpx.RequestBuilding
import spray.io._
import spray.http._
import spray.util._
import HttpHeaders._
import spray.client._
import pipelining._


class HttpClientSpec extends Specification with RequestBuilding {
  implicit val timeout: Timeout = 5 seconds span
  implicit val system = ActorSystem()
  val port = 17249

  val httpClient = system.actorOf(Props(new HttpClient()), "http-client")

  spray.http.warmUp()
  installDebuggingEventStreamLoggers()

  step {
    val handler = system.actorOf(Props(
      new Actor with SprayActorLogging {
        def receive = {
          case x@ HttpRequest(method, uri, _, entity, _) =>
            log.debug("Responding with " + x)
            sender ! response(method + "|" + uri + (if (entity.isEmpty) "" else "|" + entity.asString))
          case HttpServer.Closed(_, reason) => log.debug("Received Closed event with reason " + reason)
        }
        def response(s: String) = HttpResponse(entity = s, headers = List(`Content-Type`(ContentType.`text/plain`)))
      }
    ), "handler")
    system.actorOf(Props(new HttpServer(SingletonHandler(handler))), "test-server")
      .ask(HttpServer.Bind("localhost", port, tag = LogMark("SERVER"))).await
  }

  "The HttpClient" should {
    "properly process a request with Host header" in {
      val pipeline = addHeader(Host("localhost", port)) ~> sendReceive(httpClient)
      pipeline(Get("/abc", "Great Content")).await.withHeaders(Nil) === HttpResponse(entity = "GET|/abc|Great Content")
    }

    "properly process a request with the host specified in the URI" in {
      val pipeline = sendReceive(httpClient)
      pipeline(Get(s"http://localhost:$port/abc", "x")).await.withHeaders(Nil) === HttpResponse(entity = "GET|/abc|x")
    }

    "not fail with a timeout when there is more then 10 seconds between" in {
      val pipeline = addHeader(Host("localhost", port)) ~> sendReceive(httpClient)

      pipeline(Get("/abc", "Great Content")).await.withHeaders(Nil) === HttpResponse(entity = "GET|/abc|Great Content")

      // the problem occurs somewhere around the 10 seconds
      Thread.sleep(11 * 1000)

      pipeline(Get("/abc", "Great Content")).await.withHeaders(Nil) === HttpResponse(entity = "GET|/abc|Great Content")
    }
  }

  step(system.shutdown())

}