Display HTTP request contents in the log in a long format

[gastaldi]

It would be nice if we could enable a log of the request that comes to Quarkus and check the headers, method, path of the request, something like a verbose mode of curl.

UPDATE

Access log is already implemented in #5556 / 7b9c133 and was released in 1.4.0.Final, so this issue is about displaying the HTTP contents in a long format, like:

GET /hello HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Connection: keep-alive
Host: localhost:8080

As suggested by @stuartwdouglas, the idea is to add a 'dump' or 'full' option to the config and an attribute that prints all the headers and have the 'dump' format string print the request line followed by the headers

[hbelmiro]

Hello @gastaldi. Could you please show me the way? This would be my first contribution to the project.

[gastaldi]

@hbelmiro I think a Filter would do the job

[hbelmiro]

Does it need to be specific implementations for each extension or can we create a common filter that will be used by all of them? I prefer the second option, but I don't know if it is possible.

[gastaldi]

Since Undertow uses Vert.x, I think a Vert.x filter should be enough.

[hbelmiro]

@gastaldi I created these three classes:

• https://github.com/hbelmiro/quarkus/blob/8656/extensions/vertx-http/deployment/src/main/java/io/quarkus/vertx/http/deployment/HttpLoggingProcessor.java

• https://github.com/hbelmiro/quarkus/blob/8656/extensions/vertx-http/runtime/src/main/java/io/quarkus/vertx/http/runtime/HttpLoggingHandler.java

• https://github.com/hbelmiro/quarkus/blob/8656/extensions/vertx-http/runtime/src/main/java/io/quarkus/vertx/http/runtime/HttpLogMessage.java

It's logging like following:

2020-07-07 10:15:16,096 INFO [io.qua.ver.htt.run.HttpLoggingHandler] (vert.x-eventloop-thread-23) HTTP request: [headers={Cookie=Idea-a570dfe6=a4b7a29f-b7b6-4ea1-9683-e21229918e12, Accept=application/json, text/plain, */*, Connection=keep-alive, User-Agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/13.1.1 Safari/605.1.15, Referer=http://localhost:8080/fruits.html, Host=localhost:8080, Accept-Language=en-us, Accept-Encoding=gzip, deflate}, method='GET', path='/fruits']

Is that what you're wondering or I can log something else?

Besides that, I have another few questions:

• How will the user enable the log? Will he use a property in application.properties?
• In HttpLoggingProcessor class I used FilterBuildItem.AUTHENTICATION. What would be the right priority? Should I use one of the three priority constants in FilterBuildItem class or I must create a new one? If I must create a new one, what would be its value?

[gastaldi]

@hbelmiro that looks nice. TBH I was expecting an output similar to the HTTP request:

GET /hello HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Connection: keep-alive
Host: localhost:8080

How will the user enable the log? Will he use a property in application.properties?

Yes, a property in application.properties is a good solution IMHO

In HttpLoggingProcessor class I used FilterBuildItem.AUTHENTICATION. What would be the right priority? Should I use one of the three priority constants in FilterBuildItem class or I must create a new one? If I must create a new one, what would be its value?

I think it should happen before AUTHENTICATION.

[hbelmiro]

@gastaldi I changed the format to:

2020-07-07 17:21:54,959 INFO  [io.qua.ver.htt.run.log.HttpLoggingHandler] (vert.x-eventloop-thread-20) HTTP request:
GET /boom HTTP/1.1
Accept: */*
Connection: Keep-Alive
User-Agent: Apache-HttpClient/4.5.12 (Java/13.0.2)
Host: localhost:8081
Accept-Encoding: gzip,deflate

I couldn't find a way to inject this HttpRequestFormatter in HttpLoggingHandler class.
https://github.com/hbelmiro/quarkus/blob/e23102e3cea0be73fc742d989f63639071d4c7fb/extensions/vertx-http/runtime/src/main/java/io/quarkus/vertx/http/runtime/logging/HttpLoggingHandler.java#L16

I tried in several ways, but none of them worked. Do you know what is the right way to inject a dependency in my Handler?

[gastaldi]

@hbelmiro I think Vert.x already has a feature to log requests. Look for Request logger in https://vertx.io/docs/vertx-web/js/ and see if it's possible to enable that instead of writing your own

[hbelmiro]

@gastaldi It works with io.vertx.ext.web.handler.LoggerHandler.
Unfortunately the API allow us to use only three fixed formats:

DEFAULT
2020-07-07 20:58:57,623 INFO [io.ver.ext.web.han.imp.LoggerHandlerImpl] (executor-thread-1) 0:0:0:0:0:0:0:1 - - [Tue, 7 Jul 2020 23:58:57 GMT] "GET /fruits HTTP/1.1" 200 99 "http://localhost:8080/fruits.html" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/13.1.1 Safari/605.1.15"

SHORT
2020-07-07 21:07:54,845 INFO [io.ver.ext.web.han.imp.LoggerHandlerImpl] (executor-thread-1) 0:0:0:0:0:0:0:1 - GET /fruits HTTP/1.1 200 99 - 99 ms

TINY
2020-07-07 21:09:10,338 INFO [io.ver.ext.web.han.imp.LoggerHandlerImpl] (executor-thread-1) GET /fruits 200 99 - 87 ms

We could allow the user to choose a format by application.properties, or else the "DEFAULT" format would be used.

[gastaldi]

+1, I think we could even propose a LONG format with the layout as in #8656 (comment). That custom formatter could live in Quarkus for now, but it would ideally need to go upstream (in Vert.x Web sources - https://github.com/vert-x3/vertx-web)

[hbelmiro]

@gastaldi I submitted the PR 10590.

[gastaldi]

@hbelmiro hey, thanks for the hard work! As @stuartwdouglas pointed out in this feature is already implemented, it just doesn't display the long format as you have implemented. Would you mind changing your PR (or opening a new one) with that dump feature implemented?

Sorry about the noise, totally my fault. I should have seen that #5556 was already implemented.

[gastaldi]

BTW I have updated the issue description

[hbelmiro]

@gastaldi No problem. These things happen.
I'll try to add the long format in the existing code.

[hbelmiro]

@gastaldi Today there are two formats that can be used: "common" and "combined".
We will create the third one (long):

        if (formatString.equals("common")) {
            return "%h %l %u %t \"%r\" %s %b";
        } else if (formatString.equals("combined")) {
            return "%h %l %u %t \"%r\" %s %b \"%{i,Referer}\" \"%{i,User-Agent}\"";
        } else if (formatString.equals("long")) {
            // return our new long format
        }

So we need to create the new format using the attributes defined in this table

But there isn't an attribute for all headers. The existing attribute is for a specific header: %{i,request_header_name}.

If we decide to create a new one, we'll also have to create a way to format them, since those attributes are used for other things too.

In our case, for example, we want to print this way:

header1: header1_value
header2: header2_value
header3: header3_value

But there might be cases where the user needs to print them like this, for example:

header1=header1_value, header2=header2_value, header3=header3_value

Would you like to discuss this with someone else before we decide anything?

[stuartwdouglas]

I would add %{ALL_HEADERS} that dumps it in the one per line format. If there is a request for the single line format we can look at it later.

[hbelmiro]

What about %{ALL_REQUEST_HEADERS}? Or should %{ALL_HEADERS} dump the response ones too?

[stuartwdouglas]

All request headers is probably best.

…

On Fri, 10 Jul 2020, 11:54 pm Helber Belmiro, ***@***.***> wrote: What about %{ALL_REQUEST_HEADERS}? Or should %{ALL_HEADERS} dump the response ones too? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#8656 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AACQG64M274PZY4RHLQ7OB3R24MPHANCNFSM4MK3KHEQ> .

[hbelmiro]

New PR created (10654).

[hbelmiro]

@gastaldi I updated the PR. I couldn't find a way to display the request body because it isn't available when the attributes are read.