Add aroundRequest directive which captures complete request / response processing duration

[jrudolph]

Many people have attempted to write an aroundRequest directive that captures the full request / response cycle to precisely measure and log processing times.

It needs to take into regard:

• sending request and response entity out
• timeouts
• exceptions / rejections

It would be good if we would provide this directive out-of-box so there's only one implementation to maintain.

Here are some third-party attempts:

https://medium.com/@krzysztof.ciesielski/i-extended-this-implementation-to-make-it-handle-timeouts-27fefd5b2e23
https://blog.softwaremill.com/measuring-response-time-in-akka-http-7b6312ec70cf

[kstokoz]

Honestly i think this boils down to provide out of the box directives to allow people create proper access logs (see #2181) which would allow connecting request/response, properly handling rejections and timeouts, having callbacks for measuring response times for SLAs (last byte in-fist byte out, last byte in - last byte out).
Existing logRequestResult directive is not flexible enough.

In my current project we have similar to linked custom directives to write access logs, it would be quite convenient to have it out of the box. I think for any enterprise proper access logs is a must.

[patriknw]

We can go ahead with this.

[kstokoz]

For example server idle timeout which is happening outside of routes are not even reported correctly right now.

For put/post requests when entity idle timeout is triggered original HttpIdleTimeoutException is lost in debug log and in handleExceptions receives akka.http.scaladsl.model.EntityStreamException: Entity stream truncation

[kstokoz]

It would be also great to be able to log requests rejected by GracefulTerminatorStage during shutdown.

[jrudolph]

Thanks, @kstokoz, these are all good points.

We have two issues here:

• On which level and how to gather this information
• What the API should be to access this information

The original suggestion was to write a directive similar to the ones listed in the blog posts above. However, it will be quite hard to incorporate the features you suggested as a directive.

[kstokoz]

@jrudolph i would agree that with current implementation addressing all of cases can be problematic.
In current project we have something similar to the suggested around directive + combination of exception handlers + timeout handlers - i can cover most of the mentioned cases and manage to write access log entry. Only which is fully out of our control is requests rejected during termination.

It would be really awesome if akka would either provided out of the box directive for all of them or ability to register a callback to write access log, if not as a part of this issue though.

[ssgao]

The examples provided here won't really capture the full response time. It only captures the time right before the response starts streaming. That's more of a first byte time. A full response time should include the time it takes for the client to receive it. So far I haven't found a way to capture that. Would be interested to know if anyone knows.

[mantisMolloy]

I have a PR which I think addresses this use case. It handles last byte time as well @ssgao .

Any and all feedback on approach taken welcomed.

#2814

[mantisMolloy]

@ssgao is correct. The approach taken in #2814 will capture the timing for first byte sent on non-chunked responses. For chunked responses it will capture the time to first byte of the last sent chunk.

[shestero]

I'm sorry, but is possible to force a response to be chunked and just send at the end an empty chunk? In the most of HTTP use cases it's ok to send a space or zero byte at the end.
PS This is a dirty workaround but we users need a solution.

[piotrp]

For people that got here while looking for logging with response bytes, a third-party attempt:
https://github.com/derekwyatt/ahalog/blob/master/src/main/scala/org/derekwyatt/ahalog/AhaLogDirectives.scala

[mantisMolloy]

Hey @Crack, thanks for the new example. I tested it out. It looks like it works well for it's intended purpose of capturing entity size 👍

However, the onComplete function will be applied on first-byte out and not last-byte so will not capture full response time if anyone is looking for that.

[sdehors-ibm]

Hi, is #2814 the final answer to the problem? @kstokoz do you expect to merge it ?