Univention Bugzilla – Bug 46870
umcp auth command not working when using exam mode as saml user
Last modified: 2019-02-27 14:05:47 CET
When you are logged in via SSO and start an exam you have to enter your password again, since the module has the requirePassword decorator. I observed a strange behavior on my ucsschool 4.3 machine where the POST request for authenticating the user does not get resolved and the wizard does not progress. After cancelling and returning to the main page the web app still gets progress responses until you hit F5. Just before the page refreshes you can see a dialog saying "Error with the connection". After refreshing the page and trying the exam mode again all of a sudden it works like a charm. As soon as you log out from the website you have to redo this procedure.
This was the /var/log/univention/management-console-web-server.log: 23.04.18 11:32:34.315 MAIN ( PROCESS ) : CPCommand (192.168.0.224:47818) response status code: 401 23.04.18 11:32:34.315 MAIN ( PROCESS ) : CPCommand (192.168.0.224:47818) response message: This action requires you to supply your password. 23.04.18 11:32:34.315 MAIN ( PROCESS ) : CPCommand (192.168.0.224:47818) response result: {'password_required': True} 23.04.18 11:32:34.315 MAIN ( PROCESS ) : CPCommand (192.168.0.224:47818) response error: {'traceback': None, 'command': 'start_exam'} 23.04.18 11:32:47.095 MAIN ( PROCESS ) : SessionClient(0x7fab2407eb90): no request(152447596662983-1902) found: status=200 23.04.18 11:32:47.391 MAIN ( PROCESS ) : SessionClient(0x7fab2407eb90): _authenticated: success=True status=200 message=None 23.04.18 11:34:26.257 MAIN ( PROCESS ) : CPCommand (192.168.0.224:48254) response status code: 401 23.04.18 11:34:26.257 MAIN ( PROCESS ) : CPCommand (192.168.0.224:48254) response message: This action requires you to supply your password. 23.04.18 11:34:26.257 MAIN ( PROCESS ) : CPCommand (192.168.0.224:48254) response result: {'password_required': True} 23.04.18 11:34:26.257 MAIN ( PROCESS ) : CPCommand (192.168.0.224:48254) response error: {'traceback': None, 'command': 'start_exam'} 23.04.18 11:34:34.566 MAIN ( PROCESS ) : SessionClient(0x7fab2407eb90): _authenticated: success=True status=200 message=None 23.04.18 11:34:34.566 MAIN ( PROCESS ) : auth_type=None 23.04.18 11:34:35.084 MAIN ( PROCESS ) : SessionClient(0x7fab2409c110): _authenticated: success=True status=200 message=None 23.04.18 11:34:35.084 MAIN ( PROCESS ) : auth_type=None I separated the log where the first attempt ends and the second one started. There is a slight difference in the log entries, but I cannot make any sense of it.
I removed the progressbar and the authentication request got through. I think the "schoolexam/progress" always gets resolved before the the auth request but I'm not sure why.
Created attachment 9512 [details] Propsed patch The patch slows down the progress call if the status did not change. I also added a progress reset. After stopping an exam the progress wasn't reset. The require password popup delays the execution of start_exam (which resets the status) but not the progress check. The progress check now answered with the old finished status from stopping an exam which resulted in the frontend thinking start_exam was finished.
I looked some more into this. "schoolexam/progress" returns basically a static python dict. Currently around 3 calls per second containing not much more than a dict can completely block another call. The problem seems to be somewhere in make_queue_request() (see: univention-management-console-web-server) which blocks the auth call. The blocking call seems to be a thread lock acquire in python Queue. (strace also stops at a futex systemcall for the thread that is responsible for the auth call) My best guess is that due to the constant load on one thread by the "schoolexam/progress" call, python never switches to back to the thread handling the auth call? As proposed in the patch I will slowdown the progress call which seems to be the easiest solution for now. Worst case: starting an exam takes a second longer.
Created attachment 9523 [details] Propsed patch2
I think I finally found the problem: After sending the auth command univention-management-console-web-server:get_response() thinks that the session timed out and sends a second auth request. (get_response was called by the progress command). src/univention/management/console/protocol/client.py keeps track of one auth requests with an id if a second auth request is called that id gets overwritten. The first auth request now doesn't emit the 'authenticated' signal because client.py only uses one auth_id. But univention-management-console-web-server expects that signal before answering the first auth command
Branch: juern/46870_double_auth https://git.knut.univention.de/univention/ucs/commit/2e4aa195e8a664077602a9487b81b9a1751dc683
The underlying problem is now tracked with bug 47106. I will check in the workaround for now.
We need a backport for UCS 4.2 so bug #46998 doesn't introduce the same bug as well. (see bug #47109)
[4.3-1 ad1ffd1417] Bug #46870: fix hanging auth command [4.3-1 cbd3a3792d] Bug #46870: yaml
Created attachment 9571 [details] test46870.py I attached a test script that sends 500 parallel authentication requests with 0.2 seconds delay between them. I tested the new package with it. Result: the authentication still works... but I found another bug. If auth requests come in too fast, the might get lost. In my test 34 of 500 requests weren't answered.
(In reply to Sönke Schwardt-Krummrich from comment #11) > the authentication still works... but I found another bug. If auth requests > come in too fast, the might get lost. In my test 34 of 500 requests weren't > answered. → Bug 47239 OK: code change OK: functional change OK: tests OK: changelog entry OK: advisory OK: package built and installable
<http://errata.software-univention.de/ucs/4.3/125.html>