Play / Logging / Print Response Body / Run over enumerator / buffer the body

Question

I'm looking for a way to print the response body in Play framework, I have a code like this:

object AccessLoggingAction extends ActionBuilder[Request] {
  def invokeBlock[A](request: Request[A], block: (Request[A]) => Future[Result]) = {
    Logger.info(s"""Request:
      id=${request.id} 
      method=${request.method} 
      uri=${request.uri} 
      remote-address=${request.remoteAddress} 
      body=${request.body}
    """)
    val ret = block(request)
    /*
    ret.map {result =>
      Logger.info(s"""Response:
      id=${request.id} 
      body=${result.body}
      """)
    }
    */ //TODO: find out how to print result.body (be careful not to consume the enumerator)
    ret
  }
}

Currently the commented-out code is not working as I wanted, I mean, it would print:

Response:
id=1
body=play.api.libs.iteratee.Enumerator$$anon$18@39e6c1a2

So, I need to find a way to get a String out of Enumerator[Array[Byte]]. I tried to grasp the concept of Enumerator by reading this: http://mandubian.com/2012/08/27/understanding-play2-iteratees-for-normal-humans/

So..., if I understand it correctly:

1. I shouldn't dry-up the enumerator in the process of converting it to String. Otherwise, the client would receive nothing.

2. Let's suppose I figure out how to implement the T / filter mechanism. But then... wouldn't it defeat the purpose of Play framework as non-blocking streaming framework (because I would be building up the complete array of bytes in the memory, before calling toString on it, and finally log it)?

So, what's the correct way to log the response?

Thanks in advance, Raka

Ache

You should log the response in a way that's streaming as well. E.g. System.out is an OutputStream, you can log there in a streaming way (though you might end up with two responses interleaved). If you're logging to a database you can stream to that. And so on. – Kirchner

I think I found the answer, here: #17752651 – Ache

Answer 1

This code works:

object AccessLoggingAction extends ActionBuilder[Request] {
  def invokeBlock[A](request: Request[A], block: (Request[A]) => Future[Result]) = {
    val start = System.currentTimeMillis

    Logger.info(s"""Request:
      id=${request.id} 
      method=${request.method} 
      uri=${request.uri} 
      remote-address=${request.remoteAddress} 
      body=${request.body}
    """)

    val resultFut = block(request)

    resultFut.map {result =>
      val time = System.currentTimeMillis - start
      Result(result.header, result.body &> Enumeratee.map(arrOfBytes => {
        val body = new String(arrOfBytes.map(_.toChar))
        Logger.info(s"""Response:
      id=${request.id} 
      method=${request.method}
      uri=${request.uri}
      delay=${time}ms 
      status=${result.header.status}
      body=${body}""")
        arrOfBytes
      }), result.connection)
    }
  }
}

I partly learned it from here (on how to get the byte array out of enumerator): Scala Play 2.1: Accessing request and response bodies in a filter.

I'm using Play 2.3.7 while the link I gave uses 2.1 (and still uses PlainResult, which no longer exists in 2.3).

Ache

Answer 2

As it appears to me, if you do logging inside result.body &> Enumeratee.map (as suggested in https://mcmap.net/q/1512293/-play-logging-print-response-body-run-over-enumerator-buffer-the-body) and the result body is presented in more than one chunk, then each chunk will be logged independently. You probably don't want this.

I'd implement it like this:

val ret = block(request).flatMap { result =>
  val consume = Iteratee.consume[Array[Byte]]()
  val bodyF = Iteratee.flatten(result.body(consume)).run
  bodyF.map { bodyBytes: Array[Byte] =>
    //
    // Log the body
    //

    result.copy(body = Enumerator(bodyBytes))
  }
}

But be warned: the whole idea of this is to consume all the data from the result.body Enumerator before logging (and return the new Enumerator). So, if the response is big, or you rely on streaming, then it's probably also the thing you don't want.

Naominaor

Answer 3

I used the above answer as a starting point, but noticed that it will only log responses if a body is present. We've adapted it to this:

var responseBody = None:Option[String]  
val captureBody = Enumeratee.map[Array[Byte]](arrOfBytes => {
    val body = new String(arrOfBytes.map(_.toChar))
    responseBody = Some(body)
    arrOfBytes
})
val withLogging = (result.body &> captureBody).onDoneEnumerating({
    logger.debug(.. create message here ..)
})
result.copy(body=withLogging)

Formularize