[undertow-dev] Better logging for predicates
Brad Wood
bdw429s at gmail.com
Wed Jun 24 12:24:14 EDT 2020
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/20200624/78a888c8/attachment-0001.html
More information about the undertow-dev
mailing list