Bug 1622760

Summary: Console login as FreeIPA domain user fails in current Fedora Rawhide / 29
Product: [Fedora] Fedora Reporter: Adam Williamson <awilliam>
Component: sssdAssignee: Jakub Hrozek <jhrozek>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: unspecified    
Version: 29CC: abokovoy, awilliam, gmarr, ipa-maint, jcholast, jhrozek, kevin, lslebodn, mboddu, mikevo, mpitt, mzidek, patdung100+redhat, pbrezina, pvoborni, rcritten, rharwood, robatino, sbose, ssorce
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard: AcceptedBlocker
Fixed In Version: sssd-2.0.0-3.fc29 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-09-02 02:59:45 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1517011    
Attachments:
Description Flags
tarball of /var/log from the server
none
tarball of /var/log from the client none

Description Adam Williamson 2018-08-28 00:49:27 UTC
In current Fedora Rawhide / 29 openQA tests, all attempts to log in to a console on a system enrolled in the FreeIPA domain fail with a 'Login incorrect' error. kinit and logging into the web UI appear to work OK.

In the simplest test scenario, the server test instance deploys itself as a server (with ipa-server-install), adds a user account called 'test1', adds an HBAC rule allowing test1 to log in to any system, and sets a permanent password for test1 by kiniting as that user and entering a new password when prompted. The client test instance then enrols into the domain using 'realm join' and the domain admin credentials, tests a few other things, then tries to log into a VT as test1, with the correct password; this should be allowed, but is denied.

I will attach logs from both the server and the client. There are several errors logged, but I'm not sure what the fatal problem is yet, so just reporting against freeipa for now.

This seems a clear Beta blocker, per Basic criteria: https://fedoraproject.org/wiki/Basic_Release_Criteria#Remote_authentication - "...the system must respect the identity, authentication and access control configuration provided by the domain."

Comment 1 Adam Williamson 2018-08-28 00:51:22 UTC
Created attachment 1479106 [details]
tarball of /var/log from the server

Comment 2 Adam Williamson 2018-08-28 00:52:14 UTC
Created attachment 1479107 [details]
tarball of /var/log from the client

Comment 3 Adam Williamson 2018-08-28 00:57:30 UTC
per the openQA logs, the failed attempt at a console login occurs at 2018-08-27T18:04:20.0843 UTC. That's 14:04:20 "local time" for the logs that log in local time. Also note these tests have failed in the 20180827.n.0 Rawhide compose, which already has 389-ds-base 1.4.0.16, so this probably isn't the same cause as https://bugzilla.redhat.com/show_bug.cgi?id=1620315 .

Comment 4 Alexander Bokovoy 2018-08-28 05:25:33 UTC
Comment on attachment 1479107 [details]
tarball of /var/log from the client

This looks like an SSSD issue within KCM.

in krb5_child.log we see

(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [main] (0x0400): krb5_child started.
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [unpack_buffer] (0x0100): cmd [241] uid [1721800001] gid [1721800001] validate [true] enterprise principal [false] offline [false] UPN [test1]
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [unpack_buffer] (0x0100): ccname: [KCM:] old_ccname: [KCM:] keytab: [/etc/krb5.keytab]
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [switch_creds] (0x0200): Switch user to [1721800001][1721800001].
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [switch_creds] (0x0200): Switch user to [0][0].
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/client003.domain.local]
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid.
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [become_user] (0x0200): Trying to become user [1721800001][1721800001].
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [main] (0x0400): Will perform online auth
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [DOMAIN.LOCAL]
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [validate_tgt] (0x0400): TGT verified using key for [host/client003.domain.local].
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [create_ccache] (0x0020): 1007: [-1765328188][Internal credentials cache error]
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [map_krb5_error] (0x0020): 1808: [-1765328188][Internal credentials cache error]
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [k5c_send_data] (0x0200): Received error code 1432158209
(Mon Aug 27 14:04:20 2018) [[sssd[krb5_child[24055]]]] [main] (0x0400): krb5_child completed successfully

So create_ccache reports 'Internal credentials cache error' -- this is KCM: ccache collection on Rawhide which is provided by the SSSD itself. Unfortunately, sssd_kcm.log is empty.

Comment 5 Alexander Bokovoy 2018-08-28 05:26:01 UTC
Jakub, could you please have a look?

Comment 6 Adam Williamson 2018-08-28 06:39:28 UTC
The test currently does 'sss_debuglevel 6' to make sssd log more verbosely; let me know if there's anything else I can do to get more logs that would help.

Comment 7 Jakub Hrozek 2018-08-28 10:48:47 UTC
Unfortunately sss_debuglevel currently doesn't work with sssd-kcm because sss_debuglevel relies on sssd starting all the services, but sssd-kcm is socket-activated.

Is it possible to re-run the test with debug_level=10 in the [kcm] section of sssd.conf?

Comment 8 Jakub Hrozek 2018-08-28 12:46:33 UTC
(In reply to Jakub Hrozek from comment #7)
> Unfortunately sss_debuglevel currently doesn't work with sssd-kcm because
> sss_debuglevel relies on sssd starting all the services, but sssd-kcm is
> socket-activated.
> 
> Is it possible to re-run the test with debug_level=10 in the [kcm] section
> of sssd.conf?

Nevermind, I reproduced the bug. Can you test a scratch build for me, please?

Comment 9 Jakub Hrozek 2018-08-28 13:58:44 UTC
Here is a COPR repo:
https://copr.fedorainfracloud.org/coprs/jhrozek/sssd-kcmfail/

Comment 10 Adam Williamson 2018-08-28 19:33:50 UTC
Roger, will do. Thanks!

Comment 11 Adam Williamson 2018-08-28 22:27:56 UTC
That looks like it works.

Comment 12 Fedora Update System 2018-08-29 16:11:06 UTC
sssd-2.0.0-3.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2018-294230d586

Comment 13 Fedora Update System 2018-08-29 19:08:59 UTC
sssd-2.0.0-3.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2018-294230d586

Comment 14 Kevin Fenzi 2018-08-29 23:13:00 UTC
+1 blocker

Comment 15 Fedora Update System 2018-08-29 23:15:02 UTC
sssd-2.0.0-3.fc29 has been pushed to the Fedora 29 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-294230d586

Comment 16 Mohan Boddu 2018-08-30 13:27:29 UTC
+1 Blocker

Comment 17 Geoffrey Marr 2018-08-30 14:48:12 UTC
Voted as a blocker in-bug:

The decision to classify this bug as an "AcceptedBlocker" (Beta) was made as it violates the following criteria:

"...the system must respect the identity, authentication and access control configuration provided by the domain."

Comment 18 Fedora Update System 2018-09-02 02:59:45 UTC
sssd-2.0.0-3.fc29 has been pushed to the Fedora 29 stable repository. If problems still persist, please make note of it in this bug report.

Comment 19 Michael Voetter 2018-12-28 13:55:53 UTC
Hey all,

I think it's still/again broken for 
sssd-2.0.0-5.fc29.x86_64
sssd-kcm-2.0.0-5.fc29.x86_64
on Fedora release 29.
 
Further, I'd like to not that I have the same problem for GDM logins of FreeIPA users as well.

If I login to the root account and then use
su <freeipa-user>

followed by
kinit

to fill the ticket cache it is afterwards possible to login with the freeipa-user.

When I again destroy the ticket cache with
kdestroy

it isn't possible anymore.

Greetings,
Mike

Comment 20 Adam Williamson 2018-12-28 17:15:10 UTC
Hum, I doubt it's *this* bug, but it does indeed appear that FreeIPA is busted in F29 at present; if you look at the openQA update test history:

https://openqa.fedoraproject.org/group_overview/2?limit_builds=100

it seems to have been failing since FEDORA-2018-7db7ccda4d , which was a krb5 update and so a possible suspect as the cause...but it seems to have failed on other updates before that update was pushed stable, so the cause may in fact be something else.

I wish someone hadn't broken this over the shutdown :( I and the whole FreeIPA team (AFAIK) are supposed to be off work until Jan 2, but I guess I'll try and round up some folks to try and figure this out.

Comment 21 Adam Williamson 2018-12-28 18:10:43 UTC
OK, so, looking into it more closely, it does seem like that update (and its partner for F28) are the problem. In that build, -22, as well as adding a patch for the security bug that's mentioned in the changelog, rharwood re-enabled a patch that I had *disabled* in -21 because it was causing FreeIPA to break completely. It seems that patch *still* causes FreeIPA to break completely. So I'm sending out a -23 with the patch disabled again. Please check it out and see if it helps.

https://bodhi.fedoraproject.org/updates/FEDORA-2018-dc944aaa79

Comment 22 Michael Voetter 2018-12-29 09:15:16 UTC
Updating to the krb5 -23 packages that you've pushed to testing resolved my issue. 
Thanks!

dnf --enablerepo=updates-testing update krb5-workstation

Packages Altered:
    Upgrade  krb5-devel-1.16.1-23.fc29.x86_64       @updates-testing
    Upgraded krb5-devel-1.16.1-22.fc29.x86_64       @@System
    Upgrade  krb5-libs-1.16.1-23.fc29.i686          @updates-testing
    Upgraded krb5-libs-1.16.1-22.fc29.i686          @@System
    Upgrade  krb5-libs-1.16.1-23.fc29.x86_64        @updates-testing
    Upgraded krb5-libs-1.16.1-22.fc29.x86_64        @@System
    Upgrade  krb5-workstation-1.16.1-23.fc29.x86_64 @updates-testing
    Upgraded krb5-workstation-1.16.1-22.fc29.x86_64 @@System
    Upgrade  libkadm5-1.16.1-23.fc29.x86_64         @updates-testing
    Upgraded libkadm5-1.16.1-22.fc29.x86_64         @@System

Comment 23 Adam Williamson 2018-12-29 18:48:14 UTC
Great, thanks for the confirmation.

Comment 24 Alexander Bokovoy 2018-12-29 21:31:20 UTC
*** Bug 1662175 has been marked as a duplicate of this bug. ***

Comment 25 Martin Pitt 2019-01-04 06:48:37 UTC
*** Bug 1663112 has been marked as a duplicate of this bug. ***