Logging HttpRequest response times in pipeline

[Elisabeth Anderson]

What's the best way to glean the time an HttpRequest has taken to complete? Currently my request looks like:

val pipeline = sendReceive ~> unmarshal[Foo]

val headers = List(RawHeader("Accept", "application/json"))

pipeline(HttpRequest(GET, Uri(uri).

    withQuery(

      "foo" -> bar,

      "bar" -> baz

    ),

    headers

))

...although I do have an alternative logging pipeline like:

val pipeline = logRequest ~> sendReceive ~> logResponse ~> unmarshal[NitroApiResult[NitroService]]

...which just simply logs the request/response using:

val logRequest: HttpRequest => HttpRequest = { req: HttpRequest => log.info(req.toString); req }

val logResponse: HttpResponse => HttpResponse = { res: HttpResponse => log.info(res.toString); res }

Is there a way of using a similar technique to log the time a response takes to come back?

[Mathias Doenitz]

Elisabeth,

how about something like this (untested):

case class TimeHeader(nanos: Long) extends HttpHeader {
def name = “Time"
def value = nanos.toString
def lowercaseName = “time"
}

val timedSendReceive: SendReceive = {
val transport: SendReceive = sendReceive
request => {
val timeStamp = System.nanoTime
transport(request) map { response =>
val timeHeader = TimeHeader(System.nanoTime - timeStamp)
response.mapHeaders(timeHeader :: _)
}
}
}

Then you can use the `timedSendReceive` exactly like the pre-defined `sendReceive`.
With the difference that all responses now also contain a `TimeHeader` with the time it took to complete the request.

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/1be31d1a-7f80-4219-9ccb-2ad24d64a9b9%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[Elisabeth Anderson]

That's really nice, thank you! Hadn't thought of using the sendReceive! :)

On Friday, March 6, 2015 at 12:41:33 PM UTC, Mathias wrote:

Elisabeth,

how about something like this (untested):

    case class TimeHeader(nanos: Long) extends HttpHeader {
      def name = “Time"
      def value = nanos.toString
      def lowercaseName = “time"
    }

    val timedSendReceive: SendReceive = {
      val transport: SendReceive = sendReceive
      request => {
        val timeStamp = System.nanoTime
        transport(request) map { response =>
          val timeHeader = TimeHeader(System.nanoTime - timeStamp)
          response.mapHeaders(timeHeader :: _)
        }
      }
    }

Then you can use the `timedSendReceive` exactly like the pre-defined `sendReceive`.
With the difference that all responses now also contain a `TimeHeader` with the time it took to complete the request.

Cheers,
Mathias

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

[Elisabeth Anderson]

Do you have an example of the overloaded render method. I've checked the scaladocs and I can't really tell what it should be doing...

On Friday, March 6, 2015 at 12:41:33 PM UTC, Mathias wrote:

Elisabeth,

how about something like this (untested):

    case class TimeHeader(nanos: Long) extends HttpHeader {
      def name = “Time"
      def value = nanos.toString
      def lowercaseName = “time"
    }

    val timedSendReceive: SendReceive = {
      val transport: SendReceive = sendReceive
      request => {
        val timeStamp = System.nanoTime
        transport(request) map { response =>
          val timeHeader = TimeHeader(System.nanoTime - timeStamp)
          response.mapHeaders(timeHeader :: _)
        }
      }
    }

Then you can use the `timedSendReceive` exactly like the pre-defined `sendReceive`.
With the difference that all responses now also contain a `TimeHeader` with the time it took to complete the request.

Cheers,
Mathias

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

On 6.3.2015, at 12:46, Elisabeth Anderson

[Mathias Doenitz]

Ah, right, sorry.
This should work:

def render[R <: Rendering](r: R) = r ~~ name ~~ “: “ ~~ value

Cheers,
Mathias

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

> To view this discussion on the web visit https://groups.google.com/d/msgid/spray-user/87ab862d-8686-464c-9ffe-83420cdef567%40googlegroups.com.

[Elisabeth Anderson]

Awesome, thanks. Just tweaked it to:

def render[R <: Rendering](r: R): r.type = r ~~ name ~~ ':' ~~ value

...is that ok?

On Friday, March 6, 2015 at 4:44:59 PM UTC, Mathias wrote:

Ah, right, sorry.
This should work:

    def render[R <: Rendering](r: R) = r ~~ name ~~ “: “ ~~ value

Cheers,
Mathias

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

[Mathias Doenitz]

Sure. That works as well.

Rendering of your `Time` header is not that big an issue anyway, since you only want to use that header as a vehicle for transporting the `nanos` values
(rather that is being a header type that should actually be rendered into a request or response).

Cheers,
Mathias

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

> To view this discussion on the web visit https://groups.google.com/d/msgid/spray-user/b918f65a-1e31-40d5-b79f-c88f1cfc5ba3%40googlegroups.com.

[Elisabeth Anderson]

Perfect, thanks Mathais—it's working well! :)

On Monday, March 9, 2015 at 9:19:58 AM UTC, Mathias wrote:

Sure. That works as well.

Rendering of your `Time` header is not that big an issue anyway, since you only want to use that header as a vehicle for transporting the `nanos` values
(rather that is being a header type that should actually be rendered into a request or response).

Cheers,
Mathias

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

[Mike Lenner]

This is super helpful - I plan to implement something similar.

One thing I'd like to be able to do is record the request, the response, and the latency for a given call. Was thinking of following this approach, but also adding details about the request (e.g. URI, post body, etc) into this mock header object in addition to the latency. Does that sound reasonable?