Request time not logged in access.log

[blsouthr]

Describe the bug
I used documentation to configure access.log and modified combined format to include time taken to process request %D or %{RESPONSE_TIME} or %T

quarkus.http.access-log.pattern=%{REMOTE_HOST} %l %{REMOTE_USER} %{DATE_TIME} "%{REQUEST_LINE}" %{RESPONSE_CODE} %b %{RESPONSE_TIME} %T

The output:
2020-11-05 10:16:04,569 INFO [io.qua.htt.access-log] (executor-thread-174) 127.0.0.1 - - 05/Nov/2020:10:16:04 +0100 "GET /api HTTP/1.1" 200 17 - -

As you can see, last two entries are empty.

Btw, what is %l config option? There is no description in the documentation, but it is used in combined format

[gsmet]

/cc @stuartwdouglas

[andrerigon]

We are seeing the same problem here.

[gsmet]

Could you post the list of extensions printed at startup so that we know more about your setups? Thanks!

[blsouthr]

@gsmet

[cdi, mailer, mutiny, qute, resteasy, resteasy-jackson, scheduler, smallrye-context-propagation, smallrye-fault-tolerance, smallrye-health, smallrye-metrics, vertx]

I don't have mutiny, qute in pom.xml

[andrerigon]

[cdi, hibernate-validator, kotlin, micrometer, mutiny, redis-client, resteasy, resteasy-jackson, resteasy-mutiny, scheduler, smallrye-context-propagation, smallrye-fault-tolerance, smallrye-health, vertx, vertx-web]

[jaikiran]

Hello @blsouthr,

Btw, what is %l config option? There is no description in the documentation, but it is used in combined format

As per the javadoc on the relevant class[1], it stands for:

Remote logical username from identd (always returns '-')

[1] https://github.com/quarkusio/quarkus/blob/master/extensions/vertx-http/runtime/src/main/java/io/quarkus/vertx/http/runtime/filters/accesslog/AccessLogHandler.java#L50

[jaikiran]

Hello @blsouthr, @andrerigon,

Looking at the code in the ResponseTimeAttribute[1] which is responsible for providing the response time value, it requires the request start time to be set in the exchange. The HTTP configuration of Quarkus, by defaults disables it[2]. Can you add the following to your application.properties file and see if it works:

quarkus.http.record-request-start-time=true

[1] https://github.com/quarkusio/quarkus/blob/master/extensions/vertx-http/runtime/src/main/java/io/quarkus/vertx/http/runtime/attribute/ResponseTimeAttribute.java#L30
[2] https://github.com/quarkusio/quarkus/blob/master/extensions/vertx-http/runtime/src/main/java/io/quarkus/vertx/http/runtime/HttpConfiguration.java#L196

[gsmet]

I wonder if we could at least raise a warning in this case. And in any case, we would need a mention in the table here: https://quarkus.io/guides/http-reference#configuring-http-access-logs as it's not exactly obvious :).

[blsouthr]

Hi @jaikiran

quarkus.http.record-request-start-time=true

solved the problem. Thanks!

[andrerigon]

Hi @jaikiran,

solved for me too. Thanks!

[ebullient]

Can this be closed?

[jaikiran]

Sorry, the linked PR is still open and I need to fix that review commetns that gsmet asked for.

[geoand]

Closing as #35588 was merged