Univention Bugzilla – Full Text Bug Listing |
Summary: | umcp auth command not working when using exam mode as saml user | ||
---|---|---|---|
Product: | UCS | Reporter: | Ole Schwiegert <schwiegert> |
Component: | SAML | Assignee: | Jürn Brodersen <brodersen> |
Status: | CLOSED FIXED | QA Contact: | Sönke Schwardt-Krummrich <schwardt> |
Severity: | normal | ||
Priority: | P5 | CC: | ahlers, best, brodersen, michelsmidt |
Version: | UCS 4.3 | ||
Target Milestone: | UCS 4.3-1-errata | ||
Hardware: | Other | ||
OS: | Linux | ||
See Also: | https://forge.univention.org/bugzilla/show_bug.cgi?id=47106 | ||
What kind of report is it?: | Bug Report | What type of bug is this?: | 5: Major Usability: Impairs usability in key scenarios |
Who will be affected by this bug?: | 3: Will affect average number of installed domains | How will those affected feel about the bug?: | 2: A Pain – users won’t like this once they notice it |
User Pain: | 0.171 | Enterprise Customer affected?: | |
School Customer affected?: | ISV affected?: | ||
Waiting Support: | Flags outvoted (downgraded) after PO Review: | ||
Ticket number: | Bug group (optional): | SAML | |
Max CVSS v3 score: | |||
Bug Depends on: | |||
Bug Blocks: | 46998, 46999, 47109, 47239 | ||
Attachments: |
Propsed patch
Propsed patch2 test46870.py |
Description
Ole Schwiegert
2018-04-23 13:13:43 CEST
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 |