allow multiple handlers per logger

[vladak]

This change adds the possibility to have multiple handlers per logger. My motivation for this was a specific use case, that is a MQTT handler that I'd like to use in addition to the classic stream handler to make it easier to see what is going on with my QtPy's:

from adafruit_logging import LogRecord, Handler
import adafruit_minimqtt.adafruit_minimqtt as MQTT
import ssl
import atexit


class MQTTHandler(Handler):
    def __init__(self, pool, broker: str, port: int, topic: str) -> None:
        """
        Setup MQTT broker connection for the specified topic.
        """
        super().__init__()

        self._mqtt_client = MQTT.MQTT(
            broker=broker,
            port=port,
            socket_pool=pool,
            ssl_context=ssl.create_default_context(),
        )

        self._topic = topic

        self._mqtt_client.connect()

        # To make it work in CPython.
        self.level = logging.WARNING

        # using weakref.finalize or defining __del__(self) might be wiser, depending on Python flavor.
        # In CPython, close() would be called from logging.shutdown()
        atexit.register(self.close)

    def close(self) -> None:
        self._mqtt_client.disconnect()

    def emit(self, record: LogRecord) -> None:
        """
        Publish message from the LogRecord to the MQTT broker.
        """
        self._mqtt_client.publish(self._topic, record.msg)

and the actual use:

import adafruit_logging as logging
import socket
from mqtt_handler import MQTTHandler
import json


logger = logging.getLogger(__name__)
mqtt_topic = "devices/cupboard/qtpy"
mqttHandler = MQTTHandler(socket, "172.40.0.3", 1883, mqtt_topic)
logger.addHandler(mqttHandler)
data = {"foo": "bar"}
logger.warning(json.dumps(data))

While this seemed like a no brainer change initially, I had to do some choices that might not be in concordance with the intended use of this library. Namely:

• a one-off warning is issued when there are no handlers in given logger and message is to be emitted
• a warning message to stderr is printed if one of the handlers' emit() raises exception

Specifically the second choice is a bit stronger than what is found in CPython (see the comments on differences I found between CPython and CircuitPython logging on [1]), however my feeling was that in embedded environment (where CircuitPython is more likely to be used, I think) it is more important to make sure all the handlers are visited during emit(), no matter what the individual outcome is. To see how it works in action, consider this handler:

from adafruit_logging import LogRecord, Handler


class RogueHandler(Handler):
    def __init__(self) -> None:
        """Defer the initialization to the parent.
        """
        super().__init__()

    def emit(self, record: LogRecord) -> None:
        """Raise exception.
        """
        raise Exception("broken emit")

and its use:

import adafruit_logging as logging
from rogue_handler import RogueHandler

logger = logging.getLogger(__name__)
rogueHandler = RogueHandler()
logger.addHandler(rogueHandler)
fileHandler = logging.FileHandler("log.txt")
logger.addHandler(fileHandler)
print(f"handler list: {logger._handlers}")
logger.warning("foo")

which produces the following to the console:

handler list: [<adafruit_logging.StreamHandler object at 0x10b3b6370>, <rogue_handler.RogueHandler object at 0x10b3b63d0>, <adafruit_logging.FileHandler object at 0x10b3e1700>]
0.057: WARNING - foo
Handler <rogue_handler.RogueHandler object at 0x10adfa460> produced exception: broken emit

and the log.txt file will actually contain the log record.

If you want this to behave differently, just let me know in comments and I will change it.

There do not seem to be any tests, let me know how to proceeed there. I only ran the above programs using Blinka.

[1] https://gist.github.com/vladak/15788891bdc2d4742dd106d65667b5a9

[FoamyGuy]

I tested this out with a Feather S2 TFT and noticed some differences from current released version behavior that I'm not sure if were intentional or not.

The simpletest script inside this repo run with the current released version outputs this:

code.py output:
6081.068: ERROR - Error message

When the same example is run with the version from this PR branch it outputs multiple times to the error level:

code.py output:
6229.832: ERROR - Error message
6229.832: ERROR - Error message
6229.836: ERROR - Error message

Was this change intentional? It seems that the first two prints are duplicates from logger.error("Error message") and the 3rd one is from the null logger further down in the example null_logger.error("Error message") which is intended not to print if my understand is correct.

[vladak]

Was this change intentional? It seems that the first two prints are duplicates from logger.error("Error message") and the 3rd one is from the null logger further down in the example null_logger.error("Error message") which is intended not to print if my understand is correct.

Good catch. This is expected, although the behavior is undesired and not matching CPython. This stems from the difference to CPython that has a concept of "last resort" handler. In CircuitPython logging a StreamHandler is automatically added in getLogger() and no distinction is made between this default logger and loggers added via addLogger().

Will need to change this somewhat.

[FoamyGuy]

Looks good to me. I tested the changes successfully on a Feather S2 TFT using a modified version of the simpletest to use multiple handlers (one file, one stream in my case.)

Thanks for working on this @vladak!

Do you know if your MQTT handler could work with adafruit.io as the backend server instead of a custom one? Or is there some specific behavior in your server that allows that to work? If it's possible to do that with adafruit.io, I'd be in favor of sharing that as an additional example in this repo if you're open to that idea. I could see that being particularly useful for projects that are in inconvenient to access locations.

Thanks for the improvements to simpletest script as well. The additional case, and labels printed make it more clear what's happening and how the class behaves with different possible inputs.

[vladak]

Sure ! With Adafruit IO this works rather nicely. Will submit a PR with the example.

As for the tests, there is a big room for improvement. I was thinking about mocking, however it needs some more thought.