You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@maven.apache.org by Benoît Berthonneau <be...@berthonneau.com> on 2014/02/12 21:30:52 UTC
Code coverage with debug logs: 100% branch coverage not possible?...
Hi all,
I need your opinion/way to tackle the following problem:
In many projects we use a Logger (doesnt 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 doesnt 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.
Re: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by jieryn <ji...@gmail.com>.
I have also been annoyed with what you describe, and have wondered how
to fill the gap of missing coverage.
Outside of copying the testcase and dynamically changing the log level
inside of it, which in addition to being burdensome, also offends my
DRY sensibility, the best idea I've had about this involves a
relatively new feature of JUnit called @Theories[1].
You could create @DataPoints {Level.ALL, Level.NONE} and then pass
them in to your test method. Then you dynamically set the class under
test's Logger.Level with the data point. I think this ought to work
just fine unless you execute your tests in parallel mode, as most
Logger declarations are as static instances.
There's one other problem which has prevented me from exploiting this
technique: @Theories needs a dedicated @RunWith(Theories.class). Which
would tend to preclude execution under @RunWith(Arquillian.class)
since @RunWith takes a singular runner argument, unless Aslak/someone
makes some tweaks[2].
[1] https://github.com/junit-team/junit/wiki/Theories
[2] https://issues.jboss.org/browse/ARQ-561
On Wed, Feb 12, 2014 at 3:30 PM, Benoît Berthonneau
<be...@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.
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@maven.apache.org
For additional commands, e-mail: users-help@maven.apache.org
RE: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Benoît Berthonneau <be...@berthonneau.com>.
With the pictures attached�
De : Beno�t Berthonneau [mailto:benoit@berthonneau.com]
Envoy� : mercredi 12 f�vrier 2014 21:57
� : 'Maven Users List'
Objet : RE: Code coverage with debug logs: 100% branch coverage not
possible?...
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 <ma...@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
< <ma...@berthonneau.com> 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
Re: Code coverage with debug logs: 100% branch coverage notpossible?...
Posted by Benoît Berthonneau <be...@berthonneau.com>.
Thanks for all your comments. I will conclude to my first idea: tests
need to be run 2 times (one with traces to OFF or INFO, and the other
one with traces to ALL)
Regards,
Benoît.
Le 13-02-2014 10:25, Stephen Connolly a écrit :
> 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 [1] My 2 cents 2014-02-13 7:13 GMT+01:00 Benoît Berthonneau <be...@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 [2] Regards Mirko -- http://illegalstateexception.blogspot.com/ [3] https://github.com/mfriedenhagen/ [4] (http://osrc.dfm.io/mfriedenhagen [5]) https://bitbucket.org/mfriedenhagen/ [6] 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 <be...@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 [7] Sauvez un arbre, Mangez un castor !
nbsp;! <us...@maven.apache.org>
Links:
------
[1]
https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/varia/NullAppender.html
[2] http://www.slf4j.org/manual.html
[3] http://illegalstateexception.blogspot.com/
[4] https://github.com/mfriedenhagen/
[5] http://osrc.dfm.io/mfriedenhagen
[6] https://bitbucket.org/mfriedenhagen/
[7] http://batmat.net
Re: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Stephen Connolly <st...@gmail.com>.
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 <be...@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
>> > >>>>
>> > >>>> <be...@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;! <us...@maven.apache.org>
>> >
>>
>
>
Re: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Stephen Connolly <st...@gmail.com>.
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.
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 <be...@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 <rw...@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 <kj...@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
> > >>>>
> > >>>> <be...@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;! <us...@maven.apache.org>
> >
>
Re: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Baptiste Mathus <ml...@batmat.net>.
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 <be...@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 <rw...@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 <kj...@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" <be...@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
> >>>>
> >>>> <be...@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;! <us...@maven.apache.org>
>
Re: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Benoît Berthonneau <be...@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 <rw...@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 <kj...@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" <be...@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
>>>>
>>>> <be...@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
Re: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Ron Wheeler <rw...@artifact-software.com>.
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 <kj...@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" <be...@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
>>>
>>> <be...@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
Re: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Mirko Friedenhagen <mf...@gmail.com>.
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 <kj...@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" <be...@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
>>
>> <be...@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
RE: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Kevin Krumwiede <kj...@gmail.com>.
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" <be...@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
>
> <be...@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
>
RE: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Benoît Berthonneau <be...@berthonneau.com>.
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
< <ma...@berthonneau.com> 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
RE: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Benoît Berthonneau <be...@berthonneau.com>.
Hi Reto,
I understood your point of view but to me the problem I'm talking about
could be "easily" solved for a better branch coverage and know what is the
real missed branches report.
Benoît.
-----Message d'origine-----
De : Reto Hablützel [mailto:rethab@rethab.ch]
Envoyé : mercredi 12 février 2014 21:47
À : Maven Users List
Objet : Re: Code coverage with debug logs: 100% branch coverage not
possible?...
To follow up on Paul's answer, I would go as far as to say that I test my
code in order to feel comfortable that it actually does what it should do.
Thus, I can very well live with 90% coverage if I know what the missing 10%
are rather than testing for the sake of making a good impression with a 100%
report.
- Reto
On Feb 12, 2014 9:37 PM, "Paul Benedict" <pb...@apache.org> wrote:
> 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
> <be...@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
Re: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Reto Hablützel <re...@rethab.ch>.
To follow up on Paul's answer, I would go as far as to say that I test my
code in order to feel comfortable that it actually does what it should do.
Thus, I can very well live with 90% coverage if I know what the missing 10%
are rather than testing for the sake of making a good impression with a
100% report.
- Reto
On Feb 12, 2014 9:37 PM, "Paul Benedict" <pb...@apache.org> wrote:
> 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
> <be...@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
>
Re: Code coverage with debug logs: 100% branch coverage not possible?...
Posted by Paul Benedict <pb...@apache.org>.
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
<be...@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