Univention Bugzilla – Bug 57026
No adjustable DEBUG messages in connector-s4.log
Last modified: 2024-02-14 12:29:16 CET
ENV: primary:~# univention-app info UCS: 5.0-6 errata948 Installed: keycloak=22.0.3-ucs2 prometheus-node-exporter=2.0.1 samba4=4.16 self-service=5.0 self-service-backend=5.0 ucsschool=5.0 v4 79 school-server Introduced by the FR release of Bug 55324 in the customer environment lots of DEBUG messaged flooded the connector-s4.log. All looking like this: 05.02.2024 14:09:54.224 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUsun-DC-Verwaltungsnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.227 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUsun-DC-Edukativnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.229 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUstar-DC-Verwaltungsnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.232 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUuranus-DC-Edukativnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.234 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUuranus-DC-Verwaltungsnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.236 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUpluto-DC-Edukativnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.238 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUpluto-DC-Verwaltungsnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.241 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUneptun-DC-Edukativnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.243 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUneptun-DC-Verwaltungsnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.246 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUsaturn-DC-Edukativnetz,cn=ucsschool,cn=groups,dc=edu,dc=v,dc=ig') loaded 05.02.2024 14:09:54.248 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUsaturn-DC-Verwaltungsnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loaded 05.02.2024 14:09:54.251 ADMIN (DEBUG ): 'groups/group' object (dn: 'cn=OUdemoschool-DC-Edukativnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') loade ANd it looks like for each of the schoolserver this message is created. They seem to come from the school.lib ?
(In reply to Christina Scheinig from comment #0) > ENV: > primary:~# univention-app info > UCS: 5.0-6 errata948 > Installed: keycloak=22.0.3-ucs2 prometheus-node-exporter=2.0.1 samba4=4.16 > self-service=5.0 self-service-backend=5.0 ucsschool=5.0 v4 FYI: this only happens when UCS@school is installed. > 05.02.2024 14:09:54.224 ADMIN (DEBUG ): 'groups/group' object (dn: > 'cn=OUsun-DC-Verwaltungsnetz,cn=ucsschool,cn=groups,dc=edu,dc=schein,dc=ig') > loaded Bug #55324 does not specify a "DEBUG" level. only a univention.debug "ALL" level. So this is not logged by the univention.logging handler but by another handler from ucsschool. > ANd it looks like for each of the schoolserver this message is created. > They seem to come from the school.lib ? The message itself comes from the simple UDM lib, which now uses the new univention.logging: management/univention-directory-manager-modules/modules/univention/udm/modules/generic.py: logging.getLogger('ADMIN').debug('%r object (dn: %r) loaded', self.name, obj.dn) Unclear is, how this logger (which is not propagating events to the root- or parent-logger) logs to a different handler from UCS@school.
`univention-s4-connector` uses and initializes `univention.debug2` and `univention.debug`. `univention.debug2` maintains it's own log-levels via a static dictionary and doesn't doesn't use the python logging module capabilities. Furthermore it also initializes the root logger with log-level DEBUG, instead of only the loggers which `univention.debug2` actually uses. Since UDM uses `univention.logging`, we use `logging.getLogger('ADMIN').debug('foo')` in some places of the SimpleUDM Python API. However `univention.logging` isn't imported in the Simple UDM API neither is it imported in the `s4-connector`. Since `univention.logging` was never imported, the relevant loggers are never configured and the root logger is set to the `DEBUG` log-level all messages not being logged through `univention.debug2` were getting logged with the `DEBUG` level. We changed `univention.debug2` so that the root logger is left untouched and in it's place the parent logger `ud2` is getting configured instead. The `ud2` logger is additionally set to `propagate=false` in order to not interfere with any other configuration that might have been done at the root logger. Prefixing all the loggers with `ud2` was already done in git:a8a6e0388cd2e308ce55da3e57764f7ad01030f4 with the introduction of `univention.logging`. univention-debug-python.yaml 2237e82df206 | fix(debug2): don't configure root logger on debug2.init univention-debug-python (12.0.3-6) 2237e82df206 | fix(debug2): don't configure root logger on debug2.init
OK: univention.debug2 now logs only to a dedicated "ud2" logger instead of the root logger. OK: advisory
Another issue was found, in the case when a C component set the univention-debug level and afterwards Python is invoked and univention.logging imported. This caused that the loglevel was set to DEBUG/ALL(4). univention-debug-python (12.0.3-8) 9443287f16c2 | fix(logging): don't set the loglevel initially to `logging.NOTSET` The listener debug level was suddently reset because the C code sets the univention-debug level and afterwards a import of univention.logging resetted the loglevel to ud.ALL(4) because the constructor set the default loglevel `logging.NOTSET`. Fixed by setting the level to the current univention.debug level.
<https://errata.software-univention.de/#/?erratum=5.0x956>