[PATCH] Enhancements to TraceInterceptor [SPR-860]

[spring-projects-issues]

Matthew Sgarlata opened SPR-860 and commented

I want to be able to see the arguments to and return values of the methods in my service and DAO objects. The TraceInterceptor did not support this functionality, so I wrote it and prepared a patch for potential inclusion in Spring. With no configuration parameters specified, log messages will appear as they did in Spring 1.0.2. The new enterMessageTemplate and exitMessageTemplate properties allow for customization.

In my application I set my enterMessageTemplate to "Entering $unqualifiedTargetClassName.$methodName($arguments)" and my exitMessageTemplate to "$unqualifiedTargetClassName.$methodName($arguments) returned $returnValue". This results in log output such as:

DEBUG (TraceInterceptor:invoke) - Entering OwnerUpdaterServiceImpl.getOwnerMetricsByUser(39,-1,5,database1110394538812,org.apache.catalina.session.StandardSessionFacade@1dbe1c9)
DEBUG (TraceInterceptor:invoke) - Entering OwnerUpdaterDAOImpl.getOwnerMetricsByUser(39,-1,5,database1110394538812)
DEBUG (JdbcTemplate:query) - Executing SQL query [select mc.metricid, mc.scorecardnodeid, mc.updatetype, mc.datatype, mc.aggregationtype, mc.equation, mc.lastreminded, mc.calendarid, sn.scorecardnodename, sn.scorecardrootnodeid, mc.calendarperiodid, ms.score, mv.actualvalue, sn.weighting, mv.goal, mc.goal as mgoal, mv.base, mc.base as mbase, mv.metricvalueid, s.organizationnodeid, mc.periodalias, mc.startdate, mc.enddate, cal.calendarname from ((((((select m.*, cp1.calendarperiodid, cp1.startdate, cp1.enddate, cp1.periodalias from metrics m, calendarperiods cp1, calendarperiods cp2 where m.calendarid = cp1.calendarid and cp2.calendarperiodid=? and ( (cp1.startdate >= cp2.startdate and cp1.startdate <= cp2.enddate) or (cp1.enddate >= cp2.startdate and cp1.enddate <= cp2.enddate) or (cp1.startdate < cp2.startdate and cp1.enddate > cp2.enddate) ) ) mc left outer join metricvalues mv on (mc.metricid = mv.metricid and mc.calendarperiodid = mv.calendarperiodid)) left outer join metricscores ms on (mc.metricid = ms.metricid and mc.calendarperiodid = ms.calendarperiodid)) left join scorecardnodes sn on (mc.scorecardnodeid = sn.scorecardnodeid)) left join scorecards s on (sn.scorecardrootnodeid = s.scorecardrootnodeid)) left join scorecardnodeownerusers sou on (mc.scorecardnodeid = sou.scorecardnodeid)) left join calendars cal on (mc.calendarid = cal.calendarid) where sou.userid = ? order by sn.scorecardnodename]
DEBUG (StatementCreatorUtils:setParameterValue) - Setting SQL statement parameter value: columnIndex 1, parameter value [39], valueClass [java.lang.Integer], sqlType unknown
DEBUG (StatementCreatorUtils:setParameterValue) - Setting SQL statement parameter value: columnIndex 2, parameter value [-1], valueClass [java.lang.Integer], sqlType unknown
DEBUG (TraceInterceptor:invoke) - OwnerUpdaterDAOImpl.getOwnerMetricsByUser(39,-1,5,database1110394538812) returned []
DEBUG (TraceInterceptor:invoke) - OwnerUpdaterServiceImpl.getOwnerMetricsByUser(39,-1,5,database1110394538812,org.apache.catalina.session.StandardSessionFacade@1dbe1c9) returned []

PS - I know service objects shouldn't have HttpSessions passed to them, I just haven't had time to factor that out of the code at my new company yet!

---

Affects: 1.2 RC1

Attachments:

• TraceInterceptorPatch.txt (7.07 kB)

Issue Links:

• TraceInterceptor enhancements [SPR-601] #5329 TraceInterceptor enhancements ("duplicates")

1 votes, 2 watchers

[spring-projects-issues]

Matthew Sgarlata commented

Patch

[spring-projects-issues]

Claus Ibsen commented

Take a look at #5329. I also enhanced the traceinterceptor.

Maybe we could mix the best of both worlds.

[spring-projects-issues]

Matthew Sgarlata commented

Hi Claus,

Looks like we were thinking along the same lines! I really like how you added an elapsed time as something that could be logged.

I had the same idea as you with making it possible to log as the target class rather than as the TraceInterceptor. The problem though is that the method name detected by Log4J will be the TraceInterceptor's invoke method. So if the method name is part of what you're logging, you could end up with a weird log message like this: "MyService:invoke - Here is my log message" Even though your MyService class doesn't have an invoke method.

One thing I wanted to do was print out argument names, but unfortunately that information doesn't seem to be available at runtime in JDK 1.3. I see you put in parameter types as well, which is an interesting option. One thing I would wonder is what if you wanted to combine the parameter types and the parameter values such as "MyService.getSomeData(3 [java.lang.Integer], "myDatabaseName" [java.lang.String]) or something like that? I don't think either of us has a clear solution to something like that. Do you think parameter types will typically be of interest? I would think you could usually infer the types well enough by looking at the values of the arguments that are printed out.

I prefer my technique of using $notiation to using numbers like {0} because it's easier to see in your configuration exactly what's going on. I'm not at all convined $whatever is best though... perhaps we should use {whatever} instead? What do you think?

One thing that is confusing to me about your TraceInterceptor is the possibility of specifying an enter and exit message format, but also having elapsedTime and argument properties. I think if everything is configured in the message format then it's clearer where the elapsedTime and arguments will print and it's also more configurable.

[spring-projects-issues]

Matthew Sgarlata commented

I just ran into some confusing log output with the TraceInterceptor that leads me to believe we also need to have a mechanism of letting the user know when an exception has been thrown. If we went with my code, that would mean adding an exceptionMessageTemplate property to the TraceInterceptor.

Here is my confusing log output. Note that NoteDAOImpl.getRecentMeetingNoteText actually threw an exception and didn't return null, unlike what is claimed by the message below

DEBUG (TraceInterceptor:invoke) - NoteDAOImpl.getRecentMeetingNoteText(5,<p><font size="1" color="#9AA4CE">There are no notes for [currentperiod]. The information below is from the last period availible, [lastperiod]</font></p>,39,org.apache.catalina.session.StandardSessionFacade@7b6617,database1110394538812) returned null
DEBUG (TraceInterceptor:invoke) - NoteServiceImpl.getRecentMeetingNoteText(5,<p><font size="1" color="#9AA4CE">There are no notes for [currentperiod]. The information below is from the last period availible, [lastperiod]</font></p>,39,org.apache.catalina.session.StandardSessionFacade@7b6617,database1110394538812) returned null
ERROR (JSP:_jspService) - Incorrect result size: expected 1, actual 2
org.springframework.dao.IncorrectResultSizeDataAccessException: Incorrect result size: expected 1, actual 2
at org.springframework.dao.support.DataAccessUtils.requiredUniqueResult(DataAccessUtils.java:64)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:577)
at org.springframework.jdbc.core.JdbcTemplate.queryForMap(JdbcTemplate.java:594)
at com.spider.scoreboard.dao.impl.NoteDAOImpl.getRecentMeetingNoteText(NoteDAOImpl.java:276)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:310)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:155)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:122)
at org.springframework.aop.interceptor.TraceInterceptor.invoke(TraceInterceptor.java:72)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:174)
at $Proxy31.getRecentMeetingNoteText(Unknown Source)
at com.spider.scoreboard.service.impl.NoteServiceImpl.getRecentMeetingNoteText(NoteServiceImpl.java:61)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:310)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:155)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:122)
at org.springframework.aop.interceptor.TraceInterceptor.invoke(TraceInterceptor.java:72)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:174)
at $Proxy32.getRecentMeetingNoteText(Unknown Source)
at com.spider.scoreboard.meeting.notes.MeetingNotesAction.execute(MeetingNotesAction.java:57)
at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484)
at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274)
at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:507)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:696)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:809)

etc

[spring-projects-issues]

Claus Ibsen commented

Hi Matthew

I do think putting in parameter types is viable when you have overloaded methods and thus want to know excatly witch method was invoked.

I haven't tried it on JDK1.3 only JDK1.4. I am sure Rob Harrop can tell why the info isn't avail in JDK1.3. I think he should be assigned both #5329 and #5586.

I thought about configuring the ENTER and EXIT method completely using a string format syntax along the lines you suggest. Using $methodName$ instead of {0} is in my opinion better as you can see excatly from the String what is outputted in the log.

Combining parameter types and values is for me confusing:

ENTER - foo(com.mycompany.Customer Customer[ID='123', Name='Claus'], Boolean true, Date 2005-03-29 CET 12:00)

As some of the parameter values will be Object's that would have a verbose toString() such as the Customer object above.

But why not give the user the choice of all 3 combinations:

• parameter types only
• parameter values only
• combination of both

About the dynamic logger. I do like it as in my code I don't get the weird logname. Again let the user decide. I would rather have the option to configure my log4j.properties as:

log4j.root=WARN, console
log4j.category.org.springfranework=INFO
log4j.category.com.mycompany=DEBUG

And still have the TraceInterceptor to output at DEBUG level in my code. If we don't have the dynamic logger option I need to specify:

log4j.root=WARN, console
log4j.category.org.springfranework=INFO
log4j.category.org.springfranework.aop.intercept.TraceInterceptor=DEBUG
log4j.category.com.mycompany=DEBUG

If I have more than one TraceInterceptor configured I get DEBUG log for them all - I won't be able to turn on ON and the other OFF. The dynamic logger will.

Can you provide a java example where the dynamic logger will use a weird name?

In your example you can output the returned object. I think that is a good idea.

/Claus

[spring-projects-issues]

Claus Ibsen commented

A few other suggestions:

• option to output the elapsed time (and use sec instead of msec, so it can be 0.023 sec instead of 23 msec)
• option to: catch any thrown exception, log it and rethrow

[spring-projects-issues]

Rob Harrop commented

Matt/Claus,

My current feeling is that we should leave TraceInterceptor as is and introduce a new CustomizableTraceInterceptor with all these improvements included.

Also - parameter names are never available at runtime, only parameter types.

Rob

[spring-projects-issues]

Matthew Sgarlata commented

Hi Rob, I think both Claus and I designed our enhancements to TraceInterceptor so that they would be 100% backwards compatible. In other words, the output of the enhanced version of TraceInterceptor would be the same as the old version. The only compatability difference I can think of is that if dependency checking is by default turned on for the application context in which the TraceInterceptor is registered, the bean would fail after upgrading to a new version of Spring. I think that's a very minor compatability issue. We are doing a point upgrade, after all, so minor changes like this are to be expected.

On the other hand, I feel introducing a new CustomizableTraceInterceptor adds no value. Why have two classes that can do the same thing? The new enhanced version is just as easy to use as the old version for a basic use case. Namely, just register the bean in the application context. The bean has no dependencies or other required beans, etc.

[spring-projects-issues]

Rob Harrop commented

There are two main reasons I want to move this into a different class:

1. Performance - TraceInterceptor has very low overhead at the moment and I don't want to increase that. This is only a small consideration but it is a consideration nonetheless.

2. Compatibility - TraceInterceptor works on JDK 1.3. To make the new version work efficiently, the String replacements should be done using regular expressions across a StringBuffer. This will only work on JDK 1.4

Rob

[spring-projects-issues]

Matthew Sgarlata commented

Hi again Rob,

PERFORMANCE

I hadn't thought much about the performance hit for these new enhancements, but you're right there would be one. However, I don't think the hit would be that significant. First of all, the hit is only in development because in other environments the logging should be turned off. Second, if you think about it there is far less String manipulation involved in the TraceInterceptor than there is in loading the XML-based Spring application context. String manipulation is certainly slow, but it isn't that slow. Further, the patch I submitted is O(n), where n is the length of the String that is output to the log file. I haven't noticed any performance difference when using the enhanced version of the interceptor.

COMPATABILITY

The version of the interceptor I wrote is compatible with JDK 1.3 because it does not use regular expressions. Instead, it just calls StringUtils.replace. That's probably more efficient than using regular expressions anyway.

[spring-projects-issues]

Rob Harrop commented

I wouldn't compare the performance of reading the configuration, which is a startup task, with the performance of a runtime tool. Also, we can't just assume that this class won't be used in production - many applications run the first few months of production under extended QA and it is often useful to be able to turn this kind of functionality on in production without it having too much of a hit.

I can't say for sure that the regex approach will be faster than using StringUtils.replace but I would assume it will be. Regex will work over the StringBuffer for all replacements whilst StringUtils is creating a new StringBuffer for every replacement. Plus, with match pattern being compiled just once, I think the overall effect will be much fast matching.

I'm nearly ready with the proposed implementation which I'll be committing to sandbox soon. For now it makes sense to keep a different class name so that I can have both implementations in CVS at the same time.

Rob

[spring-projects-issues]

Matthew Sgarlata commented

You've convinced me of the value of having a high-performance option for the TraceInterceptor. I have an idea how we could accomplish this with only one class. When the TraceInterceptor is first created, let it have a private boolean optimizedForSpeed = true. If any of the properties in the TraceInterceptor are set to false, set optimizedForSpeed = false. If optimizedForSpeed is true, skip all the regular expressions, string replacements, etc. What do you think?

[spring-projects-issues]

Rob Harrop commented

That seems like a reasonable approach, however I'm not still not sure :).

I've committed CustomizableTraceInterceptor to sandbox to get some feedback and we should find out what the rest of the team and community think.

Rob

[spring-projects-issues]

Matthew Sgarlata commented

Hi Rob, I just took a look at your CustomizableTraceInterceptor. It looks great!

Here are some minor ideas for refinement:

• Can we make the getLoggerForInvocation method protected?
• I would like to see assertDoesNotContainsText promoted to the Assert class and called doesNotHaveText or doesNotContainText
• It's called the TraceInterceptor, so we should probably log at TRACE level, not DEBUG level ;) This is probably just code left over from when Spring had a direct dependency on Log4J instead of commons-logging

[spring-projects-issues]

Claus Ibsen commented

Hi Rob

Looks great. Great idea about the regexp for search/replace. And using the Constants class to enlist the constants of your own class is smart.

I found a few javadoc glitches, I am sure you'll have fixed anyway:

• <code> around the placeholder is missing for METHOD_NAME_PLACEHOLDER.
• spelling "place holders" in methods setEnterMessage() and setExitMessage()
• javadoc for setExceptionMessage() is a copy of setExitMessage()

However one feature that I'll be strongly missing:
I do think it should be possible to log the time taken. I know there is a PerformanceInterceptor also but this would clutter the logfile if you would have a combination of both. Especially when you do development and log long processing times such as the communication with the database or web service communications.