Robert Elliot skrev den 18-11-2008 10:39:

I have an AspectJ project I'm working on to add trace logging via SLF4J on method & constructor entry & exit & variable change. I'll put it up as an enhancement JIRA once I've done a little more work on it.

That would be really nice. Looking forward to seeing your work. -- Thorbjørn Ravn Andersen "...plus... Tubular Bells!"

Thanks - I checked the slf4j-ext project when I started, but not the Subversion repository. I presume this is a post-compile step rather than runtime byte code alteration? A few things I'm implementing in my aspectj based version which you may or may not be interested in: 1) something like a PatternLayout to allow the user to choose the format of the messages at runtime (I prefer single > to double >> for instance on method entry - petty, but I feel it should be up to the user! And it's nice to be able to truncate parameter or return values if they are going to be utterly huge) 2) trace logging of field value changes so you get output like this: fieldName initialValue -> newValue 3) loggers named after the class and method / field name, so you can be more fine grained in what output you get 4) passing the stacktrace to the output (depending on how you configure the pattern) so that if you are interested in what it was that changed the field or called the method you don't need trace logging on for the entire application 5) an @Secure annotation to allow the programmer to mark a parameter or return value as something that should not be accessible via trace logging - e.g. a password Out of curiousity (not criticising!) what was the reason for picking javassist rather than aspectj? Rob ----- Original Message ----- From: "Ralph Goers" <ralph.goers@dslextreme.com> To: "logback developers list" <logback-dev@qos.ch> Sent: Tuesday, 18 November, 2008 3:37:12 PM GMT +00:00 GMT Britain, Ireland, Portugal Subject: Re: [logback-dev] Least-effort logging with bytecode modification You should have a look at the slf4j extensions project first. There is something in development there. Robert Elliot wrote:

I have an AspectJ project I'm working on to add trace logging via SLF4J on method & constructor entry & exit & variable change. I'll put it up as an enhancement JIRA once I've done a little more work on it.

Rob

----- Original Message ----- From: "Thorbjørn Ravn Andersen" <thunderaxiom@gmail.com> To: "logback developers list" <logback-dev@qos.ch> Sent: Saturday, 26 July, 2008 8:50:07 AM GMT +00:00 GMT Britain, Ireland, Portugal Subject: Re: [logback-dev] Least-effort logging with bytecode modification

Ramon Nogueira skrev den 26-07-2008 05:01:

...

I thought of implementing this with AspectJ but its probably easier to just use ASM directly for such a simple case.

Any ideas/suggestions/precedents?

You might find http://today.java.net/pub/a/today/2008/04/24/add-logging-at-class-load-time-... interesting (I wrote it) as it describes how to add entry and exit logging statements to existing code at load time.

_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://qos.ch/mailman/listinfo/logback-dev

Sorry, I guess I was thinking that you could be modifying the byte code as a post compile step, if you see what I mean, but closer inspection of the discussion should have shown me you were talking about instrumentation at runtime. I see the difference as one of problems for the end user. Using instrumentation at runtime requires the end user to alter how they run their JVM - this is always going to add to the complications of getting it running, and may be an insurmountable problem in terms of ever doing it in a production environment, it's the sort of thing that is going to make admin people nervous! I thought the general rule of thumb was that instrumentation is a development rather than a production tool, though perhaps that's a misconception. I wanted something that would give me classes that could just be deployed into an existing production environment without needing to change any startup scripts - aspectj, by operating at compile time, does that. The case for the instrumentation approach, I guess, is that it can be added after the fact without needing to recompile the entire codebase. Also it doesn't require any alteration to your build and the logging isn't embedded in your class files, which may feel cleaner. I very much wanted something like this on my last project to allow debugging of a very intermittent issue that only occured on production, where the programmer inserted log statements weren't helping me out and where even restarting the server, let alone deploying altered code, was going to be painful. In that case the instrumentation method would have been more useful, so perhaps it's the best way. I'm tempted to suggest that having both options would be nice, but on the other hand there's the issue of how they would interact - be a little irritating if you instrumented a class which already had aspect based trace logging. I haven't looked at the slf4j-ext code hard enough to know how configurable it is in terms of which classes get instrumented, though I presume that wouldn't be too difficult to achieve. Rob ----- Original Message ----- From: "Ceki Gulcu" <listid@qos.ch> To: "logback developers list" <logback-dev@qos.ch> Sent: Tuesday, 18 November, 2008 4:23:37 PM GMT +00:00 GMT Britain, Ireland, Portugal Subject: Re: [logback-dev] Least-effort logging with bytecode modification Hello Robert, Robert Elliot wrote:

Thanks - I checked the slf4j-ext project when I started, but not the Subversion repository. I presume this is a post-compile step rather than runtime byte code alteration?

No, the Agent extensions perform byte code engineering at runtime. BTW, the subject of this thread is "Least-effort logging with *bytecode* modification".

Out of curiousity (not criticising!) what was the reason for picking javassist rather than aspectj?

I think the goal was to add logging at runtime. Can you do byte code engineering with AspectJ? I'll let Thorbjørn give a more authoritative answer. It looks like you have already done some work using AspectJ-generateed logging. How useful do you find the results, mildly useful, useful, or very useful? -- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch _______________________________________________ logback-dev mailing list logback-dev@qos.ch http://qos.ch/mailman/listinfo/logback-dev

Ceki Gulcu skrev:

Hello Robert,

Robert Elliot wrote:

...

Thanks - I checked the slf4j-ext project when I started, but not the Subversion repository. I presume this is a post-compile step rather than runtime byte code alteration?

No, the Agent extensions perform byte code engineering at runtime. BTW, the subject of this thread is "Least-effort logging with *bytecode* modification".

The javaagent interface allows bytecode modification on the way through the JVM just before the class loader magically converts the flat bytes to a REAL object. Hence the title is quite fitting (if you know all the dirty details).

...

Out of curiousity (not criticising!) what was the reason for picking javassist rather than aspectj?

I think the goal was to add logging at runtime. Can you do byte code engineering with AspectJ? I'll let Thorbjørn give a more authoritative answer.

I too thought that AspectJ was a compile-time byte code instrumentation, but it was brought to my attention when the article had been published where I made javassist do the work, that it can do classload-time byte code instrumentation too. I then looked somewhat into it, but didn't reach a satisfactory result so I went with what worked for the implementation currently in Subversion. The idea of aspects here and there and everywhere inside Eclipse didn't agree with me (but that is a completely different issue, I think that for _debugging_ purposes aspects are a god send, but not for normal "progress"-logging) so I left it again - I have this puristic approach saying that given a JDK on a freshly installed machine and one of ant or eclipse (and recently maven) available to you - depending on the needs of the project - you should be able to build and deploy your stuff without jumping through hoops to get there. I have a few things to make my life easier but then I try to move them into the distributions of ant or eclipse (and recently maven) to allow the above. This allows me to throw away installations and workspaces easily, and migrate to other machines as it is just another install-configure-build-deploy circle. This spartan way of thinking has worked well for me - others may find it too much work with too little return. It is a matter of taste. I believe that the current java agent in slf4j-ext is great for getting the low fruit - those using slf4j can just include the two jars in their deployments - and if needed add the javaagent to get instant logging. A few more options may be relevant if it can be kept in this very simple current approach (the hard part is getting the information out of the byte code framework), but not more than that. This is not designed to grow to be a full aspect implementation, but it is a great way to SEE the benefit of aspects for _debugging_ (which accidentially also easily extends to _profiling_). At this point of time it would be great if the initial effort to get to instrumented logging with slf4j-ext could lead directly into an AspectJ trail that would start with a script that does exactly the same as the slf4j-ext version, and potentially lead to something much bigger. Frankly I have no idea what _can_ be done, but I believe that one possible outcome could be combining this with the XLogger and the profiling stuff plus a new XMLAppender which can produce output suitable for other tools. I have SEEN descriptions of such XML but I cannot remember where now. It is on my "put a bookmark if it shows up again"-list. Robert, please feel encouraged to present your findings - I'd much rather see some unfinished stuff now than a polished presentation next year - and let us see what you can do :) This might very well be something very useful even though it is very simple (Ceki probably has a lot to tell about making simple code useful) All AOP material I have seen say that it is GREAT for injecting log statements, but I have mostly seen words and very little code. I have spent literaly hours today writing log.debug() statements for a performance plagued application so here I would have loved to have a tool to help me do SOME of it (except it was for Java 1.4 sigh). (and it appears that my Thunderbird at work has a hard time picking the right sender address, so my answers cannot catch a debate like this early, sorry). -- Thorbjørn Ravn Andersen "...plus... Tubular Bells!"

Just chipping in. Thorbjørn Ravn Andersen wrote:

...

3) loggers named after the class and method / field name, so you can be more fine grained in what output you get

Actually this is something I've noticed that java.util.logging can do - determine the method name of the caller - without any help. Perhaps this should be the approach? Let the logger do it?

Log4j can also determine the caller as can logback. Logback can also determine and print the caller of the caller, or the caller of the caller of the caller. See http://logback.qos.ch/manual/layouts.html#ClassicPatternLayout and then search for the "caller" conversion word. The caller converter can be instructed to print the caller only when certain criteria are met as specified by an evaluator. However, printing caller information is different than naming loggers after the method as Robert described in his email.

...

4) passing the stacktrace to the output (depending on how you configure the pattern) so that if you are interested in what it was that changed the field or called the method you don't need trace logging on for the entire application

I think the caller converter mentioned above already does what you want. -- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

Thorbjørn Ravn Andersen wrote:

Ceki Gulcu skrev:

...

Log4j can also determine the caller as can logback. Logback can also determine and print the caller of the caller, or the caller of the caller of the caller. See http://logback.qos.ch/manual/layouts.html#ClassicPatternLayout and then search for the "caller" conversion word. The caller converter can be instructed to print the caller only when certain criteria are met as specified by an evaluator.

Do you happen to have measured performance of this particular aspect of logback versus j.u.l?

Should be similar. Roughly speaking, determining the caller will double the cost of each written log. On some systems, it factor can be much higher. As I mentioned previously, logback can determine the caller of the caller (of the caller, of the caller, etc) whereas jul can only determine the immediate caller. -- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

On 18 Nov 2008, at 18:43, Ceki Gulcu wrote:

However, printing caller information is different than naming loggers after the method as Robert described in his email.

Indeed - it was to allow fine grained control of trace output that I was doing it. I guess you could use a filter to control which methods etc. had trace enabled, but it seemed easier to use the existing name hierarchy mechanism. Though one negative is that "traditionally" the last element of the logger name as output by PatternLayout is the class name.

...

...

4) passing the stacktrace to the output (depending on how you configure the pattern) so that if you are interested in what it was that changed the field or called the method you don't need trace logging on for the entire application

I think the caller converter mentioned above already does what you want.

Cool, in that case I'll stop mucking about with that. Rob

Ralph Goers skrev:

...

Why? Logback already gives automatically gives you access to the class and method name.

I have not looked much into the features of logback yet, so I am just burdened of the mindset of log4j where call stack probing was expensive and not recommended. It was my understanding that j.u.l. does this "fast enough" to be turned on per default, therefore the question.

...

Hmmmm.... I'm not sure of that. Lets see how it works out.

One of my development teams have actually implemented this with some of the AOP stuff then have done. I'll be looking at that soon for addition to SLF4J.

Looking forward to see it. Am I correct in assuming that you built the log-stuff aspects internally without building on an aspect log framework? -- Thorbjørn Ravn Andersen "...plus... Tubular Bells!"

On Wed, Nov 19, 2008 at 10:05 AM, Maarten Bosteels <mbosteels.dns@gmail.com>wrote:

On Tue, Nov 18, 2008 at 7:30 PM, Thorbjørn Ravn Andersen <ravn@runjva.com>wrote:

...

Robert Elliot skrev:

...

Thanks - I checked the slf4j-ext project when I started, but not the Subversion repository. I presume this is a post-compile step rather than runtime byte code alteration?

(I got the strange feeling of already having answered this, but I'm not sure, so I'll just do it again :)

Nope. Runs at class load time (i.e. at runtime).

Please look into the XLogger for actually doing the logging, as it is intended to allow keeping the information instead of flattening it into a string (you might want to be able to process this with a tool).

...

1) something like a PatternLayout to allow the user to choose the format of the messages at runtime (I prefer single > to double >> for instance on method entry - petty, but I feel it should be up to the user! And it's nice to be able to truncate parameter or return values if they are going to be utterly huge)

Would be nice. Also if it respects a different rendering than just the normal toString() approach.

...

2) trace logging of field value changes so you get output like this: fieldName initialValue -> newValue

Nice :)

...

3) loggers named after the class and method / field name, so you can be more fine grained in what output you get

Actually this is something I've noticed that java.util.logging can do - determine the method name of the caller - without any help. Perhaps this should be the approach? Let the logger do it?

...

4) passing the stacktrace to the output (depending on how you configure the pattern) so that if you are interested in what it was that changed the field or called the method you don't need trace logging on for the entire application

When you say stack trace, you talk about the call stack? I.e. asking the JVM for the stack and rendering it, instead of carrying an exception around? Just to get matters straight.

This is a really neat idea, which might also work well with the Eclipse Console plugin.

I cannot count the times I've pasted a stack trace in the Java Stack Trace pane on the Console to be able to navigate.

I am not sure we're talking about the same thing, but have you heard of JumpToCode ? It's a plugin for IntelliJ IDEA that listens for "jump to this code" commands from external programs. Creating a similar plugin for eclipse is on my TODO list.

The idea is that log-viewers such as Vigilog and Chainsaw show hyperlinks for every LocationInfo. When hyperlink is clicked a "jump to code" command is sent to your IDE, which will navigate to the corresponding code.

This is already implemented in Vigilog. I still have to ask the chainsaw maintainers to see if they are also interested.

forgot to add some URL's: http://code.google.com/p/firewood/wiki/JumpToCodePlugin http://plugins.intellij.net/plugin/?id=1894 http://vigilog.sourceforge.net/

Maarten

...

...

5) an @Secure annotation to allow the programmer to mark a parameter or return value as something that should not be accessible via trace logging - e.g. a password

Hmmmm.... I'm not sure of that. Lets see how it works out.

...

Out of curiousity (not criticising!) what was the reason for picking javassist rather than aspectj?

It worked :)

-- Thorbjørn Ravn Andersen "...plus... Tubular Bells!"

_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://qos.ch/mailman/listinfo/logback-dev

Maarten Bosteels skrev:

I cannot count the times I've pasted a stack trace in the Java Stack Trace pane on the Console to be able to navigate.

I am not sure we're talking about the same thing, but have you heard of JumpToCode ? It's a plugin for IntelliJ IDEA that listens for "jump to this code" commands from external programs. Creating a similar plugin for eclipse is on my TODO list.

The idea is that log-viewers such as Vigilog and Chainsaw show hyperlinks for every LocationInfo. When hyperlink is clicked a "jump to code" command is sent to your IDE, which will navigate to the corresponding code.

This is already implemented in Vigilog. I still have to ask the chainsaw maintainers to see if they are also interested.

This is a very interesting thing, as I have asked the Eclipse folks the same thing a long time ago. Is there a way to communicate things back to Eclipse when running in a debugger and the answer was "no". It would be really nice to have. My only concern is if a fellow coworker decides to tease me, and start sending bogus requests. Is there a password mechanism or so? Otherwise an integration with the Eclipse plugin would be a good idea perhaps. -- Thorbjørn Ravn Andersen "...plus... Tubular Bells!"