The following components/logs are still using unstructured logging: join.log has custom format: ``` RUNNING 10univention-ldap-server.inst 2025-09-24 00:14:02.600868616+02:00 (in joinscript_init) Adding SRV record "ldap tcp 0 100 7389 master070.autotest070.test." to zone autotest070.test... done ``` appcenter.log: ``` 141507 actions.upgrade-search 25-09-23 23:53:23 [ INFO]: Executing interface update_available for keycloak 141507 actions.upgrade-search 25-09-23 23:53:23 [ INFO]: No interface defined 141507 actions.upgrade-search.progress 25-09-23 23:53:23 [ DEBUG]: 100 141507 actions.upgrade-search 25-09-23 23:53:36 [ DEBUG]: Calling upgrade-search 141507 actions.upgrade-search.progress 25-09-23 23:53:36 [ DEBUG]: 0 141507 actions.update 25-09-23 23:53:36 [ DEBUG]: Calling update 141507 actions.update.progress 25-09-23 23:53:36 [ DEBUG]: 0 141507 actions.update 25-09-23 23:53:36 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/app-categories.ini"... 141507 actions.update 25-09-23 23:53:37 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:37 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/rating.ini"... 141507 actions.update 25-09-23 23:53:37 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:37 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/license_types.ini"... 141507 actions.update 25-09-23 23:53:37 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:37 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/ucs.ini"... 141507 actions.update 25-09-23 23:53:37 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:37 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/suggestions.json"... 141507 actions.update 25-09-23 23:53:37 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:37 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/5.2/all.tar.gpg"... 141507 actions.update 25-09-23 23:53:37 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:37 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/5.0/all.tar.gpg"... 141507 actions.update 25-09-23 23:53:38 [ DEBUG]: ... Not Modified 141507 actions.update.progress 25-09-23 23:53:38 [ DEBUG]: 100 141507 cache 25-09-23 23:53:38 [ DEBUG]: Cache outdated. Need to rebuild 141507 cache 25-09-23 23:53:38 [ DEBUG]: Loaded 79 apps from cache 141507 cache 25-09-23 23:53:38 [ DEBUG]: Cache outdated. Need to rebuild 141507 cache 25-09-23 23:53:38 [ DEBUG]: Loaded 459 apps from cache 141507 actions.upgrade-search 25-09-23 23:53:38 [ DEBUG]: Checking cups=2.4.2 141507 actions.upgrade-search 25-09-23 23:53:38 [ DEBUG]: Checking dhcp-server=16.0 141507 actions.upgrade-search 25-09-23 23:53:38 [ DEBUG]: Checking mailserver=16.0 141507 actions.upgrade-search 25-09-23 23:53:38 [ DEBUG]: Checking pkgdb=15.0 141507 actions.upgrade-search 25-09-23 23:53:38 [ DEBUG]: Checking radius=9.0 141507 actions.upgrade-search 25-09-23 23:53:38 [ DEBUG]: Checking squid=5.7 141507 actions.upgrade-search 25-09-23 23:53:38 [ DEBUG]: Checking 5.0/keycloak=26.3.3-ucs1 141507 actions.upgrade-search 25-09-23 23:53:38 [ INFO]: Executing interface update_available for keycloak 141507 actions.upgrade-search 25-09-23 23:53:38 [ INFO]: No interface defined 141507 actions.upgrade-search.progress 25-09-23 23:53:38 [ DEBUG]: 100 141507 actions.upgrade-search 25-09-23 23:53:49 [ DEBUG]: Calling upgrade-search 141507 actions.upgrade-search.progress 25-09-23 23:53:49 [ DEBUG]: 0 141507 actions.update 25-09-23 23:53:49 [ DEBUG]: Calling update 141507 actions.update.progress 25-09-23 23:53:49 [ DEBUG]: 0 141507 actions.update 25-09-23 23:53:49 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/app-categories.ini"... 141507 actions.update 25-09-23 23:53:49 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:49 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/rating.ini"... 141507 actions.update 25-09-23 23:53:49 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:49 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/license_types.ini"... 141507 actions.update 25-09-23 23:53:50 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:50 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/ucs.ini"... 141507 actions.update 25-09-23 23:53:50 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:50 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/suggestions.json"... 141507 actions.update 25-09-23 23:53:50 [ DEBUG]: ... Not Modified 141507 actions.update 25-09-23 23:53:50 [ INFO]: Downloading "https://appcenter.software-univention.de/meta-inf/5.3/all.tar.gpg"... 141507 actions.update 25-09-23 23:53:50 [CRITICAL]: https://appcenter.software-univention.de/meta-inf/5.3/all.tar.gpg could not be downloaded. This seems to be a problem with the App Center server. Please try again later.141507 actions.update.progress 25-09-23 23:53:50 [ DEBUG]: 100 141507 actions.upgrade-search 25-09-23 23:53:50 [CRITICAL]: https://appcenter.software-univention.de/meta-inf/5.3/all.tar.gpg could not be downloaded. This seems to be a problem with the App Center server. Please try again later. 141507 actions.upgrade-search.progress 25-09-23 23:53:50 [ DEBUG]: 100 141507 cache 25-09-23 23:53:50 [ DEBUG]: Unable to get mtime for archive: [Errno 2] No such file or directory: '/var/cache/univention-appcenter/appcenter.software-univention.de/5.3/.all.tar' 141507 cache 25-09-23 23:53:50 [ DEBUG]: Unable to get mtime for archive: [Errno 2] No such file or directory: '/var/cache/univention-appcenter/appcenter.software-univention.de/5.3/.all.tar' 141507 cache 25-09-23 23:53:50 [ DEBUG]: Cannot load cache: Getting cached attributes failed ``` app_attributes.log ``` 2025-09-24 06:24:53 INFO Finished 2025-09-24 06:24:53 INFO Gathering AppAttributes... ``` listener.log (some lines arbitrary written by some listener modules) ``` 2025-09-24T06:28:51.578408+02:00 PROCESS updating 'uid=nfk1c518te,cn=users,dc=autotest070,dc=test' command m Updating default Portal data updated in 0.03s Updating umc Portal data untouched 2025-09-24T06:29:09.100630+02:00 PROCESS connecting to ldap://master070.autotest070.test:7389 2025-09-24T06:29:09.140689+02:00 PROCESS updating 'cn=t5l23qd4an,cn=domain,cn=mail,dc=autotest070,dc=test' command a Setting mail/hosteddomains File: /etc/amavis/conf.d/60-univention 2025-09-24T06:29:17.926101+02:00 PROCESS updating 'uid=eyosuvzs3z,cn=users,dc=autotest070,dc=test' command a Sieve/IMAP Password:· Connection dropped unexpectedly when trying to read. Sieve/IMAP Password:· Connection dropped unexpectedly when trying to read. 2025-09-24T06:29:19.083421+02:00 PROCESS dovecot: Added mail account 'eyosuvzs3z@t5l23qd4an'. ``` management-console-server.log (some cronjob or something logs into the same file without content) ``` 2025-09-24T07:27:59.446302+02:00 EXIT· 24.09.25 07:28:01.899 DEBUG_INIT 2025-09-24T07:28:01.931717+02:00 ERROR 40_extended_attribute_attributehook_value_mapping: n2asvevtdt: TEST MODULE LOADED ``` portal.log ``` 339174 user 25-09-24 07:19:11 [ DEBUG]: searching user for cookies={'UMCLang': 'en-US', 'UMCSessionId': '91b5edad-b104-47d3-8794-7e5597f34e9a', 'UMCUsername': 'e8uc91bguc', 'UMCWEB_ROUTEID': '.2'} 339174 user 25-09-24 07:19:11 [ DEBUG]: found e8uc91bguc 339174 user 25-09-24 07:19:16 [ DEBUG]: no user given 372195 cli 25-09-24 07:19:36 [ INFO]: Updating default 372195 cache 25-09-24 07:19:36 [ INFO]: refreshing cache 372195 cli 25-09-24 07:19:36 [ INFO]: Portal data updated in 0.01s 372195 cli 25-09-24 07:19:36 [ INFO]: Updating umc 372195 cli 25-09-24 07:19:36 [ INFO]: Portal data untouched 339174 user 25-09-24 07:24:04 [ DEBUG]: no user given 339174 cache 25-09-24 07:24:04 [ INFO]: loading cache file /var/cache/univention-portal/groups.json 339174 user 25-09-24 07:24:08 [ DEBUG]: searching user for cookies={'UMCLang': 'de-DE', 'UMCSessionId': '0d9cd394-a2fa-4d27-8cb9-c65d6079d3cd', 'UMCUsername': 'Administrator'} 339174 user 25-09-24 07:24:08 [ DEBUG]: found Administrator 339174 user 25-09-24 07:24:10 [ DEBUG]: no user given 339174 user 25-09-24 07:24:27 [ DEBUG]: no user given 339174 user 25-09-24 07:24:29 [ DEBUG]: searching user for cookies={'UMCLang': 'de-DE', 'UMCSessionId': 'dcf5ff8c-17ab-4af2-8e42-1294832acc5c', 'UMCUsername': 'Administrator'} 339174 user 25-09-24 07:24:29 [ DEBUG]: found Administrator 339174 user 25-09-24 07:24:32 [ DEBUG]: no user given 377112 cli 25-09-24 07:27:54 [ INFO]: Updating default 377112 cache 25-09-24 07:27:54 [ INFO]: refreshing cache 377112 cli 25-09-24 07:27:54 [ INFO]: Portal data updated in 0.01s 377112 cli 25-09-24 07:27:54 [ INFO]: Updating umc 377112 cli 25-09-24 07:27:54 [ INFO]: Portal data untouched 378356 cli 25-09-24 07:29:56 [ INFO]: Updating default 378356 cache 25-09-24 07:29:57 [ INFO]: refreshing cache 378356 cli 25-09-24 07:29:57 [ INFO]: Portal data updated in 0.01s 378356 cli 25-09-24 07:29:57 [ INFO]: Updating umc 378356 cli 25-09-24 07:29:57 [ INFO]: Portal data untouched ``` server_password_change.log ``` [2025-09-23 22:53:14.478542682] reloading dovecot after server password change File: /etc/dovecot/dovecot-ldap.conf.ext run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-nscd postchange Restarting nscd (via systemctl): nscd.service. run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-radius postchange File: /etc/freeradius/3.0/mods-available/ldap [2025-09-23 22:53:17.123438891] restart freeradius after server password change run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-sssd postchange File: /etc/sssd/sssd.conf [2025-09-23 22:53:19.723007199] done [2025-09-23 23:03:15.665591360] Starting server password change [2025-09-23 23:03:15.738430103] failed to change server password: /var/lib/univention-directory-replication/failed.ldif exists #========================================================================# [2025-09-23 23:03:15.742105766] ERROR during execution, see below for more detailed debug output [2025-09-23 23:03:15.665591360] Starting server password change [2025-09-23 23:03:15.738430103] failed to change server password: /var/lib/univention-directory-replication/failed.ldif exists #========================================================================# ``` apache2/error.log: ``` [Wed Sep 24 07:06:08.606819 2025] [mpm_prefork:notice] [pid 339617:tid 339617] AH00171: Graceful restart requested, doing restart [Wed Sep 24 07:06:08.809274 2025] [mpm_prefork:notice] [pid 339617:tid 339617] AH00163: Apache/2.4.65 (Debian) OpenSSL/3.0.17 mod_wsgi/4.9.4 Python/3.11 configured -- resuming normal operations [Wed Sep 24 07:06:08.809301 2025] [core:notice] [pid 339617:tid 339617] AH00094: Command line: '/usr/sbin/apache2' [Wed Sep 24 07:26:25.970797 2025] [proxy:error] [pid 374766:tid 374766] (111)Connection refused: AH00957: http: attempt to connect to 127.0.0.1:8090 (127.0.0.1:8090) failed [Wed Sep 24 07:26:25.970877 2025] [proxy_http:error] [pid 374766:tid 374766] [client 10.207.83.17:39768] AH01114: HTTP: failed to make connection to backend: 127.0.0.1 ``` apache2/access.log: ``` 10.207.83.17 - - [24/Sep/2025:07:29:29 +0200] "GET /univention/ HTTP/1.1" 302 864 "" "python-requests/2.28.1" 10.207.83.17 - - [24/Sep/2025:07:29:29 +0200] "GET /univention/portal/ HTTP/1.1" 200 1638 "" "python-requests/2.28.1" 10.207.83.17 - - [24/Sep/2025:07:29:30 +0200] "GET /univention/saml/ HTTP/1.1" 302 3857 "" "python-requests/2.28.1" 10.207.83.17 - - [24/Sep/2025:07:29:30 +0200] "GET /univention/get/session-info HTTP/1.1" 401 547 "" "python-requests/2.28.1" 10.207.83.17 - - [24/Sep/2025:07:29:39 +0200] "GET /univention/saml/ HTTP/1.1" 302 7297 "" "python-requests/2.28.1" 10.207.83.17 - - [24/Sep/2025:07:29:39 +0200] "GET /univention/saml/ HTTP/1.1" 302 3861 "-" "python-requests/2.28.1" 172.16.1.2 - - [24/Sep/2025:07:29:39 +0200] "POST /univention/auth HTTP/1.1" 401 4295 "-" "Java/17.0.16" 172.16.1.2 - - [24/Sep/2025:07:29:40 +0200] "POST /univention/auth HTTP/1.1" 200 700 "-" "Java/17.0.16" 10.207.83.17 - - [24/Sep/2025:07:29:41 +0200] "POST /univention/saml/ HTTP/1.1" 303 696 "" "python-requests/2.28.1" 10.207.83.17 - - [24/Sep/2025:07:29:41 +0200] "GET /univention/management/ HTTP/1.1" 200 1954 "" "python-requests/2.28.1" 10.207.83.17 - - [24/Sep/2025:07:29:41 +0200] "GET /univention/get/session-info HTTP/1.1" 200 552 "" "python-requests/2.28.1" 10.207.83.17 - - [24/Sep/2025:07:29:50 +0200] "GET / HTTP/1.1" 302 4125 "-" "Wget/1.21.3" 10.207.83.17 - - [24/Sep/2025:07:29:50 +0200] "GET /univention/ HTTP/1.1" 302 864 "-" "Wget/1.21.3" 10.207.83.17 - - [24/Sep/2025:07:29:50 +0200] "GET /univention/portal/ HTTP/1.1" 200 3541 "-" "Wget/1.21.3" 127.0.0.1 - - [24/Sep/2025:07:30:26 +0200] "GET / HTTP/1.1" 302 540 "-" "check_http/v2.3.3 (monitoring-plugins 2.3.3)" ``` +++ This bug was initially created as a clone of Bug #58627 +++