Univention Bugzilla – Bug 57101
univention.logging logs with wrong debug level in ADC/S4C
Last modified: 2024-03-07 13:07:40 CET
Since Bug #56970 we are importing "univention.logging" in univention/admin/__init__.py and univention/uldap.py before univention-debug is initialized. This causes that the UDM univention-debug loglevel is not respected anymore for every log entry written by the univention.logging interface (which is now done for the whole UDM and UMC code). Affected components are e.g. S4-Connector and AD-Connector, etc. Example with a order in which the correct level is detected: >>> import univention.debug as ud >>> ud.init('stdout', ud.FLUSH, ud.NO_FUNCTION) 29.02.24 19:17:07.846 DEBUG_INIT <_io.FileIO name=1 mode='rb+' closefd=False> >>> ud.set_level(ud.ADMIN, ud.ALL) >>> import univention.logging >>> A = univention.logging.getLogger('ADMIN') >>> A <univention.logging.Logger ADMIN (Level 9)> >>> A.univention_debug_handler.get_ud_level() 4 >>> A.univention_debug_handler.getLevel() 9 >>> A.getEffectiveLevel() 9 Example with the other order, which doesn't detect the correct level: >>> import univention.debug as ud >>> import univention.logging >>> import logging >>> A = univention.logging.getLogger('ADMIN') >>> A <univention.logging.Logger ADMIN (ERROR)> >>> ud.init('stdout', ud.FLUSH, ud.NO_FUNCTION) 29.02.24 19:14:17.109 DEBUG_INIT <_io.FileIO name=1 mode='rb+' closefd=False> >>> ud.set_level(ud.ADMIN, ud.ALL) >>> A <univention.logging.Logger ADMIN (ERROR)> >>> A.info('test') # nothing is logged :-( >>> ud.debug(ud.ADMIN, ud.INFO, 'test') 29.02.24 19:26:41.940 ADMIN ( INFO ) : test >>> A.univention_debug_handler.get_ud_level() # correct 4 >>> A.univention_debug_handler.getLevel() # correct 9 >>> A.getEffectiveLevel() # incorrect 40 >>> logging.ERROR 40 So, we should propagate all log events to the univention.logging.DebugHandler regardless of which loglevel is set. Or overwrite some getEffectiveLevel() or whatever is used by logging to detect which log level is currently set and take the log level from univention.debug.
The following seems to work. Note, that in pythons logging.py I see a cache and don't know how the second case also works, but it does: diff --git base/univention-debug-python/python/univention/logging.py base/univention-debug-python/python/univention/logging.py index 35654762698..4405ed08b91 100644 --- base/univention-debug-python/python/univention/logging.py +++ base/univention-debug-python/python/univention/logging.py @@ -289,6 +289,9 @@ class Logger(logging.Logger): super(Logger, self).setLevel(level) self.univention_debug_handler.setLevel(self.level) + def getEffectiveLevel(self): + return self.univention_debug_handler.getLevel() + def set_log_pid(self, log_pid): self._formatter.log_pid = log_pid >>> import logging, univention.logging, univention.debug as ud >>> ud.init('stdout', ud.FLUSH, ud.NO_FUNCTION) 29.02.24 19:37:15.099 DEBUG_INIT <_io.FileIO name=1 mode='rb+' closefd=False> >>> ud.set_level(ud.ADMIN, ud.ALL) >>> A = univention.logging.getLogger('ADMIN') >>> A # first case <univention.logging.Logger ADMIN (Level 9)> >>> ud.set_level(ud.ADMIN, ud.INFO) >>> A # second case <univention.logging.Logger ADMIN (DEBUG)>
That patch has been applied and helps for the moment. univention-debug-python.yaml 2ff3c5666e8e | fix(logging): detect correct univention-debug log level if univention-debug-python (12.0.3-9) 2ff3c5666e8e | fix(logging): detect correct univention-debug log level if
>>> import univention.debug as ud >>> import univention.logging >>> import logging >>> A = univention.logging.getLogger('ADMIN') >>> A <univention.logging.Logger ADMIN (ERROR)> >>> ud.init('stdout', ud.FLUSH, ud.NO_FUNCTION) 05.03.24 07:47:01.943 DEBUG_INIT <_io.FileIO name=1 mode='rb+' closefd=False> >>> ud.set_level(ud.ADMIN, ud.ALL) >>> A <univention.logging.Logger ADMIN (Level 9)> >>> A.info('test') # still nothing logged >>> ud.debug(ud.ADMIN, ud.INFO, 'test') 05.03.24 07:47:27.264 ADMIN ( INFO ) : test >>> A.univention_debug_handler.get_ud_level() # correct 4 >>> A.univention_debug_handler.getLevel() 9 >>> A.getEffectiveLevel() # correct now 9 >>> A.univention_debug_handler.level # incorrect 40
Fixed in, accidentally commited with wrong bug number: Bug #56970 univention-debug-python (12.0.3-10) 323569b34c2e | fix(logging): set level to upstream handler
OK: changelog and YAML OK: code review OK: the order of initialization does not matter anymore OK: the log level can be set with either univention.logging or univention.debug OK: usage of univention.logging and univention.debug can be mixed e.g. initializing with univention.debug and then changing log level with univention.logging or vice versa
<https://errata.software-univention.de/#/?erratum=5.0x976>