[undertow-dev] Better logging for predicates
Brad Wood
bdw429s at gmail.com
Sat Jul 25 16:42:03 EDT 2020
Here is the ticket and pull request for the logging improvements discussed
in this thread:
https://issues.redhat.com/browse/UNDERTOW-1753
https://github.com/undertow-io/undertow/pull/911
Thanks!
~Brad
*Developer Advocate*
*Ortus Solutions, Corp *
E-mail: brad at coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
On Wed, Jun 24, 2020 at 11:24 AM Brad Wood <bdw429s at gmail.com> wrote:
> Interesting thoughts Bill. My first thought was it sounded overbuilt for
> what I needed. My next thought (after reading the docs you linked to) was
> this is actually pretty cool and I like the idea of sending back timing
> information in the headers. Then my third thought was, meh-- this could
> take a quick addition of some basic logging and turn it into a huge project
> that I'm unlikely to have the time to complete. :-)
>
> The listeners seem very powerful, and I'm a fan of the interceptor pattern
> myself (even though my primary language is CFML, not Java). That aside,
> the most compelling idea was the thought of keeping the messages all
> together. The way I typically deal with logging messages from different
> threads overlapping is... to not test more than one thread at a time! :)
> In my ideal world, a "debug" level of logging for an HTTP request should
> just be a single line of logs noting what the request did such as getting
> rewritten, etc. If I dial in trace logging, I usually hit a single request
> and then pause while I do a deep dive into the logging it generated. Not
> super ideal, I realize, but it allows me to use a simple logging approach.
> I typically do something like add in some details about the exchange to
> each entry so you have a rudimentary way to match log lines from the same
> request. i.e.
>
>
>>
>> *[TRACE] io.undertow.predicate: Predicate [path( "/foo" )] resolved to
>> false for HttpServerExchange{ GET /box.json}.[TRACE] io.undertow.predicate:
>> Predicate [path( "/box.json" )] resolved to true. Next handler is
>> [reponse-code( 404 )] for HttpServerExchange{ GET /box.json}.[DEBUG]
>> io.undertow.predicate: Response code set to [404] for HttpServerExchange{
>> GET /box.json}.*
>
>
>> *[TRACE] io.undertow.predicate: Predicate [path( "/bar" )] resolved to
>> true. Next handler is [rewrite( '/' )] for HttpServerExchange{ GET
>> /bar}.[DEBUG] io.undertow.predicate: Request rewritten to [/] for
>> HttpServerExchange{ GET /bar}. *
>
>
> *(This is actually real output from my test server using the code in the
> public fork I mentioned in my previous message)*
>
> I am intrigued at what it would look like to store entries inside the
> exchange that tracked timings, predicate behaviors, etc and then turn them
> into a single log entry at the end. Unless that's something Stuart wants
> to broach, I'm unlikely to dive into it myself for lack of time and lack of
> direction on the appropriate internals to fiddle with.
>
> would not need to override toString().
>
>
> It would still be necessary to not only be able to create a text
> representation of handlers, predicates, and exchangeAttributes, but to be
> able to do so externally and with backwards compatibility. This is because
> not all the logging I'm interested in comes from inside the handlers or
> predicates themselves, but from the PredicatesHandler which controls the
> flow of execution and has a bird's eye view of what's happening and the
> context that surrounds it. Take a look at the second-to-last log line in
> my example above for /bar. That single line combines textual
> representations of the HTTP exchange, a predicate, a handler, AND
> the ConstantExchangeAttribute used by the handler. That log line is also
> logged from the PredicatesHandler where it understands the context of where
> the flow is coming from and where the flow is going.
>
> Thanks!
>
> ~Brad
>
> *Developer Advocate*
> *Ortus Solutions, Corp *
>
> E-mail: brad at coldbox.org
> ColdBox Platform: http://www.coldbox.org
> Blog: http://www.codersrevolution.com
>
>
>
> On Wed, Jun 24, 2020 at 6:09 AM Bill O'Neil <bill at dartalley.com> wrote:
>
>> Another option that might be a little more involved but could be more
>> beneficial is to create a custom attribute containing a StringBuilder or
>> some form of logging context.
>>
>> Every predicate would then append a message to the value stored in this
>> custom attribute instead of individually logging its own messages and would
>> not need to override toString(). The challenge would be you need a new
>> handler whose responsibility is to actually log out the message at the end.
>> This gives a benefit where each request will only have a single request
>> logging context logged as a single log entry. Otherwise, if you have
>> concurrent requests running it could be challenging to pick apart the full
>> context of the request you are interested in since its logs will be
>> interleaved with many other logs. It would also be nice to make this
>> functionality have timing and allow all handlers to opt-in.
>>
>> Jersey handles this logging in a unique way where the trace context is
>> sent back as an HTTP header for your request and looks like this.
>>
>> 1 $ curl -i http://localhost:9998/ALL/root/sub-resource-locator/sub-resource-method -H content-type:application/x-jersey-test --data '-=#[LKR]#=-' -H X-Jersey-Tracing-Threshold:SUMMARY -H accept:application/x-jersey-test -X POST
>> 2
>> 3 X-Jersey-Tracing-000: START [ ---- / ---- ms | ---- %] baseUri=[http://localhost:9998/ALL/] requestUri=[http://localhost:9998/ALL/root/sub-resource-locator/sub-resource-method] method=[POST] authScheme=[n/a] accept=[application/x-jersey-test] accept-encoding=n/a accept-charset=n/a accept-language=n/a content-type=[application/x-jersey-test] content-length=[11]
>> 4 X-Jersey-Tracing-001: PRE-MATCH [ 0.01 / 0.68 ms | 0.01 %] PreMatchRequest summary: 2 filters
>> 5 X-Jersey-Tracing-002: MATCH [ 8.44 / 9.15 ms | 4.59 %] RequestMatching summary
>> 6 X-Jersey-Tracing-003: REQ-FILTER [ 0.01 / 9.20 ms | 0.00 %] Request summary: 2 filters
>> 7 X-Jersey-Tracing-004: RI [86.14 / 95.49 ms | 46.87 %] ReadFrom summary: 3 interceptors
>> 8 X-Jersey-Tracing-005: INVOKE [ 0.04 / 95.70 ms | 0.02 %] Resource [org.glassfish.jersey.tests.integration.tracing.SubResource @901a4f3] method=[public org.glassfish.jersey.tests.integration.tracing.Message org.glassfish.jersey.tests.integration.tracing.SubResource.postSub(org.glassfish.jersey.tests.integration.tracing.Message)]
>> 9 X-Jersey-Tracing-006: RESP-FILTER [ 0.01 / 96.55 ms | 0.00 %] Response summary: 2 filters
>> 10 X-Jersey-Tracing-007: WI [85.95 / 183.69 ms | 46.77 %] WriteTo summary: 4 interceptors
>> 11 X-Jersey-Tracing-008: FINISHED [ ---- / 183.79 ms | ---- %] Response status: 200/SUCCESSFUL|OK
>>
>> There is also a more verbose mode that gives more detail on every filter
>> invoked.
>>
>> See https://docs.huihoo.com/jersey/2.13/monitoring_tracing.html
>>
>> Jersey has a much more rigid set of interfaces which makes it a little
>> easier to automatically generate this type of logging. Undertow offers much
>> more flexibility but that means figuring out how to properly append logs
>> will be a much more manual process.
>>
>>
>> On Wed, Jun 24, 2020 at 1:11 AM Brad Wood <bdw429s at gmail.com> wrote:
>>
>>> Thanks for the reply Stuart. I took some time and dug into this today.
>>> I ended up toying with a new logger class called io.undertow.predicate to
>>> be able to isolate the predicate and handler log messages from the other
>>> stuff already in the request logger.
>>>
>>> From what I see, this will work. In order to create useful textual
>>> representations, I'll need to override toString() in all the subclasses of
>>>
>>> - predicate
>>> - handler
>>> - exchangeAttribute
>>>
>>> This is a little tedious, but doable. The nice thing about using
>>> toString() is I don't need to add any methods to the interfaces and it has
>>> a somewhat-useful fallback of just showing the class name of the
>>> predicate/handler.
>>>
>>> What I've been playing with is adding a single debug message to each
>>> handler when it fires that describes what action it has taken on the
>>> request. And then adding a series of trace messages to the
>>> PredicatesHandler that shows every predicate that was tested as well as
>>> other flow control actions like the pseudo "restart" and "done" handlers.
>>> Additionally, trace messages can be added to specific predicates as
>>> necessary to show the runtime values used to resolve them.
>>>
>>> Are there any considerations you'd like me to take into account? For
>>> example, I see other usages of logging check to see if debug/trace is
>>> enabled prior to making the logging calls so I assume you'll want to stick
>>> with that pattern. My initial work is here in this branch of my fork:
>>> https://github.com/Ortus-Solutions/undertow/commits/predicate-logging
>>>
>>> Thanks!
>>>
>>> ~Brad
>>>
>>> *Developer Advocate*
>>> *Ortus Solutions, Corp *
>>>
>>> E-mail: brad at coldbox.org
>>> ColdBox Platform: http://www.coldbox.org
>>> Blog: http://www.codersrevolution.com
>>>
>>>
>>>
>>> On Tue, Jun 23, 2020 at 11:02 PM Stuart Douglas <sdouglas at redhat.com>
>>> wrote:
>>>
>>>> This sounds like a good idea to me.
>>>>
>>>> Stuart
>>>>
>>>> On Wed, 24 Jun 2020 at 05:53, Brad Wood <bdw429s at gmail.com> wrote:
>>>>
>>>>> I've been using Tuckey Rewrites for a long time and one of my favorite
>>>>> things about it is the very rich amount of debug and trace logging
>>>>> information it has. There's not another rewrite engine out there I've seen
>>>>> that makes it this easy to debug what's happening. The trace level logging
>>>>> gives you a full blow-by-blow of each rule that's processed, what the input
>>>>> was, and what the result of each condition was.
>>>>>
>>>>> As much as I love Undertow's predicates and handlers, the logging is,
>>>>> well, abysmal :) I'd like to do some work to improve what gets sent to the
>>>>> request_logger for debugging the predicates and handlers that fire for a
>>>>> request as part of the PredicatesHandler. My high-level approach is as
>>>>> follows:
>>>>>
>>>>> - Override the toString() method in each of the built-in
>>>>> predicates and handlers to create a basic text representation of them that
>>>>> isn't too far from the predicate language.
>>>>> - Add logging at key points in the PredicatesHandler that captures
>>>>> each predicate as it is evaluated as well as the result of that predicate
>>>>> and the next handler to be invoked.
>>>>> - I'd probably say a single debug log entry for every matched
>>>>> predicate for basic high-level debugging of predicates that had some sort
>>>>> of effect on the request.
>>>>> - And then a trace log entry with all the juicy details of each
>>>>> predicate whether it was matched or not for debugging why predicates aren't
>>>>> working correctly
>>>>>
>>>>> So again, I'm offering to work on this and contribute it to Undertow
>>>>> as a pull, but I'd like some feedback on my idea and a general sanity check
>>>>> on whether I'm wasting my time here. Well, honestly, I'll probably do the
>>>>> work regardless because the user's of my Undertow-powered tool will need
>>>>> it, but I'd like to know if these improvements would be welcomed into the
>>>>> core.
>>>>>
>>>>> Thanks!
>>>>>
>>>>> ~Brad
>>>>>
>>>>> *Developer Advocate*
>>>>> *Ortus Solutions, Corp *
>>>>>
>>>>> E-mail: brad at coldbox.org
>>>>> ColdBox Platform: http://www.coldbox.org
>>>>> Blog: http://www.codersrevolution.com
>>>>>
>>>>> _______________________________________________
>>>>> undertow-dev mailing list
>>>>> undertow-dev at lists.jboss.org
>>>>> https://lists.jboss.org/mailman/listinfo/undertow-dev
>>>>
>>>> _______________________________________________
>>> undertow-dev mailing list
>>> undertow-dev at lists.jboss.org
>>> https://lists.jboss.org/mailman/listinfo/undertow-dev
>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/undertow-dev/attachments/20200725/24eb637b/attachment-0001.html
More information about the undertow-dev
mailing list