How does logging level get set?

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

How does logging level get set?

James McMahon
Good morning. I am confused about logging levels from within java code that
defines a nar.

I have a java class file AMQPWorker.java, within which I establish a logger
used throughout my nar. This is what I inherited in the class:

abstract class AMQPWorker implements AutoCloseable {
     private final static Logger logger =
LoggerFactory.getLogger(AMQPWorker.class);

Later in this class there is a method that appears to check the log level
prior to publishing a message to the log, like so

     if (logger.isDebugEnabled()) {
          logger.debug("some debug message");
     }

When this if statement is executed, what exactly is being checked to verify
whether isDebugEnabled() returns true or false?
I can't find anywhere that the log level is set within the code.
How does the logging level get set?
Does the nar somehow inherit the logger properties set in logback.xml?
And if it does, wouldn't we always want the logging configuration in
logback.xml to be the level that allows any logging level from within the
code, a la logger.debug(), .info(), .warn(), etc?

Bottom line for me: throughout my code I want to be sure when I use a
particular logging level to determine if a message gets logged to my logger
or not, that level is respected.

Thank you for any help.
Reply | Threaded
Open this post in threaded view
|

Re: How does logging level get set?

Kevin Doran
Hi,

Logging level is set in logback.xml. To change the logging level for a given logger/package/class, you must modify that file. See [1] for more details.

In your code example, you are creating the logger correctly using the LoggerFactory. All NiFi Frameworks and extensions use the slf4j API, which is configured by logback.xml. That is why you do not see any explicit setting of log levels in our codebase - the logging framework we are using takes care of that.

With regards to why you will sometimes see logging gated by "if (logger.isDebugEnabled()) { .. }" conditionals: this is not strictly necessary, but is useful in a few scenarios.  One case is when the construction of the log message itself is expensive and adds non-trivial overhead, and you don't want to incur that expense unless you are actually logging the message. Consider the following:

    String jsonRepresentationOfX = x.toJsonString();
    logger.debug("The JSON representation of x is: {}", jsonRepresentationOfX");

If the log level is not set to debug, then the call to logger.debug(...) is a no-op; however, you still incur the overhead of the call to x.toJsonString(). This is a somewhat contrived example, but in an unavoidable situation you can see where sometimes gating a block of code by the logger.isDebugEnabled() conditional can save computation that is only necessary when you need to log the result.

The rule of thumb I follow (though others can chime in with their own thoughts on the subject), is to almost always log using the simple logger.{level}("my logging message") methods without worrying much about adding additional guards. But if you do run into a situation where you want your code to behave differently depending on the log level aside from just what shows up in the log, that is what those lookup methods on the logger object are there for.

[1] https://community.hortonworks.com/articles/106931/nifi-debugging-tutorial.html

Hope this helps,
Kevin


´╗┐On 9/11/18, 08:38, "James McMahon" <[hidden email]> wrote:

    Good morning. I am confused about logging levels from within java code that
    defines a nar.
   
    I have a java class file AMQPWorker.java, within which I establish a logger
    used throughout my nar. This is what I inherited in the class:
   
    abstract class AMQPWorker implements AutoCloseable {
         private final static Logger logger =
    LoggerFactory.getLogger(AMQPWorker.class);
   
    Later in this class there is a method that appears to check the log level
    prior to publishing a message to the log, like so
   
         if (logger.isDebugEnabled()) {
              logger.debug("some debug message");
         }
   
    When this if statement is executed, what exactly is being checked to verify
    whether isDebugEnabled() returns true or false?
    I can't find anywhere that the log level is set within the code.
    How does the logging level get set?
    Does the nar somehow inherit the logger properties set in logback.xml?
    And if it does, wouldn't we always want the logging configuration in
    logback.xml to be the level that allows any logging level from within the
    code, a la logger.debug(), .info(), .warn(), etc?
   
    Bottom line for me: throughout my code I want to be sure when I use a
    particular logging level to determine if a message gets logged to my logger
    or not, that level is respected.
   
    Thank you for any help.
   
Reply | Threaded
Open this post in threaded view
|

Re: How does logging level get set?

Mohammed Nadeem
In reply to this post by James McMahon
Hi,

To answer to your question, Nifi has a context logger which is mapped to
logback.xml file. Generally INFO level of log is defaulted in nifi-app.logs.
In your code, you can simple use getLogger().debug("your message") or INFO,
ERROR,WARN etc to enable the logging into nifi-app.log with component-id
etc.

As I mentioned, by default INFO level would go to nifi-app.logs, you can
change the level in logback.xml under root.

Thanks & Regards,
Nadeem



--
Sent from: http://apache-nifi-developer-list.39713.n7.nabble.com/
Reply | Threaded
Open this post in threaded view
|

Re: How does logging level get set?

Jeff
One point for using the isDebugEnabled (or any of the other level-checking
methods) is that if, in the values being logged, there is string
concatenation happening in the log.{level} statement itself. The cost of
that is paid whether the level is enabled or not.  Even with parameterized
logging, if the log.{level} call is passed a method invocation as a
parameter, the cost is paid there as well, as Kevin mentioned.

The best rule of thumb, IMO, is to use the enabled check if a parameter or
result of string concatenation with something being logged will cause
computation that is "expensive", such as sorting a list, especially if the
logging would be invoked iteratively.  If there's a loop that executes with
"many iterations", but has debug logging that is doing string
concatenation, that would be a good scenario to use the enabled check,
though parameterization with literal values helps in that case. If the
value you are using in a logging call comes from a getter which retrieves
something that's in a literal form, like a getter that returns a boolean
variable, that would be inexpensive.  Calling some list.size() methods are
also pretty cheap.  Even "cheap" operations can add up if the logging is
done iteratively.

Adding a lot of isDebugEnabled checks can make the code less readable and
add many extra lines of code.  Those checks might be necessary to prevent a
decrease in performance, though.  You can always run a profiler to see how
much time you can save when a particular logging level is not enabled, and
update the code with enabled checks as necessary.

On Thu, Sep 20, 2018 at 3:37 PM Mohammed Nadeem <[hidden email]>
wrote:

> Hi,
>
> To answer to your question, Nifi has a context logger which is mapped to
> logback.xml file. Generally INFO level of log is defaulted in
> nifi-app.logs.
> In your code, you can simple use getLogger().debug("your message") or INFO,
> ERROR,WARN etc to enable the logging into nifi-app.log with component-id
> etc.
>
> As I mentioned, by default INFO level would go to nifi-app.logs, you can
> change the level in logback.xml under root.
>
> Thanks & Regards,
> Nadeem
>
>
>
> --
> Sent from: http://apache-nifi-developer-list.39713.n7.nabble.com/
>