Bug 51193 - remove debug function in univention.admin.handlers.simpleLdap.__getitem__
remove debug function in univention.admin.handlers.simpleLdap.__getitem__
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: univention-debug
UCS 4.4
Other Linux
: P5 normal (vote)
: UCS 4.4-4-errata
Assigned To: Daniel Tröder
Philipp Hahn
:
Depends on: 48893
Blocks:
  Show dependency treegraph
 
Reported: 2020-04-30 11:08 CEST by Daniel Tröder
Modified: 2020-05-06 14:40 CEST (History)
2 users (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 3: Simply Wrong: The implementation doesn't match the docu
Who will be affected by this bug?: 2: Will only affect a few installed domains
How will those affected feel about the bug?: 2: A Pain – users won’t like this once they notice it
User Pain: 0.069
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Daniel Tröder univentionstaff 2020-04-30 11:08:45 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.
Comment 1 Florian Best univentionstaff 2020-04-30 11:10:42 CEST
Yes, I never ever used the debug.function functionality when I debugged a problem.
Comment 2 Philipp Hahn univentionstaff 2020-04-30 11:31:43 CEST
(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.
Comment 3 Daniel Tröder univentionstaff 2020-05-01 17:51:13 CEST
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)
Comment 4 Philipp Hahn univentionstaff 2020-05-01 18:38:03 CEST
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.
Comment 5 Philipp Hahn univentionstaff 2020-05-01 18:39:46 CEST
(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(-)
Comment 6 Daniel Tröder univentionstaff 2020-05-01 18:59:42 CEST
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)
Comment 7 Philipp Hahn univentionstaff 2020-05-02 07:40:18 CEST
(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)