How does one log Akka HTTP client requests

问题:

I need to log akka http client requests as well as their responses. While there seems to be a hint of API for logging these requests, there is no clear documentation on how it should be done. My approach has been to create a logged request which transparently wraps Http().singleRequest(req) as follows:

def loggedRequest(req: HttpRequest)
                  (implicit system: ActorSystem, ctx: ExecutionContext, m: Materializer): Future[HttpResponse] = {

  Http().singleRequest(req).map { resp ⇒
    Unmarshal(resp.entity).to[String].foreach{s ⇒
      system.log.info(req.toString)
      system.log.info(resp.toString + "\n" + s)
    }
    resp
  }
}

Unfortunately, I have to grab the future either through the unmarshal or by simply requesting resp.entity.dataBytes in order to recover the body of the response. I get the logging but the promise gets completed and I can no longer unmarshal the entity to the actual data. A working solution would log the request and response and pass this test case without an IllegalStateException with "Promise already completed" being thrown:

describe("Logged rest requests") {

  it("deliver typed responses") {
    val foo = Rest.loggedRequest(Get(s"http://127.0.0.1:9000/some/path"))
    val resp = foo.futureValue(patience)
    resp.status shouldBe StatusCodes.OK
    val res = Unmarshal(resp.entity).to[MyClass].futureValue
  }
}

Ideas welcome.

回答1:

One of the solution I've found is to use a:

import akka.http.scaladsl.server.directives.DebuggingDirectives

val clientRouteLogged = DebuggingDirectives.logRequestResult("Client ReST", Logging.InfoLevel)(clientRoute)
Http().bindAndHandle(clientRouteLogged, interface, port)

Which can easily log the request and result in raw(bytes) format. The problem is that those logs are completely unreadable. And here is place where it became complicated.

Here is my example that encode the entity of the request/response and write it to the logger.

You can pass a function to:

DebuggingDirectives.logRequestResult

def logRequestResult(magnet: LoggingMagnet[HttpRequest ⇒ RouteResult ⇒ Unit])

That is function written using magnet pattern:

LoggingMagnet[HttpRequest ⇒ RouteResult ⇒ Unit]

Where:

LoggingMagnet[T](f: LoggingAdapter ⇒ T)

Thanks to that we have access to all parts that we need to log the request and result. We have LoggingAdapter, HttpRequest and RouteResult

In my case I've create an inside function. I don't want to pass all the parameters again.

def logRequestResult(level: LogLevel, route: Route)
                      (implicit m: Materializer, ex: ExecutionContext) = {
  def myLoggingFunction(logger: LoggingAdapter)(req: HttpRequest)(res: Any): Unit = {
    val entry = res match {
      case Complete(resp) =>
        entityAsString(resp.entity).map(data ⇒ LogEntry(s"${req.method} ${req.uri}: ${resp.status} \n entity: $data", level))
      case other =>
        Future.successful(LogEntry(s"$other", level))
    }
    entry.map(_.logTo(logger))
  }
  DebuggingDirectives.logRequestResult(LoggingMagnet(log => myLoggingFunction(log)))(route)
}

The most important part is the last line where I put myLoggingFunction in to logRequestResult.

The function called myLoggingFunction, simple matched the result of server computation and create a LogEntry based on it.

The last thing is a method that allows to decode the result entity from a stream.

def entityAsString(entity: HttpEntity)
                   (implicit m: Materializer, ex: ExecutionContext): Future[String] = {
entity.dataBytes
  .map(_.decodeString(entity.contentType().charset().value))
  .runWith(Sink.head)
}

The method can be easily add to any akka-http route.

val myLoggedRoute = logRequestResult(Logging.InfoLevel, clinetRoute)
Http().bindAndHandle(myLoggedRoute, interface, port)

回答2:

For another solution, this code logs the request IP and associates a random number with each request and response so they can be associated in the logs. It also records the response time.

Since the request may take awhile to process, and may fail, I wanted to see the request immediately, and see the response if and when it returns.

RequestFields is just the data I care about from the request. There's a lot of noise by default.

val logRequestResponse: Directive0 =
  extractRequestContext flatMap { ctx =>
    extractClientIP flatMap { ip =>
      val id = scala.math.abs(rand.nextLong).toString
      onSuccess(RequestFields.fromIdIpAndRequest(id, ip, ctx.request)) flatMap { req =>
        logger.info("request", req.asJson)
        val i = Instant.now()
        mapRouteResultWith { result => 
          Result.fromIdStartTimeAndRouteResult(id, i, result) map { res =>
            logger.info("response", res.asJson)
            result
        }
      }
    }
  }
}

回答3:

My complete solution, inspired by @seanmcl

trait TraceDirectives extends LazyLogging {

  private val counter: AtomicLong = new AtomicLong(0)

  def log: Directive0 = count flatMap { requestId =>
    mapInnerRoute(addLoggingToRoute(requestId, _))
  }

  private def count: Directive1[Long] = Directive { innerRouteSupplier =>
    ctx =>
      innerRouteSupplier(Tuple1(counter.incrementAndGet()))(ctx)
  }

  private def addLoggingToRoute(requestId: Long, innerRoute: Route): Route = {
    ctx => {
      val requestStopwatch = Stopwatch.createStarted()
      extractClientIP { ip =>
        logger.info("Http request, id: {}, uri: {}, forwarded ip: {}", requestId, ctx.request.uri, ip)
        mapResponse(httpResponse => {
          logger.info("Http response, id: {}, code: {}, time: {}", requestId, httpResponse.status.intValue(), requestStopwatch.toString)
          httpResponse
        })(innerRoute)
      }(ctx)
    }
  }
}

object TraceDirectives extends TraceDirectives