maven-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Benoît Berthonneau <ben...@berthonneau.com>
Subject Re: Code coverage with debug logs: 100% branch coverage not possible?...
Date Thu, 13 Feb 2014 16:28:24 GMT
 

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 <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 [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
<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 [7] Sauvez un arbre, Mangez un castor !
nbsp;! <users-help@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

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