You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by Gary Gregory <ga...@gmail.com> on 2016/02/14 03:04:15 UTC
Better flow logging
Hi All:
I master now, I am almost able to duplicate what my custom flow logger does.
We can do this:
public int zoo(Path p1, String s1) {
EntryMessage m = logger.traceEntry("zoo(p1={}, p2={})", p1, s1);
...
if (...) {
return traceExit(x, m);
}
...
return traceExit(c, m);
}
which is nice. I am perfectly OK with writing in the method name by hand,
that's just a convention we have established at work, and it costs 0 at
runtime. Also, it can be weaved in when @LogFlow is implemented, and still
would cost 0 at runtime of course.
I describe the @LogFlow annotation in:
https://issues.apache.org/jira/browse/LOG4J2-33?focusedCommentId=15145841&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-15145841
In our app, we have some multi-threaded use cases, so it becomes important
to know /which/ object does what, not just what API is being
entered/exited.
My flow logging looks like this with:
<Pattern>%d %-5level [%t][%logger] %msg%n%throwable</Pattern>
2016-02-13 17:45:09,247 TRACE
[main][com.rs.jdbc.dv.DvSocketConnection.com.rocketsoftware.rs28.1292]
Enter DvSocketConnection@4ecf3c56.setTimeout(socket=7a6a25ab[TLS_RSA_WITH_AES_128_CBC_SHA:
Socket[addr=rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424]],
milliseconds=0, prevMillis=0)
2016-02-13 17:45:09,247 TRACE
[main][com.rs.jdbc.dv.DvSocketConnection.com.rocketsoftware.rs28.1292] Exit
DvSocketConnection@4ecf3c56.setTimeout(socket=7a6a25ab[TLS_RSA_WITH_AES_128_CBC_SHA:
Socket[addr=rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424]],
milliseconds=0, prevMillis=0) : 0
Our custom logger call site looks like this:
String m = logger.traceEntry(*this*, "zoo(p1={}, p2={})", p1, s1);
Note that "this" is passed in as a first argument, which my message builder
turns into the same format Object.toString() uses but with the class'
simple name: simpleName@hexHashCode.
Which gives us an flow message that looks like:
Enter *DvSocketConnection@4ecf3c56*.setTimeout(foo=1, bar=2)
Exit *DvSocketConnection@4ecf3c56*.setTimeout(foo=1, bar=2)
I do not use the this' toString() method because who knows what that will
give me, so I always use simpleName@hexHashCode which allows me to clearly
ID who does what. This has proved invaluable in debugging.
I would like to allow for this use case with our new traceEntry() APIs. We
could make the code generate "method(...)" vs. "simpleName@hexHash.method()"
depending on whether the value passed in is null vs. an Object. For example:
EntryMessage m = logger.traceEntry(*this*, "zoo(p1={}, p2={})", p1, s1);
vs.
EntryMessage m = logger.traceEntry(*null*, "zoo(p1={}, p2={})", p1, s1);
In order to do this I need to add an Object param to existing traceEntry()
methods. But I do not want to add yet more methods, to account for
traceEntry(Object, String, Object...) vs traceEntry(String, Object...), so
it would be just traceEntry(Object, String, Object...).
Thoughts?
Gary
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
<http://www.manning.com/bauer3/>
JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
Spring Batch in Action <http://www.manning.com/templier/>
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Better flow logging
Posted by Ralph Goers <ra...@dslextreme.com>.
Well, this is where I currently rely on location information. The only problem I had with the existing methods is that sometimes the parameters being logged at entry or exit need to be formatted (for example gson->toJson(response)).
I dislike immensely having to type in method names and especially line numbers. I would greatly prefer
logger.traceEntry(“p1={}, p2={}”, p1, p2);
logger.traceExit(result);
over what you have. It really seems hokey to me to pass the entry message to the traceExit method.
I am hoping that with Java 9 getting the location information will be much faster so I would hate to bake in your pattern for eternity.
Ralph
> On Feb 15, 2016, at 5:49 PM, Gary Gregory <ga...@gmail.com> wrote:
>
> What you describe is basically what I do now. So we are on the same page. I posted a while back what my custom flow logger class does. I do understand the niche comment as well.
>
> Another way to think about this is: how would you configure class after class, app after app, to do flow logging for multi-threaded apps or when you want to tell apart one object from the next in flow logging?
>
> Gary
>
> On Feb 15, 2016 4:20 PM, "Remko Popma" <remko.popma@gmail.com <ma...@gmail.com>> wrote:
> With all respect, isn't this a very niche use case? I wouldn't want to push this into log4j, sounds like a perfect use case for a custom flow logger, or a custom helper method:
>
> logger.traceEntry("{} zoo(p1={}, p2={})", id(this), p1, s1);
> // id(obj) returns simpleName@hexHashCode
>
>
> Sent from my iPhone
>
> On 2016/02/14, at 11:04, Gary Gregory <garydgregory@gmail.com <ma...@gmail.com>> wrote:
>
>> Hi All:
>>
>> I master now, I am almost able to duplicate what my custom flow logger does.
>>
>> We can do this:
>>
>> public int zoo(Path p1, String s1) {
>> EntryMessage m = logger.traceEntry("zoo(p1={}, p2={})", p1, s1);
>> ...
>> if (...) {
>> return traceExit(x, m);
>> }
>> ...
>> return traceExit(c, m);
>> }
>>
>> which is nice. I am perfectly OK with writing in the method name by hand, that's just a convention we have established at work, and it costs 0 at runtime. Also, it can be weaved in when @LogFlow is implemented, and still would cost 0 at runtime of course.
>>
>> I describe the @LogFlow annotation in:
>>
>> https://issues.apache.org/jira/browse/LOG4J2-33?focusedCommentId=15145841&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-15145841 <https://issues.apache.org/jira/browse/LOG4J2-33?focusedCommentId=15145841&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-15145841>
>>
>> In our app, we have some multi-threaded use cases, so it becomes important to know /which/ object does what, not just what API is being entered/exited.
>>
>> My flow logging looks like this with:
>>
>> <Pattern>%d %-5level [%t][%logger] %msg%n%throwable</Pattern>
>>
>> 2016-02-13 17:45:09,247 TRACE [main][com.rs.jdbc.dv.DvSocketConnection.com.rocketsoftware.rs28.1292] Enter DvSocketConnection@4ecf3c56.setTimeout <ma...@4ecf3c56.settimeout>(socket=7a6a25ab[TLS_RSA_WITH_AES_128_CBC_SHA: Socket[addr=rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424] <http://rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424%5D>], milliseconds=0, prevMillis=0)
>> 2016-02-13 17:45:09,247 TRACE [main][com.rs.jdbc.dv.DvSocketConnection.com.rocketsoftware.rs28.1292] Exit DvSocketConnection@4ecf3c56.setTimeout <ma...@4ecf3c56.settimeout>(socket=7a6a25ab[TLS_RSA_WITH_AES_128_CBC_SHA: Socket[addr=rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424] <http://rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424%5D>], milliseconds=0, prevMillis=0) : 0
>>
>> Our custom logger call site looks like this:
>>
>> String m = logger.traceEntry(this, "zoo(p1={}, p2={})", p1, s1);
>>
>> Note that "this" is passed in as a first argument, which my message builder turns into the same format Object.toString() uses but with the class' simple name: simpleName@hexHashCode.
>>
>> Which gives us an flow message that looks like:
>>
>> Enter DvSocketConnection@4ecf3c56.setTimeout(foo=1, bar=2)
>> Exit DvSocketConnection@4ecf3c56.setTimeout(foo=1, bar=2)
>>
>> I do not use the this' toString() method because who knows what that will give me, so I always use simpleName@hexHashCode which allows me to clearly ID who does what. This has proved invaluable in debugging.
>>
>> I would like to allow for this use case with our new traceEntry() APIs. We could make the code generate "method(...)" vs. "simpleName@hexHash.method <ma...@hexhash.method>()" depending on whether the value passed in is null vs. an Object. For example:
>>
>> EntryMessage m = logger.traceEntry(this, "zoo(p1={}, p2={})", p1, s1);
>> vs.
>> EntryMessage m = logger.traceEntry(null, "zoo(p1={}, p2={})", p1, s1);
>>
>> In order to do this I need to add an Object param to existing traceEntry() methods. But I do not want to add yet more methods, to account for traceEntry(Object, String, Object...) vs traceEntry(String, Object...), so it would be just traceEntry(Object, String, Object...).
>>
>> Thoughts?
>>
>> Gary
>>
>> --
>> E-Mail: garydgregory@gmail.com <ma...@gmail.com> | ggregory@apache.org <ma...@apache.org>
>> Java Persistence with Hibernate, Second Edition <http://www.manning.com/bauer3/>
>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
>> Spring Batch in Action <http://www.manning.com/templier/>
>> Blog: http://garygregory.wordpress.com <http://garygregory.wordpress.com/>
>> Home: http://garygregory.com/ <http://garygregory.com/>
>> Tweet! http://twitter.com/GaryGregory <http://twitter.com/GaryGregory>
Re: Better flow logging
Posted by Gary Gregory <ga...@gmail.com>.
What you describe is basically what I do now. So we are on the same page. I
posted a while back what my custom flow logger class does. I do understand
the niche comment as well.
Another way to think about this is: how would you configure class after
class, app after app, to do flow logging for multi-threaded apps or when
you want to tell apart one object from the next in flow logging?
Gary
On Feb 15, 2016 4:20 PM, "Remko Popma" <re...@gmail.com> wrote:
> With all respect, isn't this a very niche use case? I wouldn't want to
> push this into log4j, sounds like a perfect use case for a custom flow
> logger, or a custom helper method:
>
> logger.traceEntry("{} zoo(p1={}, p2={})", id(this), p1, s1);
> // id(obj) returns simpleName@hexHashCode
>
>
> Sent from my iPhone
>
> On 2016/02/14, at 11:04, Gary Gregory <ga...@gmail.com> wrote:
>
> Hi All:
>
> I master now, I am almost able to duplicate what my custom flow logger
> does.
>
> We can do this:
>
> public int zoo(Path p1, String s1) {
> EntryMessage m = logger.traceEntry("zoo(p1={}, p2={})", p1, s1);
>
> ...
> if (...) {
> return traceExit(x, m);
> }
> ...
> return traceExit(c, m);
> }
>
>
> which is nice. I am perfectly OK with writing in the method name by hand,
> that's just a convention we have established at work, and it costs 0 at
> runtime. Also, it can be weaved in when @LogFlow is implemented, and still
> would cost 0 at runtime of course.
>
> I describe the @LogFlow annotation in:
>
>
> https://issues.apache.org/jira/browse/LOG4J2-33?focusedCommentId=15145841&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-15145841
>
> In our app, we have some multi-threaded use cases, so it becomes important
> to know /which/ object does what, not just what API is being
> entered/exited.
>
> My flow logging looks like this with:
>
> <Pattern>%d %-5level [%t][%logger] %msg%n%throwable</Pattern>
>
> 2016-02-13 17:45:09,247 TRACE
> [main][com.rs.jdbc.dv.DvSocketConnection.com.rocketsoftware.rs28.1292]
> Enter DvSocketConnection@4ecf3c56.setTimeout
> <Dv...@4ecf3c56.settimeout>(socket=7a6a25ab[TLS_RSA_WITH_AES_128_CBC_SHA:
> Socket[addr=
> rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424]
> <http://rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424%5D>],
> milliseconds=0, prevMillis=0)
> 2016-02-13 17:45:09,247 TRACE
> [main][com.rs.jdbc.dv.DvSocketConnection.com.rocketsoftware.rs28.1292] Exit
> DvSocketConnection@4ecf3c56.setTimeout
> <Dv...@4ecf3c56.settimeout>(socket=7a6a25ab[TLS_RSA_WITH_AES_128_CBC_SHA:
> Socket[addr=
> rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424]
> <http://rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424%5D>],
> milliseconds=0, prevMillis=0) : 0
>
> Our custom logger call site looks like this:
>
> String m = logger.traceEntry(*this*, "zoo(p1={}, p2={})", p1, s1);
>
>
> Note that "this" is passed in as a first argument, which my message
> builder turns into the same format Object.toString() uses but with the
> class' simple name: simpleName@hexHashCode.
>
> Which gives us an flow message that looks like:
>
> Enter *DvSocketConnection@4ecf3c56*.setTimeout(foo=1, bar=2)
> Exit *DvSocketConnection@4ecf3c56*.setTimeout(foo=1, bar=2)
>
> I do not use the this' toString() method because who knows what that will
> give me, so I always use simpleName@hexHashCode which allows me to
> clearly ID who does what. This has proved invaluable in debugging.
>
> I would like to allow for this use case with our new traceEntry() APIs. We
> could make the code generate "method(...)" vs. "simpleName@hexHash.method
> <si...@hexhash.method>()" depending on whether the value passed in
> is null vs. an Object. For example:
>
> EntryMessage m = logger.traceEntry(*this*, "zoo(p1={}, p2={})", p1, s1);
>
> vs.
>
> EntryMessage m = logger.traceEntry(*null*, "zoo(p1={}, p2={})", p1, s1);
>
>
> In order to do this I need to add an Object param to existing traceEntry()
> methods. But I do not want to add yet more methods, to account for
> traceEntry(Object, String, Object...) vs traceEntry(String, Object...),
> so it would be just traceEntry(Object, String, Object...).
>
> Thoughts?
>
> Gary
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> Java Persistence with Hibernate, Second Edition
> <http://www.manning.com/bauer3/>
> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
> Spring Batch in Action <http://www.manning.com/templier/>
> Blog: http://garygregory.wordpress.com
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
>
>
Re: Better flow logging
Posted by Remko Popma <re...@gmail.com>.
With all respect, isn't this a very niche use case? I wouldn't want to push this into log4j, sounds like a perfect use case for a custom flow logger, or a custom helper method:
logger.traceEntry("{} zoo(p1={}, p2={})", id(this), p1, s1);
// id(obj) returns simpleName@hexHashCode
Sent from my iPhone
> On 2016/02/14, at 11:04, Gary Gregory <ga...@gmail.com> wrote:
>
> Hi All:
>
> I master now, I am almost able to duplicate what my custom flow logger does.
>
> We can do this:
>
> public int zoo(Path p1, String s1) {
> EntryMessage m = logger.traceEntry("zoo(p1={}, p2={})", p1, s1);
> ...
> if (...) {
> return traceExit(x, m);
> }
> ...
> return traceExit(c, m);
> }
>
> which is nice. I am perfectly OK with writing in the method name by hand, that's just a convention we have established at work, and it costs 0 at runtime. Also, it can be weaved in when @LogFlow is implemented, and still would cost 0 at runtime of course.
>
> I describe the @LogFlow annotation in:
>
> https://issues.apache.org/jira/browse/LOG4J2-33?focusedCommentId=15145841&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-15145841
>
> In our app, we have some multi-threaded use cases, so it becomes important to know /which/ object does what, not just what API is being entered/exited.
>
> My flow logging looks like this with:
>
> <Pattern>%d %-5level [%t][%logger] %msg%n%throwable</Pattern>
>
> 2016-02-13 17:45:09,247 TRACE [main][com.rs.jdbc.dv.DvSocketConnection.com.rocketsoftware.rs28.1292] Enter DvSocketConnection@4ecf3c56.setTimeout(socket=7a6a25ab[TLS_RSA_WITH_AES_128_CBC_SHA: Socket[addr=rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424]], milliseconds=0, prevMillis=0)
> 2016-02-13 17:45:09,247 TRACE [main][com.rs.jdbc.dv.DvSocketConnection.com.rocketsoftware.rs28.1292] Exit DvSocketConnection@4ecf3c56.setTimeout(socket=7a6a25ab[TLS_RSA_WITH_AES_128_CBC_SHA: Socket[addr=rs28.rocketsoftware.com/192.168.55.28,port=1292,localport=52424]], milliseconds=0, prevMillis=0) : 0
>
> Our custom logger call site looks like this:
>
> String m = logger.traceEntry(this, "zoo(p1={}, p2={})", p1, s1);
>
> Note that "this" is passed in as a first argument, which my message builder turns into the same format Object.toString() uses but with the class' simple name: simpleName@hexHashCode.
>
> Which gives us an flow message that looks like:
>
> Enter DvSocketConnection@4ecf3c56.setTimeout(foo=1, bar=2)
> Exit DvSocketConnection@4ecf3c56.setTimeout(foo=1, bar=2)
>
> I do not use the this' toString() method because who knows what that will give me, so I always use simpleName@hexHashCode which allows me to clearly ID who does what. This has proved invaluable in debugging.
>
> I would like to allow for this use case with our new traceEntry() APIs. We could make the code generate "method(...)" vs. "simpleName@hexHash.method()" depending on whether the value passed in is null vs. an Object. For example:
>
> EntryMessage m = logger.traceEntry(this, "zoo(p1={}, p2={})", p1, s1);
> vs.
> EntryMessage m = logger.traceEntry(null, "zoo(p1={}, p2={})", p1, s1);
>
> In order to do this I need to add an Object param to existing traceEntry() methods. But I do not want to add yet more methods, to account for traceEntry(Object, String, Object...) vs traceEntry(String, Object...), so it would be just traceEntry(Object, String, Object...).
>
> Thoughts?
>
> Gary
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> Java Persistence with Hibernate, Second Edition
> JUnit in Action, Second Edition
> Spring Batch in Action
> Blog: http://garygregory.wordpress.com
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory