Page 1 of 1

Best practices for debug and logging output in library modules

Posted: Wed Aug 21, 2019 3:56 pm
by cdwilson
(sorry for the formatting, BBCode seems to be disabled for my account and I can't figure out how to enable it... if you know how to fix this, please let me know!)

I'm in the middle of writing my first library module in micropython that makes use of the machine.I2C class, and as part of the bring up process for the chip, I wanted to add logging output (I2C reads/writes, etc).

For a CPython library, the logging module is included in the standard library, so you can set up debug logging within the library module like the following:

(module.py)

Code: Select all

import logging
# https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library
logging.getLogger('foo').addHandler(logging.NullHandler())
logger = logging.getLogger(__name__)
logger.debug('This is a test log message.')
Then, whoever imports the module can configure what level of log messages they want to display when they use your library:

(main.py)

Code: Select all

import logging
logging.basicConfig(level=logging.DEBUG)
However, for micropython, it's not guaranteed that the logging.py module exists on the system that is importing the library module:

Code: Select all

>>> import logging
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ImportError: no module named 'logging'
It looks like there has been some discussion a couple years ago around this topic:
https://github.com/micropython/micropyt ... -274002185

The uasyncio module looks like it tries to deal with this by importing logging when DEBUG is set, but I didn't come across any other examples of how this is handled in the lib:
https://github.com/micropython/micropyt ... t__.py#L10

I'm curious if some of the more experienced folks have any best practices or standard ways of writing micropython libraries that deal with this nicely. I guess one option is to take the uasyncio approach and just document that the library requires logging.py.

Another possibility is to try to use the logging module if it exists, for example:

(module.py)

Code: Select all

try:
    import logging
    logger = logging.getLogger(__name__)
except ImportError:
        pass

class MyDriver(object):
    def _i2c_read_register(self, register, result):
        ...
        if __debug__ and ('logging' in sys.modules) and (logger.isEnabledFor(logging.DEBUG)):
            logger.debug("Read %s from register 0x%x" % (bytes(result), register))
        ...
    def _i2c_write_register(self, register, data):
        ...
        if __debug__ and ('logging' in sys.modules) and (logger.isEnabledFor(logging.DEBUG)):
            logger.debug("Write %s to register 0x%x" % (data, register))
        ...
This would allow the library module to just work whether or not logging.py has been included in the target system. Any thoughts on how to best approach this?

Re: Best practices for debug and logging output in library modules

Posted: Wed Aug 21, 2019 4:07 pm
by dhylands
The first few posts for each user require moderator approval. During this time, BBCode is also disabled. Once you've made enough posts that you no longer require moderator approval, then BBCode gets enabled, including for your original posts which required moderator approval.

Re: Best practices for debug and logging output in library modules

Posted: Wed Aug 21, 2019 8:03 pm
by stijn
Couple of random thoughts, not enough time for a complet answer atm: there's a basic implementation of the logging module in https://github.com/micropython/micropyt ... er/logging.

Code: Select all

    if __debug__ and ('logging' in sys.modules) and (logger.isEnabledFor(logging.DEBUG)):
            logger.debug("Read %s from register 0x%x" % (bytes(result), register))
Even if you don't use the aforementioned logging, instead of this it would still be more interesting to write a dummy logging module and Logger class with a isEnabledFor method which does the if __debug__ etc so you don't have to repeat that all over the place.

Usually there's no need to call isEnabledFor manually: the actual logging module does that already in each call. But perhaps you're explicitly calling isEnabledFor because you don't want to do the string formatting? Well, you shouldn't have to do the formatting yourself, but instead call the logging functions with the arguments. The idea being that is exactly that you don't do the formatting unless actually needed, i.e. you use logger.debug("Read %s from register 0x%x", bytes(result), register), it calls isEnabledFor and whatever filtering internally and only when needed formats the message. Ok you're still paying for the call to bytes() but I wouldn't be surprised if that can be worked around with some custom formatting.

tldr; logging in Python is meant to be simple at the client side and all the complicated parts go in the configuration, the idea really is that all you do is logger.debug('abc %d, someValue) (or even logging.debug() to keep things even simpler) and whether or not, and where, it gets effectively logged is up to the filtering/formatting/... configuration. At least that's how I tend to look at it.

Re: Best practices for debug and logging output in library modules

Posted: Thu Aug 22, 2019 5:17 am
by cdwilson
@stijn thanks for the reply. I should have mentioned I'm already using the logging.py module from micropython-lib which essentially does what I need it to do from a debug perspective. The main issue I was originally trying to get at in my OP was how to handle the fact that logging.py may or may not be present for other people using my library, and how best to write the module to deal with that gracefully (or maybe it's not worth worrying about?).

You're totally right, I didn't realize that you can just call the logging functions with arguments... Normally you wouldn't need the call to isEnabledFor unless there is a case where computing the arguments for the log message is expensive (see https://docs.python.org/3/howto/logging ... timization for where I got this from originally)

Re: Best practices for debug and logging output in library modules

Posted: Thu Aug 22, 2019 7:54 am
by stijn
The main issue I was originally trying to get at in my OP was how to handle the fact that logging.py may or may not be present for other people using my library, and how best to write the module to deal with that gracefully (or maybe it's not worth worrying about?)
Ah sorry didn't catch that.

One thing you could improve in your current code is the condition: whether logging is available in sys.modules or not isn't a true prerequisite for the logger variable existing or not, and it's a lookup so there are faster and simpler ways:

Code: Select all

try:
  if __debug__:
    logger = None
  else:
    import logging
    logger = logging.getLogger(__name__)
except ImportError:
  logger = None
  
if logger and logger.isEnabledFor(logging.DEBUG):
  logger.debug("Read %s from register 0x%x", bytes(result), register)
Or more elaborate and compatible with logging and to also get rid of the (if logger) part:

Code: Select all

try:
  if __debug__:
    logger = None
  else:
    import logging
    logger = logging.getLogger(__name__)
except ImportError:
  logger = None

if not logger:
  class Logger:
    DEBUG = 0
    def isEnabledFor(self, _):
      return False
  logger = Logger()
  logging = logger

if logger.isEnabledFor(logging.DEBUG):
  logger.debug("Read %s from register 0x%x", bytes(result), register)
And then going further I'd figure out a way to get rid of isEnabledFor by passing result and deferring the bytes() call, but I don't know what type your result variable is so can't help there.

Re: Best practices for debug and logging output in library modules

Posted: Thu Aug 22, 2019 9:56 pm
by cdwilson
FYI, I think the if __debug__ logic in your code is backwards, i.e. should be:

Code: Select all

try:
    if __debug__:
        import logging
        logger = logging.getLogger(__name__)
    else:
        logger = None
except ImportError:
    logger = None
The more elaborate approach also requires the check for isEnabledFor before any call to logger.debug (since the fake Logger class doesn't have a debug method).

Here's what I ended up doing:

Code: Select all

if __debug__:
    try:
        import logging
    except ImportError:
        class Logger:
            DEBUG = 10
            def isEnabledFor(self, _):
                return False
            def debug(self, msg, *args):
                pass
            def getLogger(self, name):
                return Logger()
        logging = Logger()

    logger = logging.getLogger(__name__)
Then, in the rest of the module, debug statements are added like this:

Code: Select all

if __debug__:
    logger.debug("Debug message")

# for debug where computing the arguments for the log message is expensive
if __debug__ and logger.isEnabledFor(logging.DEBUG):
    logger.debug('Message with %s, %s', expensive_func1(), expensive_func2())
If __debug__ is False, all the debug logging code in the entire module is completely optimized away.

If __debug__ is True, then it tries to import the logging module. If that fails, dummy logging/logger objects are created that do nothing. From that point on, the rest of the code can be written without caring if logging is imported or not, i.e. you can just use logging.getLogger, logging.DEBUG, logger.debug normally.

Re: Best practices for debug and logging output in library modules

Posted: Fri Aug 23, 2019 7:14 am
by stijn
cdwilson wrote:
Thu Aug 22, 2019 9:56 pm
FYI, I think the if __debug__ logic in your code is backwards, i.e. should be:
Oops, yes :)