Bug 58627 - Change logging format of UCS into structural logging
Summary: Change logging format of UCS into structural logging
Status: CLOSED FIXED
Alias: None
Product: UCS
Classification: Unclassified
Component: univention-debug
Version: UCS 5.2
Hardware: Other Linux
: P5 normal
Target Milestone: UCS 5.2-3-errata
Assignee: Florian Best
QA Contact: Felix Botner
URL:
Keywords:
Depends on:
Blocks: 58653 58654 58656 58644 58647
  Show dependency treegraph
 
Reported: 2025-09-10 15:20 CEST by Florian Best
Modified: 2025-09-25 16:24 CEST (History)
0 users

See Also:
What kind of report is it?: Feature Request
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional): Error handling, Troubleshooting
Customer ID:
Max CVSS v3 score:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Florian Best univentionstaff 2025-09-10 15:20:09 CEST
The logging format of UCS is currently set by univention.debug to a german-dated, unstructured format.
UCS should use a common structured log format:

<timestamp> <levelname:8> [<request_id:->] <message> \t| <data>
where <data> are logfmt formatted key-values.
where <timestamp> is a valid ISO 8601 date, including the timezone.
For example:
```
2025-01-01T00:00:00.000000+00:00     INFO [         -] The message	| pid=12345 logname=LDAP func=test_module.test_function:1 foo=bar
```

This format follows the internal ADR at:
https://git.knut.univention.de/univention/dev/decision-records/-/blob/main/dev/0010-log-levels.md

The logfmt format is specified in https://www.brandur.org/logfmt.
The library to implement the logfmt <data>-segment, is python-logfmter: https://github.com/josheppinette/python-logfmter/.

The changes can be enabled via UCR variables per service, for now they are disabled by default.
We will enable the changes in UCS 5.2-4 (in three month) by default.
With UCS 5.2-5 (in six month) the old legacy format will be removed.

The logging implementation must be compatible to the old logging, several UDM hooks for example are still using univention.debug.
Since Bug #55324 we have a logging interface for univention.debug, called univention.logging.
Some components, which we use in Python, are written in C code (policy evaluation, license evaluation), which use the C univention_debug_debug() methods.

univention.debug has to be adapted for a new log level TRACE (5).
For backwards compatibility we have to offer the PROCESS (UD=2, logging=25) level, which is between WARNING and INFO.

Tracebacks must still be logged within several lines, for human readability and our current parsers for tracebacks.

How to emit log entries?:
```
from logging import getLogger
log = getLogger('ADMIN')
log.info("The message", extra={"foo": "bar"})

# or more convenient:
from univention.logging import Structured
log = Structured(log)
log.info("The message", foo="bar")
```
Comment 1 Florian Best univentionstaff 2025-09-22 15:55:45 CEST
The new logging format has been established.
All log lines of UDM have been adjusted to follow the structural format and give meaningful information in the data-section.

Examples for all possible log emit function calls in the new format:
https://raw.githubusercontent.com/univention/univention-corporate-server/refs/heads/5.2-3/base/univention-debug-python/tests/structured.log

Can be compared with the old format:
https://raw.githubusercontent.com/univention/univention-corporate-server/refs/heads/5.2-3/base/univention-debug-python/tests/legacy.log

univention.logging, univention.debug and univention.debug2 now have 100% test coverage.
Our linters are now detecting incompatible python logging calls.

Structured logging can be enabled on a per service basis:
ucr set 'umc/server/debug/structured-logging=true' \
 'directory/manager/rest/debug/structured-logging=true' \
 'directory/manager/cmd/debug/structured-logging=true' \
 'connector/s4/debug/structured-logging=true' \
 'connector/debug/structured-logging=true' \
 'notifier/debug/structured-logging=true' \
 'listener/debug/structured-logging=true'

A regex to parse log lines:
^(?P<date>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}\+\d{2}:?\d{2}) +(?P<level>\w+?) +\[(?P<request_id>.*?)\] (?P<message>.+?)\t\| (?P<data>.*?)$

All non matching lines must be ignored (i.e. are tracebacks or legacy univention.debug calls).

These will be set to true in UCS 5.2-4.

Many log lines had to be adjusted to be compatible. E.g. removing new lines from logging. Or special traceback handling.
The use of univention.debug has been replaced in S4/AD-Connector, so that it's also compatible.
Comment 2 Florian Best univentionstaff 2025-09-22 15:56:10 CEST
Related commits:
univention-s4-connector (16.3.0)
842c16eae900 | feat(s4-connector): use univention.logging
d5ee8d60e266 | feat(s4-connector): add configuration for structured logging
b70df78d4a3c | style(s4-connector): fix comparison type

univention-python.yaml
c6851f248f32 | chore(logging): update advisory

univention-python (15.3.0)
36fbf1eacf5b | feat(python): add structured log messages

univention-management-console.yaml
c6851f248f32 | chore(logging): update advisory

univention-management-console-module-udm.yaml
c6851f248f32 | chore(logging): update advisory

univention-management-console-module-udm (5.1.25-56)
r58627 | Bug #35614: Revert

univention-management-console (14.3.2)
7015e439110c | feat(umc): logging
83858ce8ebb8 | feat(umc): add configuration to enable structured logging

univention-directory-manager-rest.yaml
c6851f248f32 | chore(logging): update advisory

univention-directory-manager-rest (12.3.0)
0afb492a7a45 | feat(udm-rest): structured logging
f4376ffd3c8a | feat(udm-rest): add configuration to enable structured logging

univention-directory-manager-modules.yaml
c6851f248f32 | chore(logging): update advisory

univention-directory-manager-modules (17.3.0)
f50eee9638fb | feat(udm-cli): allow settting structured log format for UDM CLI
2ee6773f31b6 | feat(udm): add structured log messages

univention-debug.yaml
c6851f248f32 | chore(logging): update advisory

univention-debug-python.yaml
c6851f248f32 | chore(logging): update advisory

univention-debug-python (14.3.0)
2c9f6cad1d4a | feat(debug-python): add structured logging option to univention.logging
631722362897 | test(debug-python): add test cases for univention.logging with structural=True/False
ef88a8928ed3 | test(debug-python): add test definition before structured changes
d77b9a9a13c8 | test(debug-python): catch PendingDeprecationWarning warning

univention-debug (14.3.0)
81329889de74 | feat(debug): add structured log ouptut to univention-debug

univention-ad-connector (16.4.0)
7aa9b404b5c0 | feat(ad-connector): use univention.logging
b70df78d4a3c | style(s4-connector): fix comparison type

ucs-test (12.3.6)
7b75332c1501 | test(umc): test traceback format of structured logging
83858ce8ebb8 | feat(umc): add configuration to enable structured logging

33359cccd02a | ci(jenkins): enable structured log output by default
187e7cfa7a51 | ci(ruff): configure logger names

.pre-commit-config.yaml
631722362897 | test(debug-python): add test cases for univention.logging with structural=True/False
Comment 3 Felix Botner univentionstaff 2025-09-25 11:46:28 CEST
OK - changes
OK - advisory
OK - tests