Bug 46870 - umcp auth command not working when using exam mode as saml user
umcp auth command not working when using exam mode as saml user
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: SAML
UCS 4.3
Other Linux
: P5 normal (vote)
: UCS 4.3-1-errata
Assigned To: Jürn Brodersen
Sönke Schwardt-Krummrich
:
Depends on:
Blocks: 47239 46998 46999 47109
  Show dependency treegraph
 
Reported: 2018-04-23 13:13 CEST by Ole Schwiegert
Modified: 2019-02-27 14:05 CET (History)
4 users (show)

See Also:
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:
Ticket number:
Bug group (optional): SAML
Max CVSS v3 score:


Attachments
Propsed patch (1.04 KB, patch)
2018-04-24 16:30 CEST, Jürn Brodersen
Details | Diff
Propsed patch2 (1.73 KB, patch)
2018-05-07 18:24 CEST, Jürn Brodersen
Details | Diff
test46870.py (658 bytes, text/x-python)
2018-06-23 22:30 CEST, Sönke Schwardt-Krummrich
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Ole Schwiegert univentionstaff 2018-04-23 13:13:43 CEST
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.
Comment 1 Ole Schwiegert univentionstaff 2018-04-23 13:14:53 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.
Comment 2 Jürn Brodersen univentionstaff 2018-04-23 18:29:47 CEST
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.
Comment 3 Jürn Brodersen univentionstaff 2018-04-24 16:30:13 CEST
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.
Comment 4 Jürn Brodersen univentionstaff 2018-05-04 15:07:29 CEST
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.
Comment 5 Jürn Brodersen univentionstaff 2018-05-07 18:24:11 CEST
Created attachment 9523 [details]
Propsed patch2
Comment 6 Jürn Brodersen univentionstaff 2018-05-07 18:24:32 CEST
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
Comment 7 Jürn Brodersen univentionstaff 2018-05-18 16:32:03 CEST
Branch: juern/46870_double_auth

https://git.knut.univention.de/univention/ucs/commit/2e4aa195e8a664077602a9487b81b9a1751dc683
Comment 8 Jürn Brodersen univentionstaff 2018-05-30 16:25:53 CEST
The underlying problem is now tracked with bug 47106.

I will check in the workaround for now.
Comment 9 Jannik Ahlers univentionstaff 2018-05-31 11:37:41 CEST
We need a backport for UCS 4.2 so bug #46998 doesn't introduce the same bug as well.
(see bug #47109)
Comment 10 Jürn Brodersen univentionstaff 2018-06-15 15:26:38 CEST
[4.3-1 ad1ffd1417] Bug #46870: fix hanging auth command
[4.3-1 cbd3a3792d] Bug #46870: yaml
Comment 11 Sönke Schwardt-Krummrich univentionstaff 2018-06-23 22:30:00 CEST
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.
Comment 12 Sönke Schwardt-Krummrich univentionstaff 2018-06-23 22:37:12 CEST
(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
Comment 13 Erik Damrose univentionstaff 2018-06-27 14:37:25 CEST
<http://errata.software-univention.de/ucs/4.3/125.html>