Univention Bugzilla – Bug 51193
remove debug function in univention.admin.handlers.simpleLdap.__getitem__
Last modified: 2020-05-06 14:40:04 CEST
+++ This bug was initially created as a clone of Bug #48893 +++ The listener.log, directory-manager-cmd.log and probably other logfiles get spammed with completely useless log messages even when their loglevel is the default: UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = data UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = data --------- At a customer the listener logfiles size is 373M. root@master:~ # wc -l /var/log/univention/listener.log 3739668 /var/log/univention/listener.log root@master:~ # grep 'admin.handlers.base.__getitem__ key =' /var/log/univention/listener.log | wc -l 2900622 → 78% of the logfile are filled with useless information. ---------------- This bug splits of from a general discussion on univention.debug to help with one concrete (the biggest) problem: those specific lines. → Remove the debug function in univention.admin.handlers.simpleLdap.__getitem__. File management/univention-directory-manager-modules/modules/univention/admin/handlers/__init__.py line 469. → Optionally make it available through a dedicated UCR variable, though I honestly think that means performance loss and strongly advocate the idea, that if someone really need to know when the function is used, she can simply edit the file.
Yes, I never ever used the debug.function functionality when I debugged a problem.
(In reply to Daniel Tröder from comment #0) > +++ This bug was initially created as a clone of Bug #48893 +++ ... > This bug splits of from a general discussion on univention.debug to help > with one concrete (the biggest) problem: those specific lines. > > → Remove the debug function in > univention.admin.handlers.simpleLdap.__getitem__. > File > management/univention-directory-manager-modules/modules/univention/admin/ > handlers/__init__.py line 469. For this please re-tag this bug to component "UDM-Generic", not "u-debug". > → Optionally make it available through a dedicated UCR variable, though I > honestly think that means performance loss and strongly advocate the idea, > that if someone really need to know when the function is used, she can > simply edit the file. The problem here is that the using application ("udm-cli" or the UMC-UDM-module-process) is responsible for setting up univention.debug and each process uses its own set of UCR variables: listener/debug/…, umc/…/debug/…, directory/manager/cmd/debug/… UD itself does not use or depends on UCR - adding UCR support into UD itself would create a circular dependency as UCR uses UD. You can simply disable this functionality by calling univention.debug.init(…, ud.NO_FUNCTION). Currently there are 11 cases where this is hard-coded enabled: $ git grep -En '(univention.debug|ud).init\(.*,\s*((univention.debug|ud)\.FUNCTION|1|True)\s*\)' base/univention-debug-python/tests/test_debug.py:105: fd = ud.init(str(tmp), ud.NO_FLUSH, ud.FUNCTION) base/univention-debug-python/tests/test_debug.py:113: fd = ud.init(stream, ud.NO_FLUSH, ud.FUNCTION) base/univention-debug-python/tests/test_debug.py:221: fd = ud.init(str(tmp), ud.NO_FLUSH, ud.FUNCTION) base/univention-debug-python/tests/test_debug.py:239: ud.init(str(tmp), ud.NO_FLUSH, ud.FUNCTION) base/univention-debug-python/tests/test_debug2.py:104: fd = ud.init(str(tmp), ud.NO_FLUSH, ud.FUNCTION) base/univention-debug-python/tests/test_debug2.py:112: fd = ud.init(stream, ud.NO_FLUSH, ud.FUNCTION) base/univention-heimdal/kerberos_now:37:univention.debug.init('/dev/null', 1, 1) base/univention-lib/python/admember.py:78: ud.init('/var/log/univention/join.log', ud.FLUSH, ud.FUNCTION) management/univention-directory-listener/src/dump.c:74: univention_debug_init("stderr", 1, 1); management/univention-directory-listener/src/main.c:362: univention_debug_init("stderr", 1, 1); management/univention-directory-listener/src/verify.c:155: univention_debug_init("stderr", 1, 1); management/univention-directory-manager-modules/modules/univention/admincli/adduser.py:99: ud.init('/var/log/univention/directory-manager-cmd.log', 1, 1) management/univention-directory-manager-modules/modules/univention/admincli/passwd.py:46: ud.init('/var/log/univention/directory-manager-cmd.log', 1, 1) management/univention-directory-manager-modules/univention-dnsedit:41:ud.init('/var/log/univention/directory-manager-cmd.log', ud.FLUSH, ud.FUNCTION) management/univention-directory-notifier/src/univention-directory-notifier.c:206: univention_debug_init("/var/log/univention/notifier.log",1,1); management/univention-directory-reports/univention-directory-reports:120: ud.init('/var/log/univention/directory-reports.log', ud.FLUSH, ud.FUNCTION) services/univention-samba/scripts/kerberize_user:48:univention.debug.init('/dev/null', 1, 1) univention.debug.function() is already marked as deprecated. The replacement univention.debug.trace() uses the same functionality and so has the same issues. +1 for disabling it for now as I also do not use it either and find the spamming very anoying.
I got the OK from the PO to handle this as bug squashing. So I did. The function trace was removed. [4.4-4] e7319f809f Bug #51193: remove function tracing in UDM modules __getitem__() [4.4-4] 04dbe04317 Bug #51193: advisory univention-directory-manager-modules (14.0.15-3)
OK: 04dbe043172cbf73f2664837dcdbb97b331c614c OK: errata-announce -V --only univention-directory-manager-modules.yaml OK: OK: e7319f809fce2e8f5874ac5bf5b09a94ffad75c7 OK: apt install -t apt python-univention-directory-manager{,-cli} OK: udm settings/udm_syntax create --set name=bug51193 --set filename=bug51193.py --set data="$(bzip2 <<<pass|base64)" --set package=test --set packageversion=1 --set active=TRUE ; tail -f /var/log/univention/listener.log FYI: Normally you do not see the message because udm-cli does not enable function tracing and most UDL modules do not use UDM, but work on LDAP directly. So this only happens when a UDL modules uses UDM internally. TODO: There are more candidates for log spamming: $ git grep -nE '(univention.debug|ud).function' modules/ modules/univention/admin/handlers/__init__.py:1621: _d = ud.function('admin.handlers.simpleLdap._update_policies') # noqa # noqa: F841 modules/univention/admin/handlers/__init__.py:3429: _d = ud.function('admin.handlers.simplePolicy.__makeUnique') # noqa # noqa: F841 modules/univention/admin/handlers/dns/host_record.py:117: _d = ud.function('admin.handlers.dns.host_record.unmapMX old=%s' % str(old)) # noqa: F841 modules/univention/admin/handlers/dns/host_record.py:125: _d = ud.function('admin.handlers.dns.host_record.mapMX old=%s' % str(old)) # noqa: F841 modules/univention/admin/locking.py:81: _d = ud.function('admin.locking.lock type=%s value=%s scope=%s timeout=%d' % (type, value, scope, timeout)) # noqa: F841 modules/univention/admin/locking.py:137: _d = ud.function('admin.locking.relock type=%s value=%s scope=%s timeout=%d' % (type, value, scope, timeout)) # noqa: F841 modules/univention/admin/locking.py:168: _d = ud.function('admin.locking.unlock type=%s value=%s scope=%s' % (type, value, scope)) # noqa: F841 modules/univention/admin/objects.py:147: _d = ud.function('admin.objects.default') # noqa: F841 modules/univention/admin/objects.py:281: _d = ud.function('admin.objects.getPolicyReference policy_type=%s' % (policy_type)) # noqa: F841 modules/univention/admin/objects.py:301: _d = ud.function('admin.objects.removePolicyReference policy_type=%s' % (policy_type)) # noqa: F841 modules/univention/admin/objects.py:322: _d = ud.function('admin.objects.replacePolicyReference policy_type=%s new_reference=%s' % (policy_type, new_reference)) # noqa: F841 modules/univention/admin/objects.py:344: _d = ud.function('admin.objects.restorePolicyReference policy_type=%s' % (policy_type)) # noqa: F841 Bonus points if you remove them all! TODO: I still get similar messages from base/univention-python/modules/uldap.py: > UNIVENTION_DEBUG_BEGIN : uldap.parentDn > UNIVENTION_DEBUG_END : uldap.parentDn Either a new bug or do it now with this bugs also for bonus points.
(In reply to Philipp Hahn from comment #4) > OK: 04dbe043172cbf73f2664837dcdbb97b331c614c > OK: errata-announce -V --only univention-directory-manager-modules.yaml > OK: FXIED: [4.4-4] 851b6c0186 Bug #51193: univention-directory-manager-modules 14.0.15-3A~4.4.0.202005011739 doc/errata/staging/univention-directory-manager-modules.yaml | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-)
I modified uldap.py as well. I didn't modify it in all the above cases, because I think that should be discussed more broadly and I didn't want to push the "bug squashing" to far. [4.4-4] 15da79b278 Bug #51193: remove excessive log trace information from uldap methods [4.4-4] db1c2ba747 Bug #51193: advisory update univention-python (12.0.0-20)
(In reply to Daniel Tröder from comment #6) > I didn't modify it in all the above cases, because I think that should be > discussed more broadly and I didn't want to push the "bug squashing" to far. The ud.function() is already marked as deprecated and will be removed for UCS-5 anyway, provides little to no value, is impossible to be configure right, and would simplify our transition to Python 3 by removing as much code now as possible. OK: [4.4-4] 15da79b278 Bug #51193: remove excessive log trace information from OK: [4.4-4] db1c2ba747 Bug #51193: advisory update OK: errata-announce -V --only univention-python.yaml FIXED: YAML → 3358382303 OK: apt install -t apt python-univention python-univention-directory-manager{,-cli} univention-directory-manager-tools OK: udm settings/udm_syntax create OK: jenkins (3 failing test for =4.4 are unrealted, <4.4 is failing since a week)
<http://errata.software-univention.de/ucs/4.4/588.html> <http://errata.software-univention.de/ucs/4.4/589.html>