Mailing-List: contact users-help@maven.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Maven Users List" <users@maven.apache.org>
Received-SPF: pass (nike.apache.org: domain of stephen.alan.connolly@gmail.com
 designates 209.85.192.181 as permitted sender)
MIME-Version: 1.0
In-Reply-To: 
 <CANWgJS77s=fR+YUem5k9UCTr0GVgV_60vgYe9+f_rddGxrGT=Q@mail.gmail.com>
References: <9e5201cf2831$52f17c60$f8d47520$@berthonneau.com>
	<CABLGb9yyWxO8om2YE2Y-3v0RwLgB4RmY6cG9UK330DY4UVGHpQ@mail.gmail.com>
	<008101cf2834$fcf8d4d0$f6ea7e70$@berthonneau.com>
	<CAFBdXRp0KqmGHnDjjD3=_U94nh4HNo1zWrV5KNVRRxDeVSBjoQ@mail.gmail.com>
	<CAK8jvqytpdu2aa11qOrBjZhvjBShf97scfSVc4yRNnGQ9GVK_g@mail.gmail.com>
	<52FBF4F1.8090701@artifact-software.com>
	<7AFDDD6F-AC2B-4D54-A161-1A71618D308D@berthonneau.com>
	<CANWgJS77s=fR+YUem5k9UCTr0GVgV_60vgYe9+f_rddGxrGT=Q@mail.gmail.com>
Date: Thu, 13 Feb 2014 09:23:12 +0000
Message-ID: 
 <CA+nPnMy6g8DJBUuX1SywWg9-bdaeSzB1Q4VaFUnHdqAqSYV2qQ@mail.gmail.com>
Subject: Re: Code coverage with debug logs: 100% branch coverage not
 possible?...
From: Stephen Connolly <stephen.alan.connolly@gmail.com>
To: Maven Users List <users@maven.apache.org>
Content-Type: multipart/alternative; boundary=047d7bd9164e04ee3c04f2463d16

--047d7bd9164e04ee3c04f2463d16
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable

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=3D0x67267,
authenticated=3Dtrue, callerId=3D+14325551234, displayName=3D"Jim Smith"]
DEBUG: Looking up display name of id=3D0x67267, authenticated=3Dtrue,
callerId=3D+14325551234, displayName=3D"Jim Smith" using callerId +14325551=
234
DEBUG: Set display name of Caller[id=3D0x67267, authenticated=3Dtrue,
callerId=3D+14325551234, displayName=3D"Jim Smith"] to "Jim Smith" based on
caller id lookup

which from the code should never happen... what you expect is something lik=
e

DEBUG: Starting authentication flow for caller Caller[id=3D0x67267,
authenticated=3Dfalse, callerId=3D+14325551234, displayName=3Dnull]
DEBUG: Looking up display name of Caller[id=3D0x67267, authenticated=3Dtrue=
,
callerId=3D+14325551234, displayName=3Dnull] using callerId +14325551234
DEBUG: Set display name of Caller[id=3D0x67267, authenticated=3Dtrue,
callerId=3D+14325551234, displayName=3D"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.

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 ~9=
5%
> 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 existin=
g
> 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/NullA=
ppender.html
>
> My 2 cents
>
>
> 2014-02-13 7:13 GMT+01:00 Beno=EEt 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 implemente=
d
> by
> > Log4j.
> >
> > Beno=EEt
> >
> > > Le 12 f=E9vr. 2014 =E0 23:25, Ron Wheeler <rwheeler@artifact-software=
.com>
> > a =E9crit :
> > >
> > >
> > >
> > > 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=3DLoggerFactory.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 replaceme=
nt
> > >>> 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=EEt 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=E9 : mercredi 12 f=E9vrier 2014 21:36
> > >>>> =C0 : Maven Users List
> > >>>> Objet : Re: Code coverage with debug logs: 100% branch coverage no=
t
> > >>>> 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?), the=
n
> > you
> > >>>> should be able to raise your percentage.
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> On Wed, Feb 12, 2014 at 2:30 PM, Beno=EEt 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 exceptio=
n
> > (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 time=
s:
> > >>>>> 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=EEt.
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> --
> > >>>>
> > >>>> 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>
> >
>

--047d7bd9164e04ee3c04f2463d16--