Logging /w several modules/libraries

[Lou]

I’m on my ragged edge here with getting logging to live up to the hip. My current project with several modules and two library files has an error (maybe more than one). When I stated the project I just keep adding print statements wrapped in “if VERBOSE:” statements to keep track of what was going on. Now with a real problem this isn’t working. So added logging to my learning curve.
Replaced all the “prints” with “logger” statements and got things to work. Nice logger names for each module/class, several levels that seem logical. However, still lots of clutter hiding where the problem(s) is.
Using HOWTO, as a starting point looks like there should be at least 2 ways to filter out some of the log entries.

1. At the module level assign a nul handler to a logger to send entries to the bit bucket. In the code below in module fan, line 18, trying to block those entries. This is suggested for a library module. logging.getLogger(__name__).addHandler(logging.NullHandler())
   
2. At a global level useing filters to block selected entries. What little I can find to read suggest to me these are inclusive filters not exclusive filters. I haven’t found enough information to even try this approach.
   

Either approach is better than removing logger lines then later wishing I had them. Conceptually filters could be more granular than just blocking a whole module. BUT I could use some pointers to get either to work. As you can see from the output all the "INFO:fan:Level x" clutter hides what is going on between traffic and command.

Running the code from the IDE or using this short script .

cd /……………/testing
python3 TT3.py 2> testout.txt

#!/usr/bin/python3.7
"""
===========
Module TT_3
===========

"""
import logging
import fan
# import signals


def main():

    logging.basicConfig(filename='TT3.log', filemode='w', level=logging.DEBUG)
    logging.info("starting TT3")

    import traffic
    # import a fan module to run the fan and call FanLib

    f = fan.Run()                   # start updating the fan display
    t = traffic.Traffic()
    logging.debug("Got Here")
    try:
        while True:
            pass

    except KeyboardInterrupt:
        logging.info("Clean up")
        f.stop()
# end of main


if __name__ == '__main__':
    main()
logging.info("The End")

#!/usr/bin/python3.7
"""
==============
Module traffic
==============
"""

import threading
from command import Command
from time import sleep
import logging
logger = logging.getLogger(__name__)


class Traffic:
    def __init__(self) -> None:

        logger.info("starting Traffic")

        # Class to process all RPi commands
        self.com = Command()
        # initialize Monitor LEDs
        self.led = Monitor()

        # start thread to listen for LapTop
        thread_lt = threading.Thread(target=self.read_lt)
        thread_lt.start()

    def read_lt(self):
        for i in range(3):
            sleep(3)
            msg = "msg " + str(i)
            cmd_type = self.com.check(str(msg))
            logger.debug("Command type: %s", str(cmd_type))

        print("Should be done")
        logger.debug("Should be done")

# end class traffic


class Monitor:
    def __init__(self) -> None:
        self.logger = logging.getLogger("Monitor")

#!/usr/bin/python3.7
"""
==========
Module fan
==========

"""

import logging
import threading
from time import sleep
logger = logging.getLogger(__name__)


class Run:
    def __init__(self) -> None:
        logger.info("starting Fan")
        logging.getLogger(__name__).addHandler(logging.NullHandler())

        self.run_forever = True
        thread = threading.Thread(target=self.main, args='')
        thread.start()
    # end of __init__

    def main(self) -> None:

        count = 0
        while self.run_forever:
            sleep(1)
            logger.info("Level %d", count)
            count += 1

    def stop(self):
        self.run_forever = False
        logger.info(" stopping")

#!/usr/bin/python3.7
"""
===============
Module command
===============

"""
import logging
logger = logging.getLogger(__name__)


class Command:
    """
    """

    def __init__(self):
        """
        """

        logger.info("starting Command")

    def check(self, msg: str) -> int:
        """
        """
        logger.info("Message: %s", msg)
        return 42

Output:
INFO:root:starting TT3
INFO:fan:starting Fan
INFO:traffic:starting Traffic
INFO:command:starting Command
DEBUG:root:Got Here
INFO:fan:Level 0
INFO:fan:Level 1
INFO:command:Message: msg 0
DEBUG:traffic:Command type: 42
INFO:fan:Level 2
INFO:fan:Level 3
INFO:fan:Level 4
INFO:command:Message: msg 1
DEBUG:traffic:Command type: 42
INFO:fan:Level 5
INFO:fan:Level 6
INFO:fan:Level 7
INFO:command:Message: msg 2
DEBUG:traffic:Command type: 42
DEBUG:traffic:Should be done
INFO:fan:Level 8
INFO:fan:Level 9
INFO:fan:Level 10
INFO:fan:Level 11
INFO:fan:Level 12
INFO:fan:Level 13
INFO:fan:Level 14
INFO:root:Clean up
INFO:fan: stopping
INFO:root:The End
INFO:fan:Level 15

[Larz60+]

When I develop code, I do it in small steps, usually a method at a time, then make sure that the method works before moving on.
To do this, I will occasionally use a well placed print statement, but remove it once I am satisfied all is working as expected.

What is more valuable to me is to step through the method, checking all variable contents and program flow, step by step, using the debugger.

Too many print statements, or logger statements will make your code unreadable, or messy at best.

[snippsat]

Use Loguru then you get rid of all clutter boilerplate code.
What did before using standard logging was hiding all cluttering boilerplate code and import it.
Loguru make this much more enjoyable as has little boilerplate and @logger.catch decorator for Exceptions catching

[Lou]

I have found an answer to my original question, within the logging package. I am still looking at the filter option.

Staying inline with my OP I want to easily, temporally, eliminate the logging "clutter" from module fan (assume the fan is not related to what we are currently working on.)

The following line of code can be added to in the main file, TT3.py, after line 15, the basic logger configuration. The line could also be added to the fan module.

logging.getLogger("fan").propagate = False

This line will stop the "propagation" of log records from module/logger "fan" up to its parent logger, in this case "root". Setting propagate to True (the default) will again include all level appropriate log lines in the output.

A related solution is to include a line like the following. Again it can be put in the main file after the basic configuration.

logging.getLogger("fan").level = logging.WARNING

This changes the logging level for the named logger only so the debug and info lines from "fan" are blocked but warning and higher lines are included. They may be informative.

In my current project code is divided into ~10 modules/classes with 2 custom libraries. Each module is at a different level of completion with some details stubbed out so all the interfaces work, but without some functionality.
With versions of the two lines above I can limit logging to the area I am currently working on without removing and later replacing monitoring lines in other modules. That remove-and-replace scenario is what I wanted to avoid by switching from 'print' to logging.

Placing all the .propagate and .level lines in the main file keeps all the controls in one place.