kbr / fritzconnection

Python-Tool to communicate with the AVM Fritz!Box by the TR-064 protocol and the AHA-HTTP-Interface
MIT License
303 stars 59 forks source link

Change default logging level from DEBUG to INFO #123

Closed chemelli74 closed 2 years ago

chemelli74 commented 2 years ago

Default logging level should be less aggressive. Many external tools, like Home Assistant, rely on library default and doesn't force a different level if not explicitly requested.

When a debug session is requested, only in that moment logging level should be changed.

Simone

kbr commented 2 years ago

The fritzlogger-instance from fritzconnection.core.logging is designed for debugging purposes and deactivated by default because of the NullHandler. The use of this logger is optional.

The issue reported by https://github.com/home-assistant/core/issues/58653 must have been triggered by assigning a handler to the fritzlogger-instance but not adapting the log-level. But by setting a more restricting level like INFO, again no logging will happen at all, because internally all logging events are triggered on debug-level. A usecase for this could be a wrapper taking the fritzlogger instead of a separate one to trigger logging events.

DeKubus commented 2 years ago

The fritzlogger-instance from fritzconnection.core.logging is designed for debugging purposes and deactivated by default because of the NullHandler. The use of this logger is optional.

This is not the way the logger is currently implemented though, since the code does not take into account that a baseConfig is instantiated if any kind of logging is used and that will also send log data upstream to the root logger. This is not limited to custom baseConfigs either, since the default Python log module does this:

if len(root.handlers) == 0:
    basicConfig() 

This means that fritzconnection will ignore the log level and always emit debug logs if any kind of Python logging is used unless the libs logging is explicitly overridden. Simple test case:

from fritzconnection import FritzConnection
import logging

FritzConnection("192.168.0.1")
logging.warning("The log preceding this won't be printed")
FritzConnection("192.168.0.1") # the log of this will be printed

Note that I am not changing the log level for Python's logging here, i.e. the root logger is still configured with WARNING level. This is definitively a implementation bug in fritzconnection, since depending on whether or not the user provides a basicConfig the library will emit DEBUG messages to either a configured handler or to the default StreamHandler instantiated by Python's logging.

Changing the default log level would mitigate the issue, but not fix it. Please consider not emitting any messages at all if the library is not configured by omitting the default instead and only sending messages to the logger methods if it is explicitly set.

kbr commented 2 years ago

The logger is enabled by default instead of being disabled. That's indeed a bug. Thank you for reporting.

chemelli74 commented 2 years ago

@kbr, just for your knowledge: still a issue with 1.7.2 and Home Assistant.

Unfortunately this is the only library with this issue :-(

Simone

balloob commented 2 years ago

Deactivating the logger by attaching the NullHandler won't work, as any logged message will be sent to any handler of the current and any of it's parent loggers.

image

Source: Logging docs

Now one could turn off propagate, as per the docs:

Child loggers propagate messages up to the handlers associated with their ancestor loggers. Because of this, it is unnecessary to define and configure handlers for all the loggers an application uses. It is sufficient to configure handlers for a top-level logger and create child loggers as needed. (You can, however, turn off propagation by setting the propagate attribute of a logger to False.)

However that means that no Fritzbox logs could ever be consumed by any code that uses this lib unless they add specific fritzconnection logic, because it's not assumed that propagate is turned off.

balloob commented 2 years ago

One solution would be to not set a level until "enable" is called and set it back to self.logger.setLevel(logging.NOTSET) when disabled. That way you can also drop the NullHandler.

chemelli74 commented 2 years ago

@kbr any comment on above suggestion ?

Simone

kbr commented 2 years ago

@balloob , @chemelli74 , thanks for commenting. I can go into detail after busy season. Sorry to say this may take a fortnight.

chemelli74 commented 2 years ago

Hi @kbr, did you get time to check this ? ;-)

Simone

kbr commented 2 years ago

Not right now, but hopefully in the next ...

kbr commented 2 years ago

Made a complete rewrite for fritzconnection version 1.8. So I close this as there is a new logger-module with the new version. In case of bugs left (there are always bugs somewhere), please feel free to reopen or open a new issue.