maven-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stephen Connolly <stephen.alan.conno...@gmail.com>
Subject Re: Code coverage with debug logs: 100% branch coverage not possible?...
Date Thu, 13 Feb 2014 09:25:13 GMT
On 13 February 2014 09:23, Stephen Connolly <stephen.alan.connolly@gmail.com
> wrote:

> because if you enable ALL then the other side of the if will not be
> followed... you need to combine runs with ALL and NONE to get both sides of
> the logging branches.
>
> Another point that the "slf4j is the solution" camp misses is sometimes
> the log message needs evaluation in order to generate the message. For
> example you might want to extract a meaningful string representation out of
> a complex data structure... with a @CheckFoNull chain of methods to dance
> through. While slf4j and other message formatting saves you a lot of the
> cases where an `if (debug) { log }` is needed, it does not and can not
> eliminate all cases.
>
> And then there is the final point where you are dealing with a mutable
> data structure (this is of more concern with an async logger framework)...
>
> We had a case whereby the logging statements where logging the object in a
> state which it could not possibly be in... because the log formatting and
> hence toString() evaluation was taking place in a different thread async
> (to prevent logging from slowing down the main code path)... so by the time
> the log message was being formatted the object state had mutated and from
>
> if (!caller.isAuthenticated()) {
>   logger.debug("Starting authentication flow for caller {}", caller);
>   ...
> }
> if (StringUtils.isEmpty(caller.getDisplayName) &&
> StringUtils.isNotBlank(caller.getCallerId()) {
>   logger.debug("Looking up display name of {} using callerId {}", caller,
> caller.getCallerId());
>   ...
>   caller.setDisplayName(displayName);
>   logger.debug("Set display name of {} to \"{}\" based on caller id
> lookup", caller, displayName);
>   ...
> }
>
>  you would get
>
> DEBUG: Starting authentication flow for caller Caller[id=0x67267,
> authenticated=true, callerId=+14325551234, displayName="Jim Smith"]
> DEBUG: Looking up display name of id=0x67267, authenticated=true, callerId=
> +14325551234, displayName="Jim Smith" using callerId +14325551234
> DEBUG: Set display name of Caller[id=0x67267, authenticated=true, callerId=
> +14325551234, displayName="Jim Smith"] to "Jim Smith" based on caller id
> lookup
>
> which from the code should never happen... what you expect is something
> like
>
> DEBUG: Starting authentication flow for caller Caller[id=0x67267,
> authenticated=false, callerId=+14325551234, displayName=null]
> DEBUG: Looking up display name of Caller[id=0x67267, authenticated=true,
> callerId=+14325551234, displayName=null] using callerId +14325551234
> DEBUG: Set display name of Caller[id=0x67267, authenticated=true, callerId=
> +14325551234, displayName="Jim Smith"] to "Jim Smith" based on caller id
> lookup
>
> But because by the time the DEBUG message was formatted we had mutated the
> object state already the logging statements were giving the wrong output...
> the fix was to change the code to
>
> if (!caller.isAuthenticated()) {
>   if (logger.isDebug()) logger.debug("Starting authentication flow for
> caller {}", caller.toString());
>   ...
> }
> if (StringUtils.isEmpty(caller.getDisplayName) &&
> StringUtils.isNotBlank(caller.getCallerId()) {
>   if (logger.isDebug()) logger.debug("Looking up display name of {} using
> callerId {}", caller.toString(), caller.getCallerId());
>   ...
>   caller.setDisplayName(displayName);
>   if (logger.isDebug()) logger.debug("Set display name of {} to \"{}\"
> based on caller id lookup", caller.toString(), displayName);
>   ...
> }
>
> In such cases you actually *have to* wrap the logging statement and force
> the .toString() when logging
>

Well there are other solutions such as switching to immutable objects...
but if you don't have the ability to make such a change...


>
> What a framework like slf4j and the other message formatting based
> frameworks gives you, however, is the default behaviour is lazy toString
> and you can add the branches for those cases where you need them.
>
> -Stephen
>
> P.S. this logging example is a rephrase of the actual logging code which
> using a home baked framework and I have paraphrased the code somewhat,
> since this was actually a state machine... but the same issue can occur in
> any multi-threaded code base where you are logging mutable objects and
> expecting the log formatter to evaluate the toString()
>
>
> On 13 February 2014 08:47, Baptiste Mathus <ml@batmat.net> wrote:
>
>> My first feeling is that not much time should be spent on that issue,
>> logging isn't going to take a lot of points of percentage down, having
>> ~95%
>> would already be great (but maybe you already have).
>>
>> Anyway, on the other hand, if what you want is to get code coverage, why
>> not just enable the ALL logging level when recording code coverage and go
>> ahead?
>>
>> Then, if the verbosity if an issue, simply plug something like an existing
>> or custom no-op/Null appender [1]? That might sound the simplest solution,
>> isn't it?
>>
>> [1]
>>
>> https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/varia/NullAppender.html
>>
>> My 2 cents
>>
>>
>> 2014-02-13 7:13 GMT+01:00 Benoît Berthonneau <benoit@berthonneau.com>:
>>
>> > Ron, Mirko, Kevin,
>> >
>> > Thanks for your feedback : you're right with Slf4j implementation.
>> > Unfortunately, it is not. It is a home made logger interface
>> implemented by
>> > Log4j.
>> >
>> > Benoît
>> >
>> > > Le 12 févr. 2014 à 23:25, Ron Wheeler <rwheeler@artifact-software.com
>> >
>> > a écrit :
>> > >
>> > >
>> > >
>> > > Not really a Maven issue but if you do your logging like this:
>> > >
>> > > package com.myco.testapp;
>> > > import org.slf4j.Logger;
>> > > import org.slf4j.LoggerFactory;
>> > >
>> > > public class MyClass{
>> > >            private Logger
>> > _logger=LoggerFactory.getLogger(this.getClass());
>> > >
>> > >      logger.debug("blah {} in the loop that contains {}", i, max);
>> > >
>> > > }
>> > >
>> > > You can sort out the enabling of logs and destination of your logging
>> by
>> > severity and class(I think by package as well) in the log configuration
>> at
>> > run-time.
>> > >
>> > > Ron
>> > >
>> > >> On 12/02/2014 4:20 PM, Mirko Friedenhagen wrote:
>> > >> Hello Benoit,
>> > >>
>> > >> Kevin is right, using slf4j[0] one would use sth. like:
>> > >>
>> > >> logger.debug("blah {} in the loop that contains {}", i, max);
>> > >>
>> > >> No need for iffing :-).
>> > >>
>> > >> [0] http://www.slf4j.org/manual.html
>> > >> Regards Mirko
>> > >> --
>> > >> http://illegalstateexception.blogspot.com/
>> > >> https://github.com/mfriedenhagen/ (http://osrc.dfm.io/mfriedenhagen)
>> > >> https://bitbucket.org/mfriedenhagen/
>> > >>
>> > >>
>> > >>> On Wed, Feb 12, 2014 at 10:10 PM, Kevin Krumwiede <kjkrum@gmail.com
>> >
>> > wrote:
>> > >>> It does matter which implementation.  The main reason it was
>> > recommended to
>> > >>> check the logging level was because string concatenation can be
>> > expensive,
>> > >>> and you want to avoid doing it for a message that won't be logged.
>> >  But if
>> > >>> you're using a logging API like slf4j that uses parameter
>> replacement
>> > >>> tokens in the message string, if the message isn't logged, the
>> > replacement
>> > >>> won't be performed and the call will be cheap.
>> > >>> On Feb 12, 2014 1:57 PM, "Benoît Berthonneau" <
>> benoit@berthonneau.com>
>> > >>> wrote:
>> > >>>
>> > >>>> Hi Paul,
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>> Don't think that I could play with exclusions. Here is an example
:
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>> *A Unit Test :*
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>> *The tested class with ALL traces activated:*
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>> *And the same tested class with INFO traces activated:*
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>> -----Message d'origine-----
>> > >>>> De : paulus.benedictus@gmail.com [mailto:
>> paulus.benedictus@gmail.com]
>> > De
>> > >>>> la part de Paul Benedict
>> > >>>> Envoyé : mercredi 12 février 2014 21:36
>> > >>>> À : Maven Users List
>> > >>>> Objet : Re: Code coverage with debug logs: 100% branch coverage
not
>> > >>>> possible?...
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>> IIRC, there should be an option in Emma/Cobertura that allows
you
>> to
>> > >>>> exclude coverage on certain classes. So if you can exclude
your
>> log4j
>> > >>>> classes (you don't really want to test your logging, do you?),
then
>> > you
>> > >>>> should be able to raise your percentage.
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>> On Wed, Feb 12, 2014 at 2:30 PM, Benoît Berthonneau
>> > >>>>
>> > >>>> <benoit@berthonneau.com>wrote:
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>>> Hi all,
>> > >>>>> I need your opinion/way to tackle the following problem:
>> > >>>>> In many projects we use a Logger (doesn't matter which
>> > >>>>> implementation). It is often recommend to test if the debug
level
>> is
>> > >>>>> activated before logging a debug trace like the following:
>> > >>>>> if (logger.isDebugEnabled()) {
>> > >>>>>     logger.debug("blah " + i + " in the loop that contains
" +
>> max);
>> > >>>>> }
>> > >>>>> Now when you run unit tests on this kind of code you need
to make
>> a
>> > >>>> choice:
>> > >>>>
>> > >>>>> run tests with INFO level or run tests with ALL traces
activated.
>> I
>> > >>>>> choose the second option in order to:
>> > >>>>> *         Check that debug traces doesn't throw unwanted
exception
>> > (like
>> > >>>>> NPE)
>> > >>>>> *         Have a better code coverage in term of covered
lines
>> > >>>>> But in term of branches coverage we could never have a
100% :(
>> > >>>>> To me the only way to cover this is to run the tests suite
2
>> times:
>> > >>>>> one with INFO traces configured, and another one with ALL
traces
>> > >>>>> activated.
>> > >>>>> Did you face this issue and how did you solve it ?
>> > >>>>> Thanks,
>> > >>>>> Benoît.
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>>
>> > >>>> --
>> > >>>>
>> > >>>> Cheers,
>> > >>>>
>> > >>>> Paul
>> > >> ---------------------------------------------------------------------
>> > >> To unsubscribe, e-mail: users-unsubscribe@maven.apache.org
>> > >> For additional commands, e-mail: users-help@maven.apache.org
>> > >
>> > >
>> > > --
>> > > Ron Wheeler
>> > > President
>> > > Artifact Software Inc
>> > > email: rwheeler@artifact-software.com
>> > > skype: ronaldmwheeler
>> > > phone: 866-970-2435, ext 102
>> > >
>> > >
>> > > ---------------------------------------------------------------------
>> > > To unsubscribe, e-mail: users-unsubscribe@maven.apache.org
>> > > For additional commands, e-mail: users-help@maven.apache.org
>> > >
>> >
>> > ---------------------------------------------------------------------
>> > To unsubscribe, e-mail: users-unsubscribe@maven.apache.org
>> > For additional commands, e-mail: users-help@maven.apache.org
>> >
>> > --
>> > Baptiste <Batmat> MATHUS - http://batmat.net
>> > Sauvez un arbre,
>> > Mangez un castor ! nbsp;! <users-help@maven.apache.org>
>> >
>>
>
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message