[BUG] Library throwing DEBUG log msgs, even when set for INFO Level.

[ajonnet]

Debug level logs are being thrown by the library, irrespective of what value is supplied for "verbose_console" param for constructor Picamera2(). It happens when log handlers are defined prior to calling of constructor.

Due to above behaviour, Logs are filled up with debug statements being generated by the library.

To Reproduce import logging from picamera2 import Picamera2

logger = logging.getLogger("") formatStr = '[%(asctime)s] [%(threadName)s] [%(levelname)s]: %(message)s' console = logging.StreamHandler() console.setFormatter(logging.Formatter(formatStr)) logger.addHandler(console) logger.setLevel(logging.INFO) picam=Picamera2(verbose_console=1)

Console Output [0:33:57.988721016] [91] INFO Camera camera_manager.cpp:293 libcamera v0.0.0+3866-0c55e522 [0:33:58.091540556] [95] WARN RPI raspberrypi.cpp:1258 Mismatch between Unicam and CamHelper for embedded data usage! [0:33:58.093436522] [95] INFO RPI raspberrypi.cpp:1374 Registered camera /base/soc/i2c0mux/i2c@1/imx219@10 to Unicam device /dev/media3 and ISP device /dev/media0 2022-09-09T06:32:59.722Z | INFO | Initialization successful. [2022-09-09 12:02:59,722] [MainThread] [INFO]: Initialization successful. 2022-09-09T06:32:59.723Z | INFO | Camera now open. [2022-09-09 12:02:59,723] [MainThread] [INFO]: Camera now open. [2022-09-09 12:02:59,723] [MainThread] [DEBUG]: <libcamera._libcamera.CameraManager object at 0x7f90beda30>

Expected behaviour As verbose_console is set to 1, below debug statement should not have generated [2022-09-09 11:34:32,216] [MainThread] [DEBUG]: <libcamera._libcamera.CameraManager object at 0x7fae3a4bb0>

Hardware : Pi 3B OS: BullsEye Package: python3-picamera2 Version: 0.3.3-1

To avoid the issue, below patch works for now (to be called after initialization of Picamera2) logger = logging.getLogger('picamera2') logger.setLevel(logging.INFO)

[davidplowman]

Hi, thanks for raising this. Unfortunately I don't know much about the Python logging module, but here's what I found out.

Firstly, it's clear the the debug message is being printed by the logger that gets created in the test script, not by the Picamera2's logger (this is clear from the format of the message).

So it seems to me like the Picamera2 logger is correctly not outputting anything but "propagating" the message to the parent, which is logger in the script. (I think logger is actually the "root" logger.)

Anyway, could it be that this "propagation" by-passes filters on the logger, but only heeds filters on the handlers? If you change logger.setLevel(logging.INFO) to consode.setLevel(logging.INFO) then the message no longer appears. In fact, I found this flow diagram which, if I'm interpreting it correctly, demonstrates exactly this behaviour.

Does this sound correct? Like I said, I hesitate a little just because I'm not terribly familiar with the behaviour of this module. But in any case I can't really see that Picamera2 could do anything to provoke this behaviour, it does seem intrinsic to the logging module.

[davidplowman]

I've been experimenting a bit with this simplified test case:

import logging

class Dummy:
    def __init__(self, level=logging.INFO):
        self.logger = logging.getLogger("Dummy")
        self.logger.setLevel(logging.DEBUG)
        console = logging.StreamHandler()
        console.setLevel(level)
        console.setFormatter(logging.Formatter('[Dummy]: %(message)s'))
        self.logger.addHandler(console)

    def do_something(self):
        self.logger.debug("I am doing something")

logger = logging.getLogger()
logger.setLevel(logging.INFO)
console = logging.StreamHandler()
console.setFormatter(logging.Formatter('[Script]: %(message)s'))
logger.addHandler(console)
logger.setLevel(logging.INFO)
logger.debug("This should not appear")

dummy = Dummy(level=logging.INFO)
dummy.do_something()

which exhibits the same problem - it outputs the I am doing something message which is perhaps not expected.

If I replace logger.setLevel(logging.DEBUG) in the __init__ method by logger.setLevel(level) then the problem goes away. But then, if I also change dummy = Dummy(level=logging.INFO) to dummy = Dummy(level=logging.DEBUG) then the I am doing something message gets output by both loggers!

So it really does seem to be down to the rules of propagation and filters on loggers. If anyone can say what the most correct implementation of the Dummy class should be, then I'll copy that in Picamera2. Thanks!

[tvoverbeek]

@davidplowman I think you forgot something in the DUMMY init function:

    def __init__(self, level=logging.INFO):
        self.logger = logging.getLogger("Dummy")  <---
        self.logger.setLevel(logging.DEBUG)       <---
        console = logging.StreamHandler()
        console.setLevel(level)
        console.setFormatter(loggin
        self.logger.addHandler(console)           <---

Without self you define properties of the global logger. I have been bitten myself a few times by forgetting self for a class object ;-)

[davidplowman]

@tvoverbeek Ah, thanks for that, have edited the original in case anyone wants to try it! Though weirdly none of the behaviour seems to change. The rules here seem a bit twisty... :(

[tvoverbeek]

OK, I believe I now understand how it works. In the original post from @ajonnet there are 2 loggers defined. The root logger in the main program and the picamera2 logger. They are arranged hierarchically: any message from the picamera2 logger is also passed to the root logger. The picamera2 logger has a setting logging.DEBUG. The picamera2 messages are filtered by the streamhandler(s). The picamera2 streamhandler blocks DEBUG mesages (console_verbosity=1) But the root streamhandler has no level defined so it passes everything. You see it in @ajonnet's output all INFO messages occur twice: first from the picamera2 logger followed by the root logger. In @ajonnet's code (and in @davidplowman's example) replace the logger.setLevel(logging.INFO) just before the picam=Picamera2(verbose_console=1) line with console.setLevel(logging.INFO. Similar in @davidplowman's example. Then only the INFO messages appear twice and no DEBUG message.

However I think the logging concept should be changed. From the 'Advanced Logging Tutorial', the section on "Configuring logging for a library"(https://docs.python.org/3.9/howto/logging.html#configuring-logging-for-a-library):

It is strongly advised that you do not add any handlers other than [NullHandler]
(https://docs.python.org/3.9/library/logging.handlers.html#logging.NullHandler) to your library’s loggers.
This is because the configuration of handlers is the prerogative of the application developer who uses your
library. The application developer knows their target audience and what handlers are most appropriate for
their application: if you add handlers ‘under the hood’, you might well interfere with their ability to
carry out unit tests and deliver logs which suit their requirements.

The picamera2 logger should only set the logging level and not add any handlers. console-verbosity becomes logging-verbosity. Without a NullHandler even when the user does not use a logger, warning and error messages will still be written to stderr. I suppose this is the behavior we want. This avoids the double logging messages as in @ajonnet's example. What do you think?

[ajonnet]

OK, I believe I now understand how it works. In the original post from @ajonnet there are 2 loggers defined. The root logger in the main program and the picamera2 logger. They are arranged hierarchically: any message from the picamera2 logger is also passed to the root logger. The picamera2 logger has a setting logging.DEBUG. The picamera2 messages are filtered by the streamhandler(s). The picamera2 streamhandler blocks DEBUG mesages (console_verbosity=1) But the root streamhandler has no level defined so it passes everything. You see it in @ajonnet's output all INFO messages occur twice: first from the picamera2 logger followed by the root logger. In @ajonnet's code (and in @davidplowman's example) replace the logger.setLevel(logging.INFO) just before the picam=Picamera2(verbose_console=1) line with console.setLevel(logging.INFO. Similar in @davidplowman's example. Then only the INFO messages appear twice and no DEBUG message.

However I think the logging concept should be changed. From the 'Advanced Logging Tutorial', the section on "Configuring logging for a library"(https://docs.python.org/3.9/howto/logging.html#configuring-logging-for-a-library):

It is strongly advised that you do not add any handlers other than [NullHandler]
(https://docs.python.org/3.9/library/logging.handlers.html#logging.NullHandler) to your library’s loggers.
This is because the configuration of handlers is the prerogative of the application developer who uses your
library. The application developer knows their target audience and what handlers are most appropriate for
their application: if you add handlers ‘under the hood’, you might well interfere with their ability to
carry out unit tests and deliver logs which suit their requirements.

The picamera2 logger should only set the logging level and not add any handlers. console-verbosity becomes logging-verbosity. Without a NullHandler even when the user does not use a logger, warning and error messages will still be written to stderr. I suppose this is the behavior we want. This avoids the double logging messages as in @ajonnet's example. What do you think?

"configuration of handlers is the prerogative of the application developer who uses your library." -This is the principle that should hold. As part of my application code, i am already defining the required handlers and logging level. But when initialize_logger() from picamera2_logger.py is called, it overrides the behavior i expect by defining log level to DEBUG for picamera2. Logs from picamera2, should have merged as per logging configuration defined in application code.

"The picamera2 logger should only set the logging level and not add any handlers." -Here not even logging level should be defined by the library. It should be possible for application code to control what level of logs are to be generated.

I am naive with logs propagation principle. But expect it to be such that, logs from library principle should be controllable via application code.

[davidplowman]

Hi, thanks to everyone for the various investigations!

So my takeaway from all this is that Picamera2 probably should have its own logger (so that it can be controlled independently of anything else), but that it shouldn't be defining any handlers. It seems reasonable to set this logger to logging.DEBUG so that everything gets propagated to the root logger, I'm hoping there aren't any performance implications in doing that.

This potentially makes it a bit awkward to use for folks (like me, to be honest!) who just want to be able to get a few print statements coming out of the code. So perhaps there needs to be a helper function that can optionally be called to set up the logging for those of us who don't want to read lots of logging module documentation.

Finally, the logger probably needs to belong to the module, not to any Picamera2 object. In the latter case it would be impossible to configure the logger to see any debug during the construction.

So here's what I'm thinking:

import logging
import sys

_logger = logging.getLogger(__name__)
_logger.setLevel(logging.DEBUG)

class Dummy:
    DEBUG = logging.DEBUG
    INFO = logging.INFO
    WARNING = logging.WARNING
    ERROR = logging.ERROR
    CRITICAL = logging.CRITICAL

    def __init__(self):
        self.log = _logger

    @staticmethod
    def logger():
        return _logger

    @staticmethod
    def set_logging(level=logging.WARN, output=sys.stderr, msg=None):
        "Configure debug logging for simple standalone use cases, e.g. Dummy.set_logging(Dummy.DEBUG)"
        while _logger.hasHandlers():
            _logger.removeHandler(_logger.handlers[0])

        if level is not None:
            _logger.setLevel(level)

        if output is not None:
            handler = logging.StreamHandler(output)
            _logger.addHandler(handler)

            if msg is None:
                msg = "%(name) %(levelname)s: %(message)s"
            handler.setFormatter(logging.Formatter(msg))

    def do_something(self):
        self.log.error("error message")
        self.log.warn("warn message")
        self.log.info("info message")
        self.log.debug("debug message")

In this example, imagine replacing Dummy by Picamera2. Users who want to configure the logging for themselves can do so, and there's a static function to return the logger to enable this. But folks like me can instead use:

from dummy import Dummy
Dummy.set_logging(level=Dummy.DEBUG)
d = Dummy()
...

If you don't configure any logging at all, warning and error messages still come out, which seems reasonable. But I can't see how you could configure the format of the messages in this case, all you get is the text, no indication of the module name or severity. Does anyone know if that can be changed, it seems a bit unhelpful?

Anyway, what do you all think about this? Does it solve the problem in a reasonable way? Thanks!!

[davidplowman]

I've taken a bit more advice, and the feeling seemed to be that it would be better not to set the logger's level at all. Also, the Picamera2.logger() function is probably unnecessary as folks who understand the logging module would use getLogger("picamera2"), and then configure everything for themselves. So I'll prepare a PR along those lines in due course and then link it to this bug report.

[davidplowman]

This change is now available in apt so I think it's probably time to close this one! If anything else comes up... please file a new issue, and thanks again to everyone for contributing!