Comment 1 Florian Best 2022-10-25 10:05:09 CEST

So, you installed an app (e.g. UCS@school) and the joinscript created the extension but the listener failed to activate it in the first attempt (why didn't it succeed first?).
Then you are in this situation that re-running the joinscript doesn't cause modifications of the extension object, it's still not activated and therefore runs after 3 minutes into the fail-timeout.

Comment 2 Christina Scheinig 2022-10-26 12:09:43 CEST

Little update here. In the remote session, the dc has this ldapschema object as already active in the udm, but the joinscript of the backup server and the replica server were not able to finish successfully. Removing the udm schema object and rerun the joinscript on the backup, created and activated it successfully on the primary. The slave server, could finish the joinscript after the backup created and activated the schema object on the master, **without** removing it again!

root@dc:~# udm settings/ldapschema list --filter cn=umc-helpdesk
cn=umc-helpdesk
DN: cn=umc-helpdesk,cn=ldapschema,cn=univention,dc=example,dc=de
  active: TRUE
  data: QlpoOTFBWSZTWXCrKPYAAC7fgAAwTON/kD7n/mA//9/gMAFrMTQlCTRqjeqfqmEepo2RADJk/VGhp6J6gNEnojU9Rk0aaaGmgAAADQAkiU9FN6nqNT00hp6jQyfqgGgAAyXMB4xgnHbNy1VPkLgda929UKFN1hnJ6fSFOaP9oryiyuY2Hs6Jir0y8lKQIyPa9Es1xuNUuxlExApFvwQIBQYBlpS2gmcTAMK90lQTKmdxOyHHqZlzJNIToGYSjETwpDBgBOh1KAmRKuMRbc/jrNWuExrFR1qYTZWM8bsHe6mVJ67DYQiDDVUaGO9aV1Y3Kw3rRBIZOZSWP2dXPuR0q4mvIuZn06oJDaXDHK4XAad/Av4I8xL97UY6c/UOxASw7pVF5eeDRC4qFS+H6KJ/AQewtu0kAvtKrs07EbIgPWlDtMyWHivmls3XaBaNUyCFhadRxhaba5JV8mTESUxkZLmykwa5s5FS1C+VCQ6qAPwhynPWAZEhqEj860DxgWSiwLVjKGNTrWLVE0mNYRWNeEp/4u5IpwoSDhVlHsA=
  filename: umc-helpdesk.schema
  name: umc-helpdesk
  package: ucs-school-umc-helpdesk-schema
  packageversion: 16.0.5A~5.0.0.202109091718

root@dc:~# mkdir univention-support
root@dc:~# cd univention-support
root@dc:~/univention-support# udm settings/ldapschema list --filter cn=umc-helpdesk > umc-helpdesk.bak
root@dc:~/univention-support# udm settings/ldapschema remove --dn cn=umc-helpdesk,cn=ldapschema,cn=univention,dc=example,dc=de
Object removed: cn=umc-helpdesk,cn=ldapschema,cn=univention,dc=example,dc=de
root@dc:~/univention-support# udm settings/ldapschema list --filter cn=umc-helpdesk
cn=umc-helpdesk
DN: cn=umc-helpdesk,cn=ldapschema,cn=univention,dc=example,dc=de
  active: TRUE
  data: QlpoOTFBWSZTWXCrKPYAAC7fgAAwTON/kD7n/mA//9/gMAFrMTQlCTRqjeqfqmEepo2RADJk/VGhp6J6gNEnojU9Rk0aaaGmgAAADQAkiU9FN6nqNT00hp6jQyfqgGgAAyXMB4xgnHbNy1VPkLgda929UKFN1hnJ6fSFOaP9oryiyuY2Hs6Jir0y8lKQIyPa9Es1xuNUuxlExApFvwQIBQYBlpS2gmcTAMK90lQTKmdxOyHHqZlzJNIToGYSjETwpDBgBOh1KAmRKuMRbc/jrNWuExrFR1qYTZWM8bsHe6mVJ67DYQiDDVUaGO9aV1Y3Kw3rRBIZOZSWP2dXPuR0q4mvIuZn06oJDaXDHK4XAad/Av4I8xL97UY6c/UOxASw7pVF5eeDRC4qFS+H6KJ/AQewtu0kAvtKrs07EbIgPWlDtMyWHivmls3XaBaNUyCFhadRxhaba5JV8mTESUxkZLmykwa5s5FS1C+VCQ6qAPwhynPWAZEhqEj860DxgWSiwLVjKGNTrWLVE0mNYRWNeEp/4u5IpwoSDhVlHsA=
  filename: umc-helpdesk.schema
  name: umc-helpdesk
  package: ucs-school-umc-helpdesk-schema
  packageversion: 16.0.5A~5.0.0.202109091718

Comment 3 Dirk Wiesenthal 2022-11-18 12:11:27 CET

So touching any (yet to be created?) attribute in the object may help in cases where the extension itself is okay, but some temporary issues (network?) lead to a failure.

Comment 5 Christina Scheinig 2023-02-21 14:14:30 CET

Happend again, this generates support tickets

Comment 6 Christina Scheinig 2023-02-21 15:31:32 CET

next

Comment 8 Arvid Requate 2023-02-28 19:07:59 CET

I've tried to reproduce, but I failed. I've created a patch proposal (MR) anyway, but maybe it's missing the point.

My initial question would be if the ACL or schema object had `active: TRUE` or `active: FALSE` initially in these cases.

If it was `active: TRUE` I currently see no reason why the code should timeout waiting for activation 
if we also see lines like the following in the join.log:

> INFO: No change of core data of object 65ucsschool.
> No modification: cn=65ucsschool,cn=ldapacl,cn=univention,dc=schule-example,dc=de

Because in that case it was active, was not changed and so I see no reason how the code can timeout.

Comment 9 Christina Scheinig 2023-04-27 13:35:32 CEST

So workaround applied for this failure
RUNNING 33univention-portal.inst
2023-04-27 10:27:55.752505617+02:00 (in joinscript_init)
Object exists: cn=UMC,cn=univention,dc=schein,dc=de
Object exists: cn=UMC,cn=policies,dc=schein,dc=de
Object exists: cn=operations,cn=UMC,cn=univention,dc=schein,dc=de
Object exists: cn=default-umc-all,cn=UMC,cn=policies,dc=schein,dc=de
No modification: cn=Domain Admins,cn=groups,dc=schein,dc=de
Object exists: cn=default-umc-users,cn=UMC,cn=policies,dc=v,dc=de
No modification: cn=Domain Users,cn=groups,dc=schein,dc=de
Object exists: cn=ldapschema,cn=univention,dc=schein,dc=de
INFO: No change of core data of object univention-portal.
No modification: cn=univention-portal,cn=ldapschema,cn=univention,dc=schein,dc=de
 
Object exists: cn=ldapacl,cn=univention,dc=schein,dc=de
INFO: No change of core data of object 62univention-portal.
No modification: cn=62univention-portal,cn=ldapacl,cn=univention,dc=schein,dc=de
 
Object exists: cn=udm_syntax,cn=univention,dc=schein,dc=de
INFO: No change of core data of object univention-portal.
No modification: cn=univention-portal,cn=udm_syntax,cn=univention,dc=schein,dc=de
 
Waiting for activation of the extension object univention-portal: OK
Waiting for activation of the extension object 62univention-portal: OK
Waiting for activation of the extension object univention-portal: ........................................................ERROR
ERROR: Primary Directory Node did not mark the extension object active within 180 seconds.
ucs_registerLDAPExtension: registraton of /usr/lib/univention-portal/syntax/univention-portal.py failed.
 
EXITCODE=1
-----------------
So removing this entry crashed udm 

Workaround is NOT available → please fix

Comment 10 Philipp Hahn 2023-04-27 13:52:17 CEST

(In reply to Christina Scheinig from comment #9)
> So workaround applied for this failure
...
> ucs_registerLDAPExtension: registraton of /usr/lib/univention-portal/syntax/univention-portal.py failed.

The problem here is that the syntax-module is imported by several UDM modules in handlers/portal/, which still exists but then fail to load because of the missing files.
This breaks all UDM:
- UDM just stalls as the CLI server cannot be forked respectively crashes.
- `python3 -m univention.admincli.admin` at least provides some output.

# python3 -m univention.admincli.admin
Traceback (most recent call last):
  File "/usr/lib/python3.7/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/lib/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/usr/lib/python3/dist-packages/univention/admincli/admin.py", line 58, in <module>
    univention.admin.modules.update()
  File "/usr/lib/python3/dist-packages/univention/admin/modules.py", line 153, in update
    _walk(root, w_root, w_files)
  File "/usr/lib/python3/dist-packages/univention/admin/modules.py", line 140, in _walk
    m = importlib.import_module('univention.admin.handlers.%s' % (modulepackage,))  # type: Any
  File "/usr/lib/python3.7/importlib/__init__.py", line 127, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1006, in _gcd_import
  File "<frozen importlib._bootstrap>", line 983, in _find_and_load
  File "<frozen importlib._bootstrap>", line 967, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 677, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 728, in exec_module
  File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
  File "/usr/lib/python3/dist-packages/univention/admin/handlers/portals/folder.py", line 80, in <module>
    syntax=univention.admin.syntax.NewPortalEntries,
AttributeError: module 'univention.admin.syntax' has no attribute 'NewPortalEntries'

→ univention.admin.modules.update() should catch any errors on import and SKIP that module instead of crashing, so UDM can be still used for all remaining things.

→ UDM should print an error when the CLI-server cannot be forked.

Comment 12 Christina Scheinig 2023-06-30 15:49:18 CEST

Again UCS 5.0-4 

RUNNING 33univention-portal.inst
2023-06-28 15:55:16.495188349+02:00 (in joinscript_init)
Object exists: cn=UMC,cn=univention,dc=ucs,dc=schein,dc=de
Object exists: cn=UMC,cn=policies,dc=ucs,dc=schein,dc=de
Object exists: cn=operations,cn=UMC,cn=univention,dc=ucs,dc=schein,dc=de
Object exists: cn=default-umc-all,cn=UMC,cn=policies,dc=ucs,dc=schein,dc=de
No modification: cn=Domain Admins,cn=groups,dc=ucs,dc=schein,dc=de
Object exists: cn=default-umc-users,cn=UMC,cn=policies,dc=ucs,dc=schein,dc=de
No modification: cn=Domain Users,cn=groups,dc=ucs,dc=schein,dc=de
Object exists: cn=ldapschema,cn=univention,dc=ucs,dc=schein,dc=de
INFO: No change of core data of object univention-portal.
No modification: cn=univention-portal,cn=ldapschema,cn=univention,dc=ucs,dc=schein,dc=de

Object exists: cn=ldapacl,cn=univention,dc=ucs,dc=schein,dc=de
INFO: No change of core data of object 62univention-portal.
No modification: cn=62univention-portal,cn=ldapacl,cn=univention,dc=ucs,dc=schein,dc=de

Object exists: cn=udm_syntax,cn=univention,dc=ucs,dc=schein,dc=de
INFO: No change of core data of object univention-portal.
No modification: cn=univention-portal,cn=udm_syntax,cn=univention,dc=ucs,dc=schein,dc=de

Waiting for activation of the extension object univention-portal: .........................................................ERROR
ERROR: Primary Directory Node did not mark the extension object active within 180 seconds.
ucs_registerLDAPExtension: registraton of /usr/lib/univention-portal/schema/univention-portal.schema failed.

EXITCODE=1

Comment 15 Florian Best 2023-07-04 10:02:15 CEST

It's part of our Prio Bugs in Q3. But so far we don't have an idea how to reliably reproduce it.
Please also always say which joinscripts are affected with which error messages and what is part of listener.log at that time.
I am not sure if all the different failures have the same reason.

One idea for a failing univention-monitoring-client joinscript is that multiple servers are involved and maybe upgraded in parallel?
Because the listener.log once said "no modification".

Comment 16 Arvid Requate 2023-07-04 18:00:23 CEST

From that customers test system (from Comment 11) I've collected
a bit of additional information and tried to correlate updater.log
and listener.log.

The system is just the UCS primary directory node cloned probably
from the productive domain. univention-app domain shows other
backup DCs that are not available from the perspective of the
cloned primary.

tl;dr: The listner either had no connection to the LDAP server or
(in other cases) was busy initializion listener modules.

My feeling is the first problem is a consequence of running joinscripts
as part of postinst on primary nodes, while the LDAP server may
simply be down. IMHO we c/should fix this by making joinscripts
run the same way on primary directory nodes as on replicas: After
the package updates have been done. Additionally it would be
good if the initialization of new listener modules could happen
in a way that doesn't block other "urgent" replication steps.



Details from the updater.log:
======
root@master:~/univention-support # zgrep "Waiting for activation of the extension object" /var/log/univention/updater.log.16.gz 
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object univention-portal: .....................................................ERROR
Waiting for activation of the extension object 64selfservice_userattributes: OK
======
That happens in updater.log during this phase:
======
14.06.23 22:46:11.713  DEBUG_INIT
**** Starting univention-updater 5.0-0 with parameter=['/usr/share/univention-updater/univention-updater', 'net', '--updateto', '5.0-0', '--silent', '--ignoressh', '--ignoreterm']
--->DBG:update_available(mode=net)
Checking network repository
Update hold at 5.0-0, next 5.0-1 is after 5.0-0

Starting univention-upgrade. Current UCS version is 5.0-0 errata0

Update to UCS version 5.0-0 finished at Wed Jun 14 22:46:12 2023...

Starting univention-upgrade. Current UCS version is 5.0-0 errata0
[...]
Starting univention-upgrade. Current UCS version is 5.0-0 errata195
======

The context around that error is:
======
Calling joinscript 33univention-portal.inst ...
2023-06-14 23:09:54.842236237+02:00 (in joinscript_init)
Object exists: cn=UMC,cn=univention,dc=school,dc=domain
Object exists: cn=UMC,cn=policies,dc=school,dc=domain
Object exists: cn=operations,cn=UMC,cn=univention,dc=school,dc=domain
Object exists: cn=default-umc-all,cn=UMC,cn=policies,dc=school,dc=domain
No modification: cn=Domain Admins,cn=groups,dc=school,dc=domain
Object exists: cn=default-umc-users,cn=UMC,cn=policies,dc=school,dc=domain
No modification: cn=Domain Users,cn=groups,dc=school,dc=domain
Object exists: cn=ldapschema,cn=univention,dc=school,dc=domain
INFO: No change of core data of object univention-portal.
Object modified: cn=univention-portal,cn=ldapschema,cn=univention,dc=school,dc=domain

Object exists: cn=ldapacl,cn=univention,dc=school,dc=domain
INFO: No change of core data of object 62univention-portal.
Object modified: cn=62univention-portal,cn=ldapacl,cn=univention,dc=school,dc=domain

Object exists: cn=udm_syntax,cn=univention,dc=school,dc=domain
INFO: No change of core data of object univention-portal.
Object modified: cn=univention-portal,cn=udm_syntax,cn=univention,dc=school,dc=domain

Waiting for activation of the extension object univention-portal: .....................................................ERROR
ERROR: Primary Directory Node did not mark the extension object active within 180 seconds.
ucs_registerLDAPExtension: registraton of /usr/lib/univention-portal/schema/univention-portal.schema failed.

Joinscript 33univention-portal.inst finished with exitcode 1
======
During that time the listener.log shows that it was not connected:
======
14.06.23 23:09:24.700  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds
14.06.23 23:09:54.700  LISTENER    ( WARN    ) : Notifier/LDAP server is master.school.domain:7389
14.06.23 23:09:54.700  LDAP        ( PROCESS ) : connecting to ldap://master.school.domain:7389
14.06.23 23:09:54.704  LISTENER    ( ERROR   ) : failed to connect to any notifier
14.06.23 23:09:54.704  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds
14.06.23 23:10:24.705  LISTENER    ( WARN    ) : Notifier/LDAP server is master.school.domain:7389
14.06.23 23:10:24.705  LDAP        ( PROCESS ) : connecting to ldap://master.school.domain:7389
======
So no activation could take place during that time.


The problem also occurs later for other LDAP extensions. E.g. during:
======
> Starting univention-upgrade. Current UCS version is 5.0-2 errata378
======
more failures occur:
======
root@master:~/univention-support # zgrep "Waiting for activation of the extension object .*ERROR" /var/log/univention/updater.log.*.gz 
/var/log/univention/updater.log.15.gz:Waiting for activation of the extension object univention-monitoring: .....................................................ERROR
/var/log/univention/updater.log.15.gz:Waiting for activation of the extension object s4_connector: .....................................................ERROR
======
The details around the first one:
======
Calling joinscript 30univention-monitoring-client.inst ...
2023-06-15 09:51:48.801416903+02:00 (in joinscript_init)
Object exists: cn=monitoring,dc=school,dc=domain
Object exists: cn=ldapschema,cn=univention,dc=school,dc=domain
Object modified: cn=univention-monitoring,cn=ldapschema,cn=univention,dc=school,dc=domain
Object exists: cn=ldapacl,cn=univention,dc=school,dc=domain
Object created: cn=62univention-monitoring,cn=ldapacl,cn=univention,dc=school,dc=domain

Waiting for activation of the extension object univention-monitoring: .....................................................ERROR
ERROR: Primary Directory Node did not mark the extension object active within 180 seconds.
ucs_registerLDAPExtension: registraton of /usr/lib/univention-monitoring-client/schema/univention-monitoring.schema failed.
======
The details around the second one:
======
Calling joinscript 97univention-s4-connector.inst ...
2023-06-15 09:55:11.636882641+02:00 (in joinscript_init)
Not updating connector/s4/ldap/host
Not updating connector/s4/ldap/base
Not updating connector/s4/ldap/ssl
Not updating connector/s4/mapping/group/language
Not updating connector/s4/ldap/protocol
Not updating connector/s4/ldap/socket
Object exists: cn=gPLink,cn=custom attributes,cn=univention,dc=school,dc=domain
Object exists: cn=WMIPolicy,cn=System,dc=school,dc=domain
Object exists: cn=SOM,cn=WMIPolicy,cn=System,dc=school,dc=domain
Object exists: cn=udm_syntax,cn=univention,dc=school,dc=domain
Object modified: cn=s4_connector,cn=udm_syntax,cn=univention,dc=school,dc=domain

Waiting for activation of the extension object s4_connector: .....................................................ERROR
ERROR: Primary Directory Node did not mark the extension object active within 180 seconds.
ucs_registerLDAPExtension: registraton of /usr/lib/python3/dist-packages/univention/admin/syntax.d/s4_connector.py failed.
======

And then again:
======
> Starting univention-upgrade. Current UCS version is 5.0-2 errata703
[...]
/var/log/univention/updater.log.15.gz:Waiting for activation of the extension object 64selfservice_userattributes: .....................................................ERROR
/var/log/univention/updater.log.15.gz:Waiting for activation of the extension object 64selfservice_userattributes: .....................................................ERROR
======
univention-self-service-master (5.0.6-1A~5.0.0.202302061855) wird eingerichtet ...
Neue Version der Konfigurationsdatei /etc/univention/registry.info/variables/univention-self-service-master.cfg wird installiert ...
Neue Version der Konfigurationsdatei /etc/univention/templates/modules/self-service-acl.py wird installiert ...
Neue Version der Konfigurationsdatei /etc/univention/templates/modules/self-service-links.py wird installiert ...
Module: self-service-links
cn=self-service-create-account,cn=entry,cn=portals,cn=univention,dc=school,dc=domain active state set to False
cn=self-service-verify-account,cn=entry,cn=portals,cn=univention,dc=school,dc=domain active state set to False
cn=self-service-password-forgotten,cn=entry,cn=portals,cn=univention,dc=school,dc=domain active state set to True
cn=self-service-protect-account,cn=entry,cn=portals,cn=univention,dc=school,dc=domain active state set to True
cn=self-service-service-specific-passwords,cn=entry,cn=portals,cn=univention,dc=school,dc=domain active state set to False
cn=self-service-my-profile,cn=entry,cn=portals,cn=univention,dc=school,dc=domain active state set to True
Module: self-service-acl
Registering ACL in LDAP
Object exists: cn=ldapacl,cn=univention,dc=school,dc=domain
Object modified: cn=64selfservice_userattributes,cn=ldapacl,cn=univention,dc=school,dc=domain

Waiting for activation of the extension object 64selfservice_userattributes: .....................................................ERROR
ERROR: Primary Directory Node did not mark the extension object active within 180 seconds.
ucs_registerLDAPExtension: registraton of /usr/share/univention-self-service/64selfservice_userattributes.acl failed.
======


This last thing is interesting, as it sometimes worked and sometimes not:
======
root@master:~/univention-support # zgrep "Waiting for activation of the extension object 64selfservice_userattributes"  /var/log/univention/updater.log.15.gz 
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: .....................................................ERROR
Waiting for activation of the extension object 64selfservice_userattributes: .....................................................ERROR
Waiting for activation of the extension object 64selfservice_userattributes: OK
Waiting for activation of the extension object 64selfservice_userattributes: OK
======

This is always "OK" when there's also the line
> INFO: No change of core data of object 64selfservice_userattributes.
In contrast, the first "ERROR" came, when there was an actual change.
In this case it was an ACL, but it also happens with UDM syntax extensions:
======
root@master:~/univention-support # zgrep "Waiting for activation of the extension object s4_connector"  /var/log/univention/updater.log.15.gz
## univention-s4-connector (14.0.10-7A~5.0.0.202210041605) wird eingerichtet ...
## [...]
## Calling joinscript 97univention-s4-connector.inst ...
Waiting for activation of the extension object s4_connector: .....................................................ERROR
## univention-s4-connector (14.0.13-6) wird eingerichtet ...
## [...]
## Calling joinscript 97univention-s4-connector.inst ...
Waiting for activation of the extension object s4_connector: OK
======


Now let's look at temporal correlations:
Around the time of the ERROR for 64selfservice_userattributes (2023-06-15 10:53:49.260182440+02:00)
the listener.log shows a lot of activity about the initialization of listener modules:
======
15.06.23 10:46:45.379  DEBUG_INIT
15.06.23 10:46:45.389  LISTENER    ( WARN    ) : Notifier/LDAP server is master.school.domain:7389
15.06.23 10:46:45.389  LDAP        ( PROCESS ) : connecting to ldap://master.school.domain:7389
15.06.23 10:46:48.126  LISTENER    ( ERROR   ) : import of filename=/usr/lib/univention-directory-listener/system/ucsschool-kelvin-rest-api.py failed
[...]
Traceback (most recent call last):
  File "/usr/lib/univention-directory-listener/system/ucsschool-kelvin-rest-api.py", line 10, in <module>
    class AppListener(AppListener):
  File "/usr/lib/python3/dist-packages/univention/listener/handler.py", line 69, in __new__
    kls.config = kls._get_configuration(name)
  File "/usr/lib/python3/dist-packages/univention/listener/handler.py", line 353, in _get_configuration
    return conf_class()
  File "/usr/lib/python3/dist-packages/univention/listener/handler_configuration.py", line 84, in __init__
    self._run_checks()
  File "/usr/lib/python3/dist-packages/univention/listener/handler_configuration.py", line 95, in _run_checks
    if not getattr(self, f'get_{attr}', lambda: '')() and not getattr(self, attr, ''):
  File "/usr/lib/python3/dist-packages/univention/appcenter/listener.py", line 99, in get_ldap_filter
    return '(|%s)' % ''.join(filter_format('(univentionObjectType=%s)', [udm_module]) for udm_module in app.listener_udm_modules)
AttributeError: 'NoneType' object has no attribute 'listener_udm_modules'
15.06.23 10:48:31.689  LISTENER    ( ERROR   ) : import of filename=/usr/lib/univention-directory-listener/system/ucsschool-kelvin-rest-api.py failed in module_import
15.06.23 10:48:31.750  LISTENER    ( WARN    ) : initializing module school_creation_self_service
[...]
15.06.23 10:53:37.415  LISTENER    ( PROCESS ) : school_creation_self_service: Adding 'Domain Users Foo_bar' to ucrv 'umc/self-service/passwordreset/whitelist/
Setting umc/self-service/passwordreset/whitelist/groups
15.06.23 10:53:37.831  LISTENER    ( WARN    ) : finished initializing module school_creation_self_service with rv=0
15.06.23 10:53:37.831  LISTENER    ( WARN    ) : initializing module license_uuid
[...]
15.06.23 10:54:34.337  LISTENER    ( WARN    ) : finished initializing module license_uuid with rv=0
15.06.23 10:54:34.337  LISTENER    ( WARN    ) : initializing module bildungslogin_metadata
[...]
15.06.23 10:55:41.540  LISTENER    ( PROCESS ) : bildungslogin_metadata: New Bildungslogin license. Code: 'FOO-bar' Product ID: 'urn:foo:medium:bar,cn=bildungslogin,cn=vbm,cn=univention,dc=school,dc=domain'
15.06.23 10:55:41.540  LISTENER    ( PROCESS ) : bildungslogin_metadata: Meta data for product 'urn:foo:medium:bar' already exist in LDAP.
[...]
15.06.23 10:55:41.947  LISTENER    ( WARN    ) : finished initializing module bildungslogin_metadata with rv=0
15.06.23 10:55:41.947  LISTENER    ( WARN    ) : initializing module school_creation_http_api_update
[...]
15.06.23 11:06:53.768  LISTENER    ( PROCESS ) : school_creation_http_api_update: Update school foo12345 in http api
[...]
15.06.23 11:14:16.059  LISTENER    ( WARN    ) : finished initializing module school_creation_http_api_update with rv=0
======

So that's kind of "explainable".
How about the ERROR for s4_connector (2023-06-15 09:55:11.636882641+02:00)?
======
15.06.23 09:54:59.815  DEBUG_INIT
15.06.23 09:54:59.825  LISTENER    ( WARN    ) : Notifier/LDAP server is master.school.domain:7389
15.06.23 09:54:59.825  LDAP        ( PROCESS ) : connecting to ldap://master.school.domain:7389
15.06.23 09:54:59.831  LISTENER    ( ERROR   ) : failed to connect to any notifier
15.06.23 09:54:59.831  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds
15.06.23 09:55:11.532  LISTENER    ( WARN    ) : received signal 15
15.06.23 09:55:11.548  DEBUG_INIT
15.06.23 09:55:11.559  LISTENER    ( WARN    ) : Notifier/LDAP server is master.school.domain:7389
15.06.23 09:55:11.559  LDAP        ( PROCESS ) : connecting to ldap://master.school.domain:7389
15.06.23 09:55:14.828  LISTENER    ( ERROR   ) : import of filename=/usr/lib/univention-directory-listener/system/ucsschool-kelvin-rest-api.py failed
Traceback (most recent call last):
  File "/usr/lib/univention-directory-listener/system/ucsschool-kelvin-rest-api.py", line 10, in <module>
    class AppListener(AppListener):
  File "/usr/lib/python3/dist-packages/univention/listener/handler.py", line 62, in __new__
    kls.config = kls._get_configuration()
  File "/usr/lib/python3/dist-packages/univention/listener/handler.py", line 353, in _get_configuration
    return cls.Configuration()
  File "/usr/lib/python3/dist-packages/univention/listener/handler_configuration.py", line 83, in __init__
    self._run_checks()
  File "/usr/lib/python3/dist-packages/univention/listener/handler_configuration.py", line 94, in _run_checks
    if not getattr(self, 'get_{}'.format(attr), lambda: '')() and not getattr(self, attr, ''):
  File "/usr/lib/python3/dist-packages/univention/appcenter/listener.py", line 98, in get_ldap_filter
    return '(|%s)' % ''.join(filter_format('(univentionObjectType=%s)', [udm_module]) for udm_module in app.listener_udm_modules)
AttributeError: 'NoneType' object has no attribute 'listener_udm_modules'
15.06.23 09:55:14.829  LISTENER    ( ERROR   ) : import of filename=/usr/lib/univention-directory-listener/system/ucsschool-kelvin-rest-api.py failed in module_import
15.06.23 09:55:14.892  LISTENER    ( WARN    ) : initializing module ldap-cache-baa04df67e7af6bb0769f5cb7e72dba9
15.06.23 09:59:59.280  DEBUG_INIT
15.06.23 09:59:59.291  LISTENER    ( WARN    ) : Notifier/LDAP server is master.school.domain:7389
15.06.23 09:59:59.291  LDAP        ( PROCESS ) : connecting to ldap://master.school.domain:7389
15.06.23 10:00:02.236  LISTENER    ( ERROR   ) : import of filename=/usr/lib/univention-directory-listener/system/ucsschool-kelvin-rest-api.py failed
Traceback (most recent call last):
[...]
15.06.23 10:06:44.157  LISTENER    ( PROCESS ) : updating 'cn=UNIVENTION_SAMBA_REPLICATION,cn=monitoring,dc=school,dc=domain' command m
15.06.23 10:06:44.231  LISTENER    ( PROCESS ) : updating 'cn=UNIVENTION_SAMBA_REPLICATION_MISSING,cn=monitoring,dc=school,dc=domain' command m
15.06.23 10:06:44.237  LISTENER    ( PROCESS ) : updating 'cn=univentionObjectIdentifier,cn=temporary,cn=univention,dc=school,dc=domain' command a
15.06.23 10:06:44.240  LISTENER    ( PROCESS ) : updating 'cn=univention-monitoring,cn=ldapschema,cn=univention,dc=school,dc=domain' command m
Multifile: /etc/ldap/slapd.conf
15.06.23 10:06:48.960  LISTENER    ( PROCESS ) : updating 'cn=62univention-monitoring,cn=ldapacl,cn=univention,dc=school,dc=domain' command a
15.06.23 10:06:48.963  LISTENER    ( PROCESS ) : ldap_extension: cn=62univention-monitoring,cn=ldapacl,cn=univention,dc=school,dc=domain active? [b'FALSE']
Multifile: /etc/ldap/slapd.conf
15.06.23 10:06:53.133  LISTENER    ( PROCESS ) : updating 'cn=monitoring/alert,cn=udm_module,cn=univention,dc=school,dc=domain' command m
15.06.23 10:06:53.595  LISTENER    ( PROCESS ) : updating 'cn=UNIVENTION_S4CONNECTOR,cn=monitoring,dc=school,dc=domain' command m
15.06.23 10:06:53.601  LISTENER    ( PROCESS ) : updating 'cn=UNIVENTION_S4CONNECTOR_WARNING,cn=monitoring,dc=school,dc=domain' command m
15.06.23 10:06:53.607  LISTENER    ( PROCESS ) : updating 'cn=UNIVENTION_S4CONNECTOR_MISSING,cn=monitoring,dc=school,dc=domain' command m
15.06.23 10:06:53.612  LISTENER    ( PROCESS ) : updating 'cn=s4_connector,cn=udm_syntax,cn=univention,dc=school,dc=domain' command m
15.06.23 10:06:53.870  LISTENER    ( PROCESS ) : updating 'cn=64selfservice_userattributes,cn=ldapacl,cn=univention,dc=school,dc=domain' command m
15.06.23 10:06:53.873  LISTENER    ( PROCESS ) : ldap_extension: cn=64selfservice_userattributes,cn=ldapacl,cn=univention,dc=school,dc=domain active? [b'TRUE']
Multifile: /etc/ldap/slapd.conf
15.06.23 10:06:58.056  LISTENER    ( PROCESS ) : updating 'cn=ldap_extension,cn=handler_messages,cn=univention,dc=school,dc=domain' command m
15.06.23 10:06:58.061  LISTENER    ( PROCESS ) : updating 'cn=ldap_extension,cn=handler_messages,cn=univention,dc=school,dc=domain' command m
15.06.23 10:06:58.062  LISTENER    ( PROCESS ) : updating 'cn=s4_connector,cn=udm_syntax,cn=univention,dc=school,dc=domain' command m
15.06.23 10:06:58.066  LISTENER    ( PROCESS ) : updating 'cn=ldap_extension,cn=handler_messages,cn=univention,dc=school,dc=domain' command m
15.06.23 10:07:10.562  LISTENER    ( WARN    ) : received signal 15
15.06.23 10:07:10.661  LISTENER    ( ERROR   ) : Error reloading prometheus alert rules: 404 Client Error: Not Found for url: http://localhost/metrics-prometheus/-/re
26513
15.06.23 10:07:10.688  LISTENER    ( PROCESS ) : ldap_extension: Reloading LDAP server.
15.06.23 10:08:41.183  DEBUG_INIT
======
That ^^^ section of the log output coincidently shows the activation of
cn=univention-monitoring,cn=ldapschema, ... and
cn=62univention-monitoring,cn=ldapacl,... which according to the updater.log
didn't happen quick enough at 2023-06-15 09:51:48 (see closer to the top of this comment).

Also for the first

Comment 17 Arvid Requate 2023-08-18 11:45:06 CEST

As a first step we decided to follow the approach of Comment 3
to make univention-run-join-scripts actually trigger the activation
again before waiting for activation.

For the next step to go ahead and make the registration/activation process more robust I created Bug #56453.


6c73df7166 | Add ldap_touch_udm_object
1eeedbde52 | Advisory

product: ucs
release: "5.0"
version: [4]
scope: ucs_5.0-0-errata5.0-4
src: univention-lib
fix: 9.0.16-3
desc: |
 This update addresses the following issues:
 * In case an LDAP ACL or schema extension got installed by a joinscript
   by running `ucs_registerLDAPExtension` and it was not activated for some
   reason (e.g. because the slapd was not running at the time when the
   postrun of the `ldap_extension` listener module was running)
   a rerun of `univention-run-join-scripts` did not change anything.
   Now `ucs_registerLDAPExtension` has been adjusted to do a trivial
   (i.e. no-op) LDAP modification to re-trigger activation.
bug: [55337]

Comment 18 Felix Botner 2023-08-21 09:02:36 CEST

- OK univention-lib 9.0.16-4
- OK manual tests
- OK jenkins tests
- OK yaml

Comment 19 Philipp Hahn 2023-08-23 14:54:15 CEST

<https://errata.software-univention.de/#/?erratum=5.0x785>