Univention Bugzilla – Bug 35707
Listener log level (listener.log) messages should be reviewed
Last modified: 2021-11-23 16:35:17 CET
Currently the test 00_base/99check_log_files shows: Errors found in '/var/log/univention/listener.log': E: listener.log:28, 25.08.14 18:00:11.973 LISTENER ( ERROR ) : connection to notifier was closed E: listener.log:29, 25.08.14 18:00:11.973 LISTENER ( ERROR ) : failed to recv result E: listener.log:30, 25.08.14 18:00:11.973 LISTENER ( ERROR ) : listener: 1 E: listener.log:32, 25.08.14 18:00:17.259 LDAP ( ERROR ) : start_tls: Can't contact LDAP server E: listener.log:36, 25.08.14 18:01:18.308 LDAP ( ERROR ) : start_tls: Can't contact LDAP server E: listener.log:95, 25.08.14 18:09:31.166 LISTENER ( ERROR ) : well-known-sid-name-mapping.d/univention-ldap-server.py: postrun: Initiating graceful reload of ldap server(s). E: listener.log:106, 25.08.14 18:10:08.709 LISTENER ( ERROR ) : well-known-sid-name-mapping.d/univention-ldap-server.py: postrun: Initiating graceful reload of ldap server(s). E: listener.log:117, 25.08.14 18:10:13.520 LISTENER ( WARN ) : error searching DN cn=Domain Admins,cn=groups,dc=autotest093,dc=local: -1 E: listener.log:118, 25.08.14 18:10:13.520 LISTENER ( ERROR ) : change_update_dn: Can't contact LDAP server E: listener.log:119, 25.08.14 18:10:29.173 LISTENER ( ERROR ) : well-known-sid-name-mapping.d/univention-ldap-server.py: postrun: Initiating graceful reload of ldap server(s). Some of those seem to be just a debug messages with an "ERROR" level. Should be reviewed.
We should change SIGUSR1/SIGUSR2 to make UDL reload the debug setting and apply them to to currently running process. We should support multiple facilities, as debugging cache_lowlevel.c is almost never of interest and it logs too much with DEBUG. We should log to syslog which would allow us to forward the messages to a central log server more easily, which makes debugging a distributed system like UDL/UDN much better.
Created attachment 8495 [details] Unify UDL log message format The attached patch converts all univention_debug() users to use the common format __FILE__:__LINE__:__func__: msg... The old explicit logging of __xxx___has been removed manually. It also converts all users to use UV_DEBUG_LISTENER and UV_DEBUG_TRANSFILE, as currently it's a mixed mess. UV_DEBUG_LDAP is not used anymore, but still enabled for UDL modules. What is still needed is more categories, e.g. verbose logging for the main event loop, but no logging for low-level cache handling details. We should wait for Bug #43685 to decide on a future logging framework.
Created attachment 9742 [details] UV_DEBUG_LDAP -> UV_DEBUG_LISTENER The log messages are from UDL not not related to LDAP, so use UV_DEBUG_LISTENER instead of UV_DEBUG_LDAP.
4.3-3 <https://git.knut.univention.de/univention/ucs/commits/phahn/30263-udl-memory>
UDL logging sucks: UDL cannot be debugged in a busy customer environment because either I get no useful message or I'am drowned in low-level debugging stuff. We need more categories for UDL so I can get what I want: - minimum one message for transaction - also a message when transaction processing is completed - message per module (start and end) so I can see how long each module took - I don't want to augment each module itself to do that - messages from modules should go into a separate file/category - low-level stuff should be in a separate category - stuff for opening,closing LDAP connections → separate category - Increasing the loglevel per SIGUSR1 and decreasing with SIGUSR2 is not enough. - Logging should be to a common log like syslog or journal to easier correlate them with logging messages from other services (like slapd)
Again we had a major support case, where UDL only kept silence. Some sort of progress report when initializing modules would be very much appreciated, e.g. "Processed %d transactions in %s seconds (%.1f tps)"