Univention Bugzilla – Bug 42997
Listener module for generating netlogon scripts is too slow
Last modified: 2018-04-20 16:48:16 CEST
Currently the listener module for generating netlogon scripts is triggered by LDAP modifications of user, group and share objects. For each event the corresponding netlogon scripts are rebuilt. There are some situations when this approach takes too much time: a) when rejoining slave systems, the rebuild o all netlogon scripts takes minutes up to hours b) when starting the exam mode, there the replication might be too slow and hits the current timeout of 300 seconds for replication of all exam users to the corresponding school server. Idea to speed up the rebuild: Affected DNs are not immediately handled in handler() but collected until a certain number of changes is reached, e.g. handler() has been called 100 times (UCR variable!), or the listener module's postrun() method is called. DNs might be collected by creating/touching the file /var/lib/ucs-school-netlogon-user-logonscripts/${DN}. This way recurring changes to the same LDAP object are automatically merged and there is no information loss if the listener gets stopped. Log excerpts from a customer system: 15.11.16 13:47:03.619 LISTENER (INFO): updating 'cn=exam-someuser1,cn=uid,cn=temporary,cn=univention,dc=example,dc=com' command a 15.11.16 13:47:03.733 LISTENER (INFO): updating 'cn=xxxxxx,cn=uidNumber,cn=temporary,cn=univention,dc=example,dc=com' command a 15.11.16 13:47:03.831 LISTENER (INFO): updating 'cn=xxxxxx,cn=gidNumber,cn=temporary,cn=univention,dc=example,dc=com' command a 15.11.16 13:47:03.925 LISTENER (INFO): updating 'cn=xxxxxx,cn=gidNumber,cn=temporary,cn=univention,dc=example,dc=com' command d 15.11.16 13:47:03.993 LISTENER (INFO): updating 'cn=S-1-5-21-xxxxxxxxxx-xxxxxxxxxx-xxxxxxxxxx-xxxxxxx,cn=sid,cn=temporary,cn=univention,dc=example,dc=com' command a 15.11.16 13:47:04.073 LISTENER (INFO): updating 'uid=exam-someuser1,cn=examusers,ou=schoolA,dc=example,dc=com' command a 15.11.16 13:47:04.318 LISTENER (INFO): updating 'cn=Domain Users schoolA,cn=groups,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:04.653 LISTENER (INFO): updating 'cn=schuelerschoolA,cn=groups,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:04.872 LISTENER (INFO): updating 'cn=schoolA-Q II,cn=klassen,cn=schueler,cn=groups,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:05.002 LISTENER (INFO): updating 'cn=schoolA-GKurs-13-mat 10,cn=kurse,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:05.152 LISTENER (INFO): updating 'cn=schoolA-LKurs-13-BIO 4,cn=kurse,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:05.290 LISTENER (INFO): updating 'cn=schoolA-GKurs-13-che 30,cn=kurse,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:05.382 LISTENER (INFO): updating 'cn=schoolA-GKurs-13-kun 15,cn=kurse,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:05.640 LISTENER (INFO): updating 'cn=schoolA-LKurs-13-GEG 2,cn=kurse,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:05.812 LISTENER (INFO): updating 'cn=schoolA-GKurs-13-spopr 12,cn=kurse,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:05.952 LISTENER (INFO): updating 'cn=schoolA-GKurs-13-deu 65,cn=kurse,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:06.137 LISTENER (INFO): updating 'cn=schoolA-GKurs-13-ges 35,cn=kurse,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:06.443 LISTENER (INFO): updating 'cn=schoolA-GKurs-13-eng 50,cn=kurse,ou=schoolA,dc=example,dc=com' command m 15.11.16 13:47:06.654 LISTENER (INFO): updating 'cn=OUschoolA-Klassenarbeit,cn=ucsschool,cn=groups,dc=example,dc=com' command m 15.11.16 13:47:06.788 LISTENER (INFO): updating 'cn=exam-someuser1,cn=uid,cn=temporary,cn=univention,dc=example,dc=com' command d 15.11.16 13:47:06.869 LISTENER (INFO): updating 'cn=S-1-5-21-xxxxxxxxxx-xxxxxxxxxx-xxxxxxxxxx-xxxxxxx,cn=sid,cn=temporary,cn=univention,dc=example,dc=com' command d
Please also have a look at Bug 43019.
*** Bug 44629 has been marked as a duplicate of this bug. ***
The code for generating the netlogon scripts for Windows users has been moved to a daemon. There is no explicit init.d script. The daemon is started via systemd: systemctl status ucs-school-netlogon-user-logonscripts.service The listener module now uses the UDM modules for users, shares and groups for generation of the listener LDAP filter. For communication with the daemon, a sqlite database is used with 3 columns: id, user_dn and username. The id is automatically increasing. If a user is created, modified, deleted, the user DN is written to sqlite. Please note, that there should always be only one entry per user object at a time within the database. If the user is modified a second time, the entry is automatically replace with the same data (→ no effective modification in DB). Upon group modification, the uniqueMember difference between old and new is automatically calculated in listener module and only the difference is written to DB. For further performance optimization, only DNs starting with "uid=" are written to DB (not computers in group or groups in group). Upon share modifications (add, modify, delete) all users of the associated group are affected. Because of this, a share modification triggers a group modification internally (handled like a new group). Only changes to univentionShareSambaName, univentionShareHost and univentionShareGid are considered as relevant share modification, that trigger further actions. All other modifications are ignored (e.g. description change). If a new entry has been written to DB, the signal USR1 is sent to the daemon. The daemon is started via systemd and logs into the file /var/log/univention/ucs-school-user-logonscript-daemon.log. A configuration for logrotate has been added, that restarts the daemon after rotating the log file. The PID of the daemon is automatically written to /var/run/ucs-school-user-logonscript-daemon.pid, which is used by the listener module for sending SIGUSR1 to the daemon. The daemon regulary iterates over all entries within the DB. Between each complete run, the daemon sleeps for 180 seconds (adjustable via ucsschool/userlogon/daemon/check-interval). If SIGUSR1 is detected by the daemon, and the daemon is sleeping, the remaining sleep time is reduced to 7 seconds (adjustable via ucsschool/userlogon/daemon/check-interval-minimum) if more than 7 seconds were remaining. This way, the daemon aggregates several events (e.g. 1 user is created → 1 new user object and at least 3 group modifications that are merged into 1 event for the daemon). If an exception is raised during netlogon creation, the user DN is requeued to the DB (with new ID, which means at the end of the queue), the daemon sleeps for 5 seconds (adjustable via ucsschool/userlogon/daemon/error-delay) and then processes the next entry within the DB. This way, problematic entries are automatically retried after some time. Most of the code path has not been changed (some smaller changes "cls." → "self."; global lo instance). The database handling has been implemented in ucsschool.netlogon.lib.SqliteQueue() The log output below shows a successful sample run and a manually triggered exception. The log level of the daemon is adjustable via ucsschool/userlogon/daemon/debug/level (default: 3). For QA: please check if the vbs scripts of old and new version of this package are the identical: # cp -a /var/lib/samba/netlogon/user /var/lib/samba/netlogon/user.ORIG # dpkg -i $PKG # univention-directory-listener-ctrl resync ucs-school-user-logonscript # diff -Naur /var/lib/samba/netlogon/user{.ORIG,} # Add new user: ============= ==> /var/log/univention/listener.log <== 10.09.17 15:12:07.943 LISTENER ( PROCESS ) : updating 'cn=saca6,cn=uid,cn=temporary,cn=univention,dc=nstx,dc=local' command a 10.09.17 15:12:08.207 LISTENER ( PROCESS ) : updating 'cn=3629,cn=uidNumber,cn=temporary,cn=univention,dc=nstx,dc=local' command a 10.09.17 15:12:08.245 LISTENER ( PROCESS ) : updating 'cn=3629,cn=gidNumber,cn=temporary,cn=univention,dc=nstx,dc=local' command a 10.09.17 15:12:08.250 LISTENER ( PROCESS ) : updating 'cn=3629,cn=gidNumber,cn=temporary,cn=univention,dc=nstx,dc=local' command d 10.09.17 15:12:08.254 LISTENER ( PROCESS ) : updating 'cn=S-1-5-21-3842850871-998187786-178935136-8258,cn=sid,cn=temporary,cn=univention,dc=nstx,dc=local' command a 10.09.17 15:12:08.260 LISTENER ( PROCESS ) : updating 'uid=saca6,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' command a 10.09.17 15:12:08.706 LISTENER ( PROCESS ) : samba4-idmap: added entry for S-1-5-21-3842850871-998187786-178935136-8258 UNIVENTION_DEBUG_BEGIN : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local UNIVENTION_DEBUG_END : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local ==> /var/log/univention/ucs-school-user-logonscript-daemon.log <== 2017-09-10 15:12:08,772 [INFO] signal received - reduced wait time by 86.3 seconds ==> /var/log/univention/listener.log <== 10.09.17 15:12:08.786 LISTENER ( PROCESS ) : updating 'cn=saca6,cn=uid,cn=temporary,cn=univention,dc=nstx,dc=local' command d 10.09.17 15:12:08.817 LISTENER ( PROCESS ) : updating 'cn=S-1-5-21-3842850871-998187786-178935136-8258,cn=sid,cn=temporary,cn=univention,dc=nstx,dc=local' command d 10.09.17 15:12:08.824 LISTENER ( PROCESS ) : updating 'cn=uidNumber,cn=temporary,cn=univention,dc=nstx,dc=local' command m 10.09.17 15:12:08.840 LISTENER ( PROCESS ) : updating 'cn=3629,cn=uidNumber,cn=temporary,cn=univention,dc=nstx,dc=local' command d 10.09.17 15:12:08.854 LISTENER ( PROCESS ) : updating 'cn=Domain Users gsmitte,cn=groups,ou=gsmitte,dc=nstx,dc=local' command m UNIVENTION_DEBUG_BEGIN : uldap.__open host=slave66.nstx.local port=7389 base=dc=nstx,dc=local UNIVENTION_DEBUG_END : uldap.__open host=slave66.nstx.local port=7389 base=dc=nstx,dc=local UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = displayName UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = displayName UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = ucsschoolClassShareFileServer UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = ucsschoolClassShareFileServer UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = ucsschoolHomeShareFileServer UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = ucsschoolHomeShareFileServer 10.09.17 15:12:09.206 LISTENER ( PROCESS ) : pupilgroups: all_local_schools=['ou=gsmitte,dc=nstx,dc=local'] 10.09.17 15:12:09.207 LISTENER ( PROCESS ) : pupilgroups: dn: cn=Domain Users gsmitte,cn=groups,ou=gsmitte,dc=nstx,dc=local UNIVENTION_DEBUG_BEGIN : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local UNIVENTION_DEBUG_END : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local 10.09.17 15:12:09.827 LISTENER ( PROCESS ) : updating 'cn=gsmitte-1,cn=klassen,cn=schueler,cn=groups,ou=gsmitte,dc=nstx,dc=local' command m 10.09.17 15:12:09.925 LISTENER ( PROCESS ) : pupilgroups: dn: cn=gsmitte-1,cn=klassen,cn=schueler,cn=groups,ou=gsmitte,dc=nstx,dc=local UNIVENTION_DEBUG_BEGIN : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local UNIVENTION_DEBUG_END : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local 10.09.17 15:12:10.457 LISTENER ( PROCESS ) : updating 'cn=schueler-gsmitte,cn=groups,ou=gsmitte,dc=nstx,dc=local' command m 10.09.17 15:12:10.672 LISTENER ( PROCESS ) : pupilgroups: dn: cn=schueler-gsmitte,cn=groups,ou=gsmitte,dc=nstx,dc=local UNIVENTION_DEBUG_BEGIN : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local UNIVENTION_DEBUG_END : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local 10.09.17 15:12:11.239 LISTENER ( PROCESS ) : updating 'uid=saca6,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' command m UNIVENTION_DEBUG_BEGIN : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local UNIVENTION_DEBUG_END : uldap.__open host=master65.nstx.local port=7389 base=dc=nstx,dc=local 10.09.17 15:12:11.372 LISTENER ( PROCESS ) : updating 'uid=saca6,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' command m ==> /var/log/univention/ucs-school-user-logonscript-daemon.log <== 2017-09-10 15:12:14,365 [DEBUG] just woke up... 2017-09-10 15:12:14,366 [DEBUG] starting sqlite query: 'SELECT userdn,username FROM user_queue ORDER BY id LIMIT 1' 2017-09-10 15:12:14,366 [DEBUG] next entry: userdn=u'uid=saca6,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' 2017-09-10 15:12:14,366 [DEBUG] found uid=saca6,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local in queue 2017-09-10 15:12:14,374 [DEBUG] removed entry: userdn=u'uid=saca6,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' 2017-09-10 15:12:14,374 [DEBUG] fetching data for uid=saca6,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local 2017-09-10 15:12:14,378 [INFO] updating logon script for uid=saca6,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local 2017-09-10 15:12:14,379 [DEBUG] user is member of following groups: set(['5020', '5023', '5087']) 2017-09-10 15:12:14,381 [DEBUG] user links {'gsmitte-1': 'slave66', 'Marktplatz': 'slave66'} 2017-09-10 15:12:14,396 [DEBUG] starting sqlite query: 'SELECT userdn,username FROM user_queue ORDER BY id LIMIT 1' 2017-09-10 15:12:14,397 [INFO] all items processed... sleeping... Test error: =========== 2017-09-10 15:25:51,246 [DEBUG] starting sqlite query: 'SELECT userdn,username FROM user_queue ORDER BY id LIMIT 1' 2017-09-10 15:25:51,247 [DEBUG] next entry: userdn=u'uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' 2017-09-10 15:25:51,248 [DEBUG] found uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local in queue 2017-09-10 15:25:51,255 [DEBUG] removed entry: userdn=u'uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' 2017-09-10 15:25:51,256 [DEBUG] fetching data for uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local 2017-09-10 15:25:51,259 [INFO] updating logon script for uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local 2017-09-10 15:25:51,262 [DEBUG] user is member of following groups: set(['5020', '5023', '5087']) 2017-09-10 15:25:51,266 [DEBUG] added/updated entry: userdn=u'uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' username=None 2017-09-10 15:25:51,266 [ERROR] An error occured while processing "uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local": ValueError('This is a test error',) 2017-09-10 15:25:51,266 [DEBUG] EXCEPTION: Traceback (most recent call last): File "./ucs-school-user-logonscript-daemon", line 268, in run self.handle_user_change(user_dn, username) File "./ucs-school-user-logonscript-daemon", line 369, in handle_user_change for share in self.get_shares_with_specific_gidNumber(ID): File "./ucs-school-user-logonscript-daemon", line 303, in get_shares_with_specific_gidNumber raise ValueError('This is a test error') # TODO FIXME remove test error ValueError: This is a test error 2017-09-10 15:25:54,270 [DEBUG] starting sqlite query: 'SELECT userdn,username FROM user_queue ORDER BY id LIMIT 1' 2017-09-10 15:25:54,270 [DEBUG] next entry: userdn=u'uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' 2017-09-10 15:25:54,270 [DEBUG] starting sqlite query: 'SELECT userdn,username FROM user_queue ORDER BY id LIMIT 1' 2017-09-10 15:25:54,271 [DEBUG] next entry: userdn=u'uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' 2017-09-10 15:25:54,271 [DEBUG] found uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local in queue 2017-09-10 15:25:54,274 [DEBUG] removed entry: userdn=u'uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local' 2017-09-10 15:25:54,274 [DEBUG] fetching data for uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local 2017-09-10 15:25:54,276 [INFO] updating logon script for uid=saca7,cn=schueler,cn=users,ou=gsmitte,dc=nstx,dc=local ... Changes have been merged to branch "4.2". ucs-school-netlogon-user-logonscripts (13.0.2-1): c8486c7d4f24 | Bug #42997: Merge branch 'sschwardt/42997/422/async-netlogon-generation' into 4.2 0857af046423 | Bug #42997: add changelog entry b876e1633347 | Bug #42997: add descriptions for new UCR variables 2b2daf30df00 | Bug #42997: small changes to UCR variable description d9ec90db0ea2 | Bug #42997: handle groups in groups or computers in groups c98494953861 | Bug #42997: only handle relevant user changes ef9ceb6df4b3 | Bug #42997: send signal USR1 to daemon if queue has been modified 75ec25c491ce | Bug #42997: add spool directory to package 4eeee0acea28 | Bug #42997: add ucslint.overrides 770f4dc68e44 | Bug #42997: cleanup whitespace e21a939c2445 | Bug #42997: initial version of ucsschool.netlogon.lib 11e14841efc6 | Bug #42997: whitespace cleanup for pyflakes 168546aa1773 | Bug #42997: exit early c336749cea00 | Bug #42997: use with statement / chmod+chown before closing with statement 9aac8221f5e8 | Bug #42997: add more log levels 28389f51ecc4 | Bug #42997: add config for log rotation and automatic daemon restart cda9031270f0 | Bug #42997: implement initial version of daemon 9e6131edb968 | Bug #42997: add debug output to listener module 2320f2535d58 | Bug #42997: prepare listener module for new daemon 2a8ac79a5a65 | Bug #42997: remove old code from listener module 03a19bd11c00 | Bug #42997: copy code as base for daemon ucs-school-netlogon-user-logonscripts.yaml: c8486c7d4f24 | Bug #42997: Merge branch 'sschwardt/42997/422/async-netlogon-generation' into 4.2 0e6df3fdc65d | Bug #42997: add advisory Package: ucs-school-netlogon-user-logonscripts Version: 13.0.2-1A~4.2.0.201710091107 Branch: ucs_4.2-0 Scope: ucs-school-4.2
Renamed Performance for 1416 users: 09.10.17 12:26:32.860 LISTENER ( WARN ) : initializing module ucs-school-user-logonscript […] 09.10.17 12:28:30.568 LISTENER ( WARN ) : finished initializing module ucs-school-user-logonscript with rv=0 Added performance optimization for group objects (and indirectly share object). A DB commit is now only performed *once* after all relevant group members have been added to sqlite DB. Before, after each user a DB commit has been performed. This reduced the group handling time for my test group from 3.5 seconds down to 0.04s. The complete resync (see above) takes now on my test machine 1m58s. Without optimization it took 2m33s. Package: ucs-school-netlogon-user-logonscripts Version: 13.0.2-2A~4.2.0.201710091237 Branch: ucs_4.2-0 Scope: ucs-school-4.2 65bdf92708f2 | Bug #42997: Merge branch 'sschwardt/42997/422/async-netlogon-generation' into 4.2 6f2d1e5e6893 | Bug #42997: add changelog entry 3ad0c715a389 | Bug #42997: add performance optimization for group handling 5c6bdc1f14cd | Bug #42997: rename ucsschool.netlogon.lib to ucsschool.netlogon (part 2/2) d039ca6942c1 | Bug #42997: rename ucsschool.netlogon.lib to ucsschool.netlogon (part 1/2)
(In reply to Sönke Schwardt-Krummrich from comment #4) > Renamed Renamed python module ucsschool.netlogon.lib to ucsschool.netlogon.
Note: the sqlite database (containing DN and username) is readable by everybody REOPEN: usernames with special characters causes error in the listener module: udm users/user create --position cn=schueler,cn=users,ou=oldschool,dc=school,dc=local --set username='qaäöüasdf' --set lastname='qaäöüasdf' --set password=univention 24.08.17 12:03:59.302 LISTENER ( INFO ) : ucs-school-user-logonscript: handle_group: dn: cn=Domain Users,cn=groups,dc=school,dc=local 24.08.17 12:03:59.302 LISTENER ( INFO ) : ucs-school-user-logonscript: handle_group: difference: set(['uid=qa\xc3\xa4\xc3\xb6\xc3\xbcasdf,cn=schueler,cn=users,ou=oldschool,dc=school,dc=local']) Traceback (most recent call last): File "/usr/lib/univention-directory-listener/system/ucs-school-user-logonscript.py", line 178, in handler handle_group(dn, new, old, lo, user_queue) File "/usr/lib/univention-directory-listener/system/ucs-school-user-logonscript.py", line 144, in handle_group user_queue.add(user_dn, db_commit=False) File "/usr/lib/pymodules/python2.7/ucsschool/netlogon/__init__.py", line 125, in add self.cursor.execute('insert or replace into user_queue (id, userdn, username) VALUES ((select id from user_queue where userdn = ?), ?, (select username from user_queue where userdn = ?))', (userdn, userdn, userdn)) sqlite3.ProgrammingError: You must not use 8-bit bytestrings unless you use a text_factory that can interpret 8-bit bytestrings (like text_factory = str). It is highly recommended that you instead just switch your application to Unicode strings. 24.08.17 12:03:59.304 LISTENER ( WARN ) : handler: ucs-school-user-logonscript (failed)
I cannot start an exam with 2000 users in 400 classes. After 15 minutes I get an 501 HTTP error.
(In reply to Florian Best from comment #7) > I cannot start an exam with 2000 users in 400 classes. After 15 minutes I > get an 501 HTTP error. Please send me the listener.log via mail.
(In reply to Florian Best from comment #6) > Note: the sqlite database (containing DN and username) is readable by > everybody > REOPEN: usernames with special characters causes error in the listener > module: I was able to reproduce it. From https://www.ietf.org/rfc/rfc4514.txt: > 3. Parsing a String Back to a Distinguished Name > > The string representation of Distinguished Names is restricted to > UTF-8 [RFC3629] encoded Unicode [Unicode] characters. The "uid" attribute uses the syntax 1.3.6.1.4.1.1466.115.121.1.15 (→ UTF-8). Therefore username and the user DN are always encoded in UTF-8. The class SqliteQueue in ucsschool.netlogon has been adapted accordingly and decodes incoming (UTF-8) strings to unicode if not already unicode. Query results are given back as UTF-8 encoded strings. ucs-school-netlogon-user-logonscripts (13.0.2-4): c22d5cc9a844 | Bug #42997: Merge branch 'sschwardt/42997/422/async-netlogon-generation' into 4.2 db80a7046bcd | Bug #42997: add changelog entry 5001b3a92550 | Bug #42997: fix utf-8 problems with SqliteQueue Package: ucs-school-netlogon-user-logonscripts Version: 13.0.2-4A~4.2.0.201710111129 Branch: ucs_4.2-0 Scope: ucs-school-4.2
Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: Traceback (most recent call last): Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: File "/usr/share/ucs-school-netlogon-user-logonscripts/ucs-school-user-logonscript-daemon", line 689, in <module> Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: main() Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: File "/usr/share/ucs-school-netlogon-user-logonscripts/ucs-school-user-logonscript-daemon", line 685, in main Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: handler.run() Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: File "/usr/share/ucs-school-netlogon-user-logonscripts/ucs-school-user-logonscript-daemon", line 661, in run Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: if self.user_queue.query_next_user()[0] is None and not self.shutdown_requested: Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: File "/usr/lib/pymodules/python2.7/ucsschool/netlogon/__init__.py", line 156, in query_next_user Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: username = row[1].encode('utf-8') Okt 12 18:12:53 slave81 ucs-school-user-logonscript-daemon[2181]: AttributeError: 'NoneType' object has no attribute 'encode'
m( ucs-school-netlogon-user-logonscripts (13.0.2-5): 32a505aaad73 | Bug #42997: Merge branch 'sschwardt/42997/422/async-netlogon-generation' into 4.2 59f2d2d338ab | Bug #42997: add changelog entry 7ec09decee9f | Bug #42997: import standard modules first 1832f2c40530 | Bug #42997: fix traceback if username is None Package: ucs-school-netlogon-user-logonscripts Version: 13.0.2-5A~4.2.0.201710122316 Branch: ucs_4.2-0 Scope: ucs-school-4.2
OK: Code review OK: no SQL injection possible OK: In a clean environment I could start an exam in short time with 100, 200, 400 users. 2000 users is still failing with some timeout. OK: error handling (ucr set ucsschool/userlogon/umclink/filter='') OK: the netlogon daemon creates ca. 100 scripts per second. OK: YAML
UCS@school 4.2 v4 has been released. http://docs.software-univention.de/changelog-ucsschool-4.2v4-de.html If this error occurs again, please clone this bug.