How to configure logback to get nice logs of akka-http logRequest event

As a result of the answer to this question I am able to get logRequest to log to a file called access.log.

I have

val routes =
      path("ping" ) {
        withLog(accessLog) {
          logRequest("ping", Logging.InfoLevel) {
            complete("pong")
          }
        }
      }

Part of my logback.xml configuration looks like

 <appender name="ACCESSLOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>log/access.log</file>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>
                %d{yyyy-MM-dd HH:mm:ss} %msg%n
            </pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>log/access-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>64 MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
    </appender>

And the resulting entry in the log file looks like

2019-02-06 16:51:04 ping: HttpRequest(HttpMethod(GET),http://localhost:8080/ping,List(Host: localhost:8080, Connection: keep-alive, Cache-Control: max-age=0, Upgrade-Insecure-Requests: 1, User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36, Accept: text/html, application/xhtml+xml, application/xml;q=0.9, image/webp, image/apng, */*;q=0.8, Accept-Encoding: gzip, deflate, br, Accept-Language: en-GB, en-US;q=0.9, en;q=0.8, Cookie: xxx, Timeout-Access: <function1>),HttpEntity.Strict(none/none,ByteString()),HttpProtocol(HTTP/1.1))

What can I do to get my log entries to look something like

2019-02-06 16:51:04 GET /ping <time_taken>

Solution

You can define a method that will produce a LogEntry and you set your log message in the way you want.

  def myLogEntry(req: HttpRequest): LogEntry = {
    LogEntry(s"${req.method} /${req.uri.path}", Logging.InfoLevel)
  }

  logRequest(myLogEntry _) {
    complete("pong")
  }

The problem is with information like <time_taken> as it's not available when directive logRequest is executed. This directive prints log message on incoming http request when directive is triggered. There is no information yet for the inner route result, completed or rejected.

Check out this blog post to see how time can be calculated.