How to implement logging for an imported module?

[Robert Latest]

Hello,

I'm trying to add logging to a module that gets imported by another module. But
I only get it to work right if the imported module knows the name of the
importing module. The example given in the "Logging Cookbook" also rely on this
fact.

https://docs.python.org/3/howto/logging-cookbook.html#logging-cookbook

I couldn't find any information on how to implement logging in a library that
doesn't know the name of the application that uses it. How is that done?

Here's some example code consisting of the main module foo.py and imported
modules bar.py and baz.py


### foo.py
import logging

import bar, baz

formatter = logging.Formatter(
'%(asctime)s - %(name)s - %(levelname)s - %(message)s')

ch = logging.StreamHandler()
ch.setFormatter(formatter)

logger = logging.getLogger('foo')
logger.addHandler(ch)
logger.setLevel(logging.DEBUG)

logger.debug('debug from <%s>', __name__)
logger.info('info from <%s>', __name__)
logger.warning('warning from <%s>', __name__)
logger.error('error from <%s>', __name__)

bar.func()
baz.func()

### bar.py
'''This "generic" approach doesn't honor loglevel or formats
when imported by another module'''
import logging

l = logging.getLogger(__name__)
def func():
l.debug('debug from <%s>', __name__)
l.info('info from <%s>', __name__)
l.warning('warning from <%s>', __name__)
l.error('error from <%s>', __name__)

### baz.py
'''This only works if the importing module is named 'foo', which
precludes its use as a library module'''
import logging

l = logging.getLogger('foo.baz')
def func():
l.debug('debug from <%s>', __name__)
l.info('info from <%s>', __name__)
l.warning('warning from <%s>', __name__)
l.error('error from <%s>', __name__)

[Dieter Maurer]

Robert Latest wrote at 2021-3-7 10:21 GMT:
>I'm trying to add logging to a module that gets imported by another module. But
>I only get it to work right if the imported module knows the name of the
>importing module. The example given in the "Logging Cookbook" also rely on this
>fact.

I have used so called "monkey patching" to achieve something like this
(in fact "function call tracing").
"monkey patching" means code modification at runtime.

Suppose your application implements a logging decorator `log`.
Then on import, you can replace methods (easiest) or functions
with decorated variants either directly in the imported module/class
or for use by the importer.

[Joseph L. Casale]

> I couldn't find any information on how to implement logging in a library that
> doesn't know the name of the application that uses it. How is that done?

Hello,
That's not how it works, it is the opposite. You need to know the name of its logger,
and since you imported it, you do.

Logging is hierarchical, organized by dot separated names. However, all loggers
share the same root (top level) logger (a logger without any name, or in other words,
no hierarchical specificity). Loggers are singletons, all loggers share the same root
and each time you get a logger, if any code has previously asked for that logger by
name and therefore created it, you'll get that instance.

When you create a logger, it starts at level WARNING, which means only warnings
or higher are considered.

When you create a handler, it starts at level NOTSET, which means only level 0
and above are considered. Since NOTSET is 0, everything is considered by default.

Loggers pass messages that they are considering to all their handlers, which then
each filter again by the handlers own distinct level.

Don't add handlers in library code (except a null handler).

Do set a level on your library logger that you deem appropriate (INFO is likely
not appropriate).

Then, in your consuming code, if you instantiate a named logger, you won't see
messages that fall below the threshold of the library, and root defaults.

Create (get) a root logger (you don't have to use it) and set the level, and attach a
handler to it. Then get the logger your library uses and set the level to what you want.

Proceed with creating your own named logger and using that in your code, however
when the library emits a log message, it will traverse up, unfiltered and be passed to
a handler.

Think of the process like a tree data structure, with the single root at the top, and
each immediate child being a named logger without additional specificity (no dot),
and each child of those taking the named plus one dot, followed by another name.

That helps when understanding the design behavior of propagation, and rather than
restate what is already well done, see https://docs.python.org/3/library/logging.html#logging.Logger.propagate.

It does make a lot of sense, and it facilitates a concise and powerful ability to configure
an application where some messages can be ignored, written to different files, combined
into one, or some even emailed.

Last word of advice, don't fight it by hacking up or patching (somehow?), it will
simply not work right for any other case even slightly different than the one you
somehow beat into submission.

I hope that helps,
Joseph Casale

[Pankaj Jangid]

"Joseph L. Casale" <jca...@activenetwerx.com> writes:

>> I couldn't find any information on how to implement logging in a
>> library that doesn't know the name of the application that uses
>> it. How is that done?

> Create (get) a root logger (you don't have to use it) and set the
> level, and attach a handler to it. Then get the logger your library
> uses and set the level to what you want.

So does that mean if we change the following code to get a logger
without any name then it will work? Without any further change.

>> logger = logging.getLogger('foo')
>> logger.addHandler(ch)
>> logger.setLevel(logging.DEBUG)

--
Regards,
Pankaj Jangid

[Robert Latest]

Joseph L. Casale wrote:
>> I couldn't find any information on how to implement logging in a library that
>> doesn't know the name of the application that uses it. How is that done?
>

> That's not how it works, it is the opposite. You need to know the name of its
> logger, and since you imported it, you do.

[much snipping]

> Last word of advice, don't fight it by hacking up or patching (somehow?), it
> will simply not work right for any other case even slightly different than
> the one you somehow beat into submission.

I didn't waht to hack the logging system, it's just that I wasn't sure of its
design principles. I had hoped that if I set up a logger (including levels and
formatter) in my main app, the loggers in the imported modules would somwhow
automagically follow suit. Now I understand that for each imported module I
must import its logger, too, and decide how to deal with its messages.

> I hope that helps,

Much appreciated,
robert

[Richard Damon]

Each instance of the logger inherents from a 'parent' logger, except for
the top level logger which has the name None (as in the singleton of
NoneType), and unless told otherwise will inherit it properties from its
parent.

Thus, if you get the root logger with logging.getLogger() you can set
properties there, and unless a child logger has specifical been told not
to inherit or has been specifically given a different value.

General convention is that modules will use their name as the name of
their logger, as that is generally unique.

--
Richard Damon

[Robert Latest]

I must admit I'm still struggling with the very basics of logging. I don't
understand the behavior of the code samples below at all, see comments.
It seems that logging.debug() et al have some side effects that are required
to get a logger to notice its level in the first place.


# Example 1:
# Why does the logger "mylog" require
# a call to the root logger in order to work?

import logging

mylog = logging.getLogger('foo')
mylog.setLevel(logging.DEBUG)

mylog.debug('1 mylog.debug()') # prints nothing
logging.debug('2 logging.debug()') # prints nothing
mylog.debug('3 mylog.debug()') # works


# Example 2:
# Why do I have to call 'logging.debug' before the root
# logger works?

import logging

mylog = logging.getLogger() # now mylog is the root logger
mylog.setLevel(logging.DEBUG) # setting level of root logger

mylog.debug('1 mylog.debug()') # prints nothing, why?
logging.debug('2 logging.debug()') # works
mylog.debug('3 mylog.debug()') # works

[Peter Otten]

Because logging.debug() implicitly calls basicConfig() if there are no
handlers yet for the root logger. You should always configure your
handlers explicitly, usually by a call to logging.basicConfig().

>
> import logging

# - set the root logger's level
# - add a handler to the root logger
logging.basicConfig(level=logging.DEBUG)

> mylog = logging.getLogger('foo')

In most cases I want the same log-level for all loggers, so I'd omit the
line below.