Re: Code coverage with debug logs: 100% branch coverage notpossible?...

[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