JDKLogger calls, was: Monitoring, logging and exceptions (again)

[Jean-Sebastien Delfino <js...@apache.org>]

Raymond Feng wrote:
> I just created https://issues.apache.org/jira/browse/TUSCANY-1635 to 
> track the aspectj-based tracing.
>
> Thanks,
> Raymond
>
> ----- Original Message ----- From: "Jean-Sebastien Delfino" 
> <js...@apache.org>
> To: <tu...@ws.apache.org>
> Sent: Wednesday, August 29, 2007 11:06 AM
> Subject: Re: Monitoring, logging and exceptions (again)
>
>
>> Simon Laws wrote:
>>> On 8/20/07, Simon Laws <si...@googlemail.com> wrote:
>>>
>>>>
>>>> On 8/20/07, Simon Nash <nash@hursley.ibm.com > wrote:
>>>>
>>>>> See inline.
>>>>>
>>>>>    Simon
>>>>>
>>>>> Raymond Feng wrote:
>>>>>
>>>>>
>>>>>> Comments inline.
>>>>>>
>>>>>> Thanks,
>>>>>> Raymond
>>>>>>
>>>>>> ----- Original Message ----- From: "Jean-Sebastien Delfino"
>>>>>> < jsdelfino@apache.org>
>>>>>> To: < tuscany-dev@ws.apache.org>
>>>>>> Sent: Friday, August 17, 2007 9:27 AM
>>>>>> Subject: Re: Monitoring, logging and exceptions (again)
>>>>>>
>>>>>>
>>>>>>
>>>>>>> [snip]
>>>>>>> ant elder wrote:
>>>>>>>
>>>>>>>
>>>>>>>> And also my 2p inline...
>>>>>>>>
>>>>>>>>    ...ant
>>>>>>>>
>>>>>>>> On 8/16/07, Simon Laws < simonslaws@googlemail.com> wrote:
>>>>>>>>
>>>>>>>>
>>>>>>>>> A number of different requirements have been discussed and
>>>>>>>>>
>>>>> solutions
>>>>>
>>>>>>>>> proposed. My 2p (I'm using Raymond's definitions b.t.w)
>>>>>>>>>
>>>>>>>>> Tracing: Dump out input/output/exception for method calls for the
>>>>>>>>> purpose
>>>>>>>>> of
>>>>>>>>> debugging/troubleshooting. (Target for developers/technical
>>>>>>>>>
>>>>> support)
>>>>>
>>>>>>>>> I feel that tracing of execution paths through the Tuscany 
>>>>>>>>> codebase
>>>>>>>>> would
>>>>>>>>> be
>>>>>>>>> useful but agree that " it's a lot of work and will be 
>>>>>>>>> difficult to
>>>>>>>>>               maintain
>>>>>>>>> and keep consistent" if we did it manually.  I'm happy that 
>>>>>>>>> this is
>>>>>>>>>
>>>>> the
>>>>>
>>>>>>>>> responsibility of whoever wants to trace through the code and 
>>>>>>>>> not a
>>>>>>>>> core
>>>>>>>>> part of the codebase. For the Tuscany developer community AspectJ
>>>>>>>>>
>>>>> have
>>>>>
>>>>>>>>> been
>>>>>>>>> proposed a couple of times and support has been prototyped. We
>>>>>>>>>
>>>>> could
>>>>>
>>>>>>>>> choose
>>>>>>>>> SLF4J as the  interface through which  messages are output.
>>>>>>>>>
>>>>>>>>>
>>>>>>>> I'm not sure we need to use SLF4J if we go the AspectJ route. 
>>>>>>>> SLF4J
>>>>>>>>
>>>>> is a
>>>>>
>>>>>>>> facade for logging APIs, so you can code to  the SLF4J API and 
>>>>>>>> then
>>>>>>>> plug in
>>>>>>>> whatever logging impl you like, but if the only logging calls we
>>>>>>>>
>>>>> have
>>>>>
>>>>>>>> are
>>>>>>>> confined to a single tracing aspect we might as well just code 
>>>>>>>> that
>>>>>>>> aspect
>>>>>>>> to a specific logging API like JDK logging. That avoids the extra
>>>>>>>> dependency
>>>>>>>> on SLF4J and anyone can add additional aspects if they really want
>>>>>>>>
>>>>> to
>>>>>
>>>>>>>> use a
>>>>>>>> different logger. The main other benefit of SLF4J is its
>>>>>>>>
>>>>> parameterized
>>>>>
>>>>>>>> message logging (avoids all the "if(logger.isDebugEnabled())" ) 
>>>>>>>> but
>>>>>>>> again if
>>>>>>>> all the logging calls are in a single aspect thats not so useful.
>>>>>>>>
>>>>>>>>
>>>>>>> Makes sense to me. If we go the aspectj route for tracing method
>>>>>>> entry/exit, I agree that using the JDK logger directly is simpler.
>>>>>>>
>>>>>>>
>>>>>> Since the aspect is on the side, we're flexible. JDK logger can be
>>>>>> default and it can be replaced easily if the embedders or users 
>>>>>> choose
>>>>>> to do so.
>>>>>>
>>>>>>
>>>>>>> A few more questions on this: What dependencies will aspectj add to
>>>>>>> our distribution? aspectjweaver is more than 1Mb, do we need it?
>>>>>>>
>>>>>> I'll try to spend some time to explore both the compile-time and
>>>>>> load-time weaving.
>>>>>>
>>>>>>
>>>>>>>> What about mid-method logging of specific interesting events, for
>>>>>>>> example
>>>>>>>> the contents of requests as the enter and leave bindings and
>>>>>>>> implementation
>>>>>>>> types and things like that? That sort of logging is often all a 
>>>>>>>> lot
>>>>>>>> of users
>>>>>>>> want to see not the detail tracing of every method entry/exit. 
>>>>>>>> Could
>>>>>>>> we add
>>>>>>>> things like this in specific places?
>>>>>>>>
>>>>>>>>
>>>>> +1 for the ability to produce this level of information.  This is my
>>>>> preferred approach for debugging or understanding how some part of 
>>>>> the
>>>>> code works.  Having every method entry and exit produce a trace line
>>>>> often creates a huge amount of output that obscures the essential
>>>>> details
>>>>> of what is happening.
>>>>>
>>>>>
>>>>>>> Can this mid-method logging be split in two categories?
>>>>>>>
>>>>>>> a) Debug tracing
>>>>>>> A simple solution is to split the method in two, and then leverage
>>>>>>>
>>>>> the
>>>>>
>>>>>>> entry/exit method tracing as discussed above.
>>>>>>>
>>>>> In many cases this would lead to a convoluted code structure with 
>>>>> local
>>>>> variables needing to be passed as parameters between the two 
>>>>> methods, or
>>>>> methods that contain a single line of code (if a trace line needs 
>>>>> to be
>>>>> produced from within a loop).
>>>>>
>>>>>
>>>>>> We can use JDK logger to add statements in the middle of a method.
>>>>>>
>>>>> Then
>>>>>
>>>>>> we can use an aspect to capture such calls to dump out the
>>>>>>
>>>>> information.
>>>>>
>>>>>> For example, if we have the following statement in a method:
>>>>>> logger.debug(...);
>>>>>> The apsect can trap it by a point cut like "call *
>>>>>> java.util.logger.Logger.debug(..).
>>>>>>
>>>>>>
>>>>> If the logger call is already there, why is an aspect needed to 
>>>>> trap it?
>>>>> Why not just let it execute?
>>>>>
>>>>>
>>>>>>> b) End-user readable information (info that a binding is
>>>>>>> sending/receiving a message for example)
>>>>>>> This falls into the second category discussed in this thread,
>>>>>>> reporting significant events to a management console.
>>>>>>>
>>>>>> The above suggestion should help too. The key here is to have some
>>>>>>
>>>>> calls
>>>>>
>>>>>> to indicate such requirements and they can be then trapped to 
>>>>>> provide
>>>>>> the concrete logic.
>>>>>>
>>>>>>
>>>>>>> I think we're starting to see concrete solutions for (a) with
>>>>>>>
>>>>> aspectj.
>>>>>
>>>>>>> I have not seen any real concrete proposal for (b) yet.
>>>>>>>
>>>>>>> -- 
>>>>>>> Jean-Sebastien
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: tuscany-dev-unsubscribe@ws.apache.org
>>>>> For additional commands, e-mail: tuscany-dev-help@ws.apache.org
>>>>>
>>>> I agree that entry and exit tracing can be overwhelming in a lot of
>>>> situations. I think this is an advantage of taking the AspectJ 
>>>> approach. If
>>>> people want to add this kind of tracing then we can make that 
>>>> possible with
>>>> no direct impact on the tuscany code base.
>>>>
>>>> A concrete proposal for other messages...
>>>>
>>>> I've been poking around to see what others do and, on closer 
>>>> inspection,
>>>> CXF have a rather nice, IMHO, approach which is a combination of a 
>>>> home
>>>> grown logging util class and the JDK logger that.
>>>>
>>>>   uses parameters to reduce the formatting load for inactive log
>>>> statements
>>>>   uses message property files for message lookup
>>>>   encompasses basic internationalization support using ICU and the 
>>>> message
>>>> files behind the scenes
>>>>   handles exceptions and strings (although it doesn't localize 
>>>> exception
>>>> strings)
>>>>
>>>> SLF4J does very similar things to this but we didn't seem to get much
>>>> traction with that before on this thread. It seems that we all have
>>>> different requirements for reducing dependencies vs providing logging
>>>> function. If we can reach a satisfactory level of function while 
>>>> relying on
>>>> the built in JDK logging features then that seems to be a good 
>>>> compromise.
>>>> Also with some home grown utilities we can at least make life a little
>>>> easier for ourselves in terms of recording user oriented messages 
>>>> related to
>>>> model elements.
>>>>
>>>> Looking at the CXF code this is what you build.
>>>>
>>>> MyModule
>>>>   src
>>>>     main
>>>>        java
>>>>          somepath
>>>>             SomeTuscanyClassA
>>>>             Messages.properties
>>>>        resources
>>>>           logging.properties
>>>>
>>>> Nothing too surprising there. They have a LogUtil class (see
>>>> cxf-common-utilities) which provides an interface for getting JDK 
>>>> loggers
>>>> and for logging with them. I'm assuming they created it but we 
>>>> should check.
>>>> Here is an example of how to use it.
>>>>
>>>> import java.util.logging.Level;
>>>> import java.util.logging.Logger;
>>>>
>>>> import org.apache.cxf.common.logging.LogUtils;
>>>>
>>>> public class SomeTuscanyClassA {
>>>>
>>>>     private static final Logger Log1 = LogUtils.getL7dLogger (
>>>> SomeTuscanyClassA.class);
>>>>
>>>>     public SomeTuscanyClassA() {
>>>>         Integer params[] = {8, 9, 4};
>>>>
>>>>         LogUtils.log(Log1,
>>>>                      Level.INFO,
>>>>                      "TEST_MESSAGE",
>>>>                      null,
>>>>                      (Object[])params);
>>>>
>>>>         Exception ex = new IllegalStateException("some exception 
>>>> string");
>>>>
>>>>         LogUtils.log(Log1,
>>>>                  Level.INFO ,
>>>>                  "TEST_MESSAGE",
>>>>                  ex,
>>>>                  (Object[])params);
>>>>
>>>>
>>>>     }
>>>>
>>>> We could then extend this to allow  for common Tuscany situations. For
>>>> example, by allowing a model element to be passed in,
>>>>
>>>>         LogUtils.log(Log1,
>>>>                           Level.INFO,
>>>>                           composite, // or some other 
>>>> specialization of
>>>> Base where the component name, uri can be read from
>>>>                           "TEST_MESSAGE",
>>>>                           null,
>>>>                           (Object[])params);
>>>>
>>>> We could then chose to use
>>>>
>>>> SEVERE
>>>> WARNING
>>>> INFO
>>>> CONFIG
>>>>
>>>> To record our end user readable information. This proposal assumes 
>>>> people
>>>> are comfortable with committing to JDK logging. If people are 
>>>> comfortable
>>>> with this then I don't see why we can't use.
>>>>
>>>> FINE
>>>> FINER
>>>> FINEST
>>>>
>>>> for mid method tracing.
>>>>
>>>> So is this going in the right direction? Or do people have completely
>>>> different approaches in mind?
>>>>
>>>> Regards
>>>>
>>>> Simon
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> I have noticed JDK logger statements appearing in various places in 
>>>> the
>>>>
>>> code. Did we reached a conclusion on this?
>>>
>>> Simon
>>>
>>>
>>
>> Looks like System.out.println calls have been replaced by JDK logger 
>> calls in revision r568417:
>> http://svn.apache.org/viewvc?view=rev&revision=568417
>>
>> I'm happy with that change, JDK logger is probably not perfect... but 
>> which logger library is? Sorry for bringing that up :)
>>
>> I don't think we've reached any clear conclusion on tracing. Here's 
>> my opinion:
>>
>> I'm +1 on using JDK logger;
>>
>> would prefer to avoid a home-grown logger layer on top of it (as we 
>> have better things to do than grow yet another not perfect logger API);
>>
>> and I'm happy with using aspectj to generate entry/exit trace calls 
>> externally without polluting the runtime source code, but I think we 
>> should just provide a sample + documentation showing how to do it on 
>> the side instead of embedding aspectj in our runtime.
>>
>> I don't have a firm opinion on monitoring - which is a different 
>> subject IMO - yet.
>>
>> -- 
>> Jean-Sebastien
>>
>>

So how about we all spend a few hours going through the modules we've 
been working on and add JDKLogger calls to log important events, infos, 
errors (like I'm starting a component, sending a message, about to fail 
etc.)?

-- 
Jean-Sebastien


---------------------------------------------------------------------
To unsubscribe, e-mail: tuscany-dev-unsubscribe@ws.apache.org
For additional commands, e-mail: tuscany-dev-help@ws.apache.org