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
-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
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(a)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(a)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(a)redhat.com>
wrote:
> This sounds like a good idea to me.
>
> Stuart
>
> On Wed, 24 Jun 2020 at 05:53, Brad Wood <bdw429s(a)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(a)coldbox.org
>> ColdBox Platform:
http://www.coldbox.org
>> Blog:
http://www.codersrevolution.com
>>
>> _______________________________________________
>> undertow-dev mailing list
>> undertow-dev(a)lists.jboss.org
>>
https://lists.jboss.org/mailman/listinfo/undertow-dev
>
> _______________________________________________
undertow-dev mailing list
undertow-dev(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/undertow-dev