Bug 1557609 - Login to FreeIPA web UI as regular user fails
Summary: Login to FreeIPA web UI as regular user fails
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: freeipa
Version: 28
Hardware: All
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: IPA Maintainers
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: AcceptedBlocker
Depends On:
Blocks: F28BetaBlocker
TreeView+ depends on / blocked
 
Reported: 2018-03-17 06:27 UTC by Adam Williamson
Modified: 2018-03-21 21:26 UTC (History)
9 users (show)

Fixed In Version: freeipa-4.6.90.pre1-6.1.fc28
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-03-21 20:31:32 UTC
Type: Bug


Attachments (Terms of Use)
Archive of /var/log from the server (1.79 MB, application/x-gzip)
2018-03-17 06:29 UTC, Adam Williamson
no flags Details
Archive of /var/log from the client (1.80 MB, application/x-gzip)
2018-03-17 06:29 UTC, Adam Williamson
no flags Details


Links
System ID Priority Status Summary Last Updated
FedoraHosted FreeIPA 7452 None None None 2018-03-19 19:53:28 UTC

Description Adam Williamson 2018-03-17 06:27:01 UTC
With https://bodhi.fedoraproject.org/updates/FEDORA-2018-2fd7295cb9 and https://bodhi.fedoraproject.org/updates/FEDORA-2018-066e9e600b , freeipa works a *lot* better. However, openQA does still hit a problem. One test which involves logging into the web UI as a user created on the server during server deployment fails (while logging in as the FreeIPA administrator works).

As part of server deployment, we create two user accounts - test3 and test4. test4 is granted no privileges and is just used to test that access to certain things is correctly *denied*. test3 is granted login privileges and stuff, and is used to test password changing via the web UI.

When test3 tries to log in to the web UI to change its password, this fails:

https://openqa.stg.fedoraproject.org/tests/257031#step/freeipa_password_change/11

I don't know what 'show details' says, unfortunately (I could tweak the test to find out over the weekend). But we do have logs! I'll attach full tarballs of /var/log on the server and client.

The login attempt happened at 2018-03-17T05:09:24.0624 UTC according to the client test log. Around that time in the client system logs I really don't see a whole lot, but on the server I see these interesting messages in the HTTP server logs (the difference in time is just UTC vs. system local time):

server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.673910 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: test3@DOMAIN.LOCAL: batch: i18n_messages(): SUCCESS
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.682713 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: test3@DOMAIN.LOCAL: batch: config_show(): EmptyResult
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.687326 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: test3@DOMAIN.LOCAL: batch: whoami(): SUCCESS
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.687863 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: test3@DOMAIN.LOCAL: batch: env(None): SUCCESS
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.690008 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: test3@DOMAIN.LOCAL: batch: dns_is_enabled(): SUCCESS
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.691584 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: test3@DOMAIN.LOCAL: batch: trustconfig_show(): NotFound
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.692866 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: test3@DOMAIN.LOCAL: batch: domainlevel_get(): SUCCESS
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.695413 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: test3@DOMAIN.LOCAL: batch: ca_is_enabled(): SUCCESS
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.696895 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: test3@DOMAIN.LOCAL: batch: vaultconfig_show(): InvocationError
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.697175 2018] [wsgi:error] [pid 8206:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: [jsonserver_session] test3@DOMAIN.LOCAL: batch(({'method': 'i18n_messages', 'params': ([], {})}, {'method': 'config_show', 'params': ([], {})}, {'method': 'whoami', 'params': ([], {})}, {'method': 'env', 'params': ([], {})}, {'method': 'dns_is_enabled', 'params': ([], {})}, {'method': 'trustconfig_show', 'params': ([], {})}, {'method': 'domainlevel_get', 'params': ([], {})}, {'method': 'ca_is_enabled', 'params': ([], {})}, {'method': 'vaultconfig_show', 'params': ([], {})}), version='2.229'): SUCCESS
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.714049 2018] [:warn] [pid 8207:tid 140231285995264] [client 10.0.2.102:38678] failed to set perms (3140) on file (/var/run/ipa/ccaches/test3@DOMAIN.LOCAL)!, referer: https://ipa001.domain.local/ipa/ui/
server/var/log/httpd/error_log:[Sat Mar 17 01:09:24.746485 2018] [wsgi:error] [pid 8205:tid 140231233902336] [remote 10.0.2.102:38678] ipa: INFO: [jsonserver_session] test3@DOMAIN.LOCAL: user_show/1('test3', all=True, version='2.229'): SUCCESS

krb5kdc.log has:

server/var/log/krb5kdc.log:Mar 17 01:09:24 ipa001.domain.local krb5kdc[8108](info): AS_REQ (8 etypes {18 17 20 19 16 23 25 26}) 10.0.2.100: NEEDED_PREAUTH: test3@DOMAIN.LOCAL for krbtgt/DOMAIN.LOCAL@DOMAIN.LOCAL, Additional pre-authentication required
server/var/log/krb5kdc.log:Mar 17 01:09:24 ipa001.domain.local krb5kdc[8108](info): AS_REQ (8 etypes {18 17 20 19 16 23 25 26}) 10.0.2.100: ISSUE: authtime 1521263364, etypes {rep=18 tkt=18 ses=18}, test3@DOMAIN.LOCAL for krbtgt/DOMAIN.LOCAL@DOMAIN.LOCAL
server/var/log/krb5kdc.log:Mar 17 01:09:24 ipa001.domain.local krb5kdc[8108](info): TGS_REQ (8 etypes {18 17 20 19 16 23 25 26}) 10.0.2.100: ISSUE: authtime 1521263364, etypes {rep=18 tkt=18 ses=18}, test3@DOMAIN.LOCAL for HTTP/ipa001.domain.local@DOMAIN.LOCAL
server/var/log/krb5kdc.log:Mar 17 01:09:24 ipa001.domain.local krb5kdc[8108](info): ... CONSTRAINED-DELEGATION s4u-client=test3@DOMAIN.LOCAL

I don't see any immediately obviously-related AVCs, but there *are* some AVCs.

Not sure how much use this is. Please let me know what other info would be useful and I'll try to get it out of the tests.

Comment 1 Adam Williamson 2018-03-17 06:28:28 UTC
Proposing as a Beta blocker. Beta criteria:

"The core functional requirements for all Featured Server Roles must be met, without any workarounds being necessary." - https://fedoraproject.org/wiki/Fedora_28_Beta_Release_Criteria#Role_functional_requirements

From the domain controller role core requirements:

"The FreeIPA configuration web UI must be available and allow at least basic configuration of user accounts and permissions" - https://fedoraproject.org/wiki/Domain_controller_role_requirements

Comment 2 Adam Williamson 2018-03-17 06:29:10 UTC
Created attachment 1409049 [details]
Archive of /var/log from the server

Comment 3 Adam Williamson 2018-03-17 06:29:35 UTC
Created attachment 1409050 [details]
Archive of /var/log from the client

Comment 4 Alexander Bokovoy 2018-03-17 07:26:18 UTC
Adam, logs on the server are OK, nothing bad. The "errors" are from components which aren't installed, so they are expected.

AVCs related to gssproxy need to be fixed:
type=AVC msg=audit(1521262938.030:375): avc:  denied  { getattr } for  pid=7390 comm="gssproxy" path="/proc/8543" dev="proc" ino=70561 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:httpd_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1521263042.297:377): avc:  denied  { getattr } for  pid=7390 comm="gssproxy" path="/proc/8210" dev="proc" ino=70560 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:httpd_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1521263042.559:378): avc:  denied  { getattr } for  pid=7390 comm="gssproxy" path="/proc/8207" dev="proc" ino=70559 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:httpd_t:s0 tclass=dir permissive=0

There is also AVC for oddjob helper when creating a homedir:
Mar 17 01:08:28 client002 audit[761]: USER_AVC pid=761 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  denied  { send_msg } for msgtype=method_call interface=com.redhat.oddjob_mkhomedir member=mkhomedirfor dest=com.redhat.oddjob_mkhomedir spid=2818 tpid=2578 scontext=system_u:system_r:init_t:s0 tcontext=system_u:system_r:oddjob_t:s0-s0:c0.c1023 tclass=dbus permissive=0#012 exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'


However, given that server processing of a test3 request when successfully through, the problem might actually be somewhere else, like Web UI javascript code itself. The last command Web UI login screen should issue is 'user_show(test3)' and it indeed does that and gets successful response.

On the client I see this in the secure log:

Mar 17 01:08:28 client002 login[2813]: pam_sss(login:auth): authentication success; logname=LOGIN uid=0 euid=0 tty=tty4 ruser= rhost= user=test3@DOMAIN.LOCAL
Mar 17 01:08:28 client002 systemd[2818]: pam_unix(systemd-user:session): session opened for user test3@domain.local by (uid=0)
Mar 17 01:08:29 client002 login[2813]: pam_unix(login:session): session opened for user test3@DOMAIN.LOCAL by LOGIN(uid=0)
Mar 17 01:08:29 client002 login[2813]: LOGIN ON tty4 BY test3@domain.local
Mar 17 01:08:33 client002 login[2813]: pam_unix(login:session): session closed for user test3@DOMAIN.LOCAL
Mar 17 01:08:36 client002 login[2849]: pam_sss(login:auth): authentication success; logname=LOGIN uid=0 euid=0 tty=tty4 ruser= rhost= user=test4@DOMAIN.LOCAL
Mar 17 01:08:36 client002 login[2849]: pam_sss(login:account): Access denied for user test4@DOMAIN.LOCAL: 6 (Permission denied)
Mar 17 01:08:36 client002 login[2849]: Permission denied


According to your explanation, test4 should correctly be denied and it is indeed denied, no problem here. test3 is allowed to login and it is allowed to do so.

I'll setup a local F28 to test it.

Comment 5 Adam Williamson 2018-03-17 23:29:35 UTC
Thanks. If you don't figure it out by Monday, I'll work on making the test show the extra information in the browser.

Comment 6 Alexander Bokovoy 2018-03-18 08:01:33 UTC
My mirrors don't yet have the packages. I tried ~10 mirrors and all of them lacked the packages even though bodhi reports they were already pushed out ~7 hours ago.

I suspect it will have to wait until Monday.

Comment 7 Adam Williamson 2018-03-19 19:18:30 UTC
I know you got to it now, but for the record, some tricks for package stuff:

* Hack up your repo definitions to use a baseurl pointing to a known-good mirror, instead of the mirrormanager magic
* Just grab the update packages directly - `bodhi updates download --updateid=(UPDATEID)` , then 'dnf update *.rpm' or create a side repo containing them or whatever

You can also get packages directly from *Koji* with `koji download-build --arch=x86_64 --arch=noarch NVR` or so.

It seems some mirrors have been slow to sync lately, we're not sure why, nirik says he's hopeful things will be smoothed out soon.

Comment 8 Alexander Bokovoy 2018-03-19 19:53:29 UTC
Thanks.

I reproduced the issue, tracked as https://pagure.io/freeipa/issue/7452 upstream. I provided a pull request https://github.com/freeipa/freeipa/pull/1708 upstream to fix it.

Comment 9 Adam Williamson 2018-03-19 21:12:49 UTC
Discussed at 2018-03-19 Fedora 28 blocker review meeting: https://meetbot-raw.fedoraproject.org/fedora-blocker-review/2018-03-19/f28-blocker-review.2018-03-19-16.02.html . Accepted as a blocker per criterion cited in #c1.

Comment 10 Fedora Update System 2018-03-19 23:21:14 UTC
freeipa-4.6.90.pre1-2.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-8cff0f34f6

Comment 11 Adam Williamson 2018-03-19 23:23:02 UTC
https://openqa.fedoraproject.org/tests/207752 will test this, if anyone wants to follow it live :P

Comment 12 Fedora Update System 2018-03-20 14:52:47 UTC
freeipa-4.6.90.pre1-3.fc28 has been pushed to the Fedora 28 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-8cff0f34f6

Comment 13 Adam Williamson 2018-03-20 19:11:11 UTC
Fix confirmed.

Comment 14 Fedora Update System 2018-03-21 01:07:56 UTC
freeipa-4.6.90.pre1-4.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-8cff0f34f6

Comment 15 Fedora Update System 2018-03-21 14:12:57 UTC
freeipa-4.6.90.pre1-5.fc28 has been pushed to the Fedora 28 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-8cff0f34f6

Comment 16 Fedora Update System 2018-03-21 16:24:54 UTC
freeipa-4.6.90.pre1-6.1.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-8cff0f34f6

Comment 17 Fedora Update System 2018-03-21 20:31:32 UTC
freeipa-4.6.90.pre1-6.1.fc28 has been pushed to the Fedora 28 stable repository. If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.