Bug 1521110 - sssd-kcm: krb5_cc_cache_match on empty ccache does not work
Summary: sssd-kcm: krb5_cc_cache_match on empty ccache does not work
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: sssd
Version: 27
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Fabiano Fidêncio
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-12-05 20:13 UTC by Robbie Harwood
Modified: 2018-04-05 15:00 UTC (History)
11 users (show)

Fixed In Version: sssd-1.16.1-2.fc27 sssd-1.16.1-2.fc28 sssd-1.16.1-2.fc26
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-04-02 13:01:59 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
test.c (3.31 KB, text/plain)
2017-12-05 20:13 UTC, Robbie Harwood
no flags Details

Description Robbie Harwood 2017-12-05 20:13:29 UTC
Created attachment 1363325 [details]
test.c

Calling krb5_cc_cache_match() returns "No KCM server found" on a vanilla Fedora installation onto which I install sssd-kcm.  Please see attached reproducer.

Note that this behavior works fine with all other collection types (i.e., KEYRING and DIR); see usage instructions in attachment.  The script should run like so:

./test /tmp/ccache DIR:/tmp/sdf
Acquiring creds from: /tmp/ccache
Storing creds into: DIR:/tmp/sdf

But instead it does

./test /tmp/ccache KCM:
Acquiring creds from: /tmp/ccache
Storing creds into: KCM:
Problem with dest ccache - maybe it wasn't empty?
90: No KCM server found

Comment 1 Lukas Slebodnik 2017-12-06 17:32:22 UTC
(In reply to Robbie Harwood from comment #0)
> Created attachment 1363325 [details]
> test.c
> 
> Calling krb5_cc_cache_match() returns "No KCM server found" on a vanilla
> Fedora installation onto which I install sssd-kcm.  Please see attached
> reproducer.
> 
> Note that this behavior works fine with all other collection types (i.e.,
> KEYRING and DIR); see usage instructions in attachment.  The script should
> run like so:
> 
> ./test /tmp/ccache DIR:/tmp/sdf
> Acquiring creds from: /tmp/ccache
> Storing creds into: DIR:/tmp/sdf
> 
> But instead it does
> 
> ./test /tmp/ccache KCM:
> Acquiring creds from: /tmp/ccache
> Storing creds into: KCM:
> Problem with dest ccache - maybe it wasn't empty?
> 90: No KCM server found
      ^^^^^^^^^^^^^^^^^^^
I cannot reproduce this error.
And moreover it passed for me for 1st time

sh-4.4$ date
Wed Dec  6 18:30:00 CET 2017
sh-4.4$ 
sh-4.4$ klist -c FILE:./ccache
Ticket cache: FILE:./ccache
Default principal: lslebodn

Valid starting       Expires              Service principal
12/06/2017 18:24:09  12/07/2017 18:24:03  krbtgt/FEDORAPROJECT.ORG
        renew until 12/13/2017 18:24:03
sh-4.4$ 
sh-4.4$ klist -l
Principal name                 Cache name
--------------                 ----------
lslebodn            KCM:1000:91818
sh-4.4$ 
sh-4.4$ ./test ./ccache KCM:
Acquiring creds from: ./ccache
Storing creds into: KCM:
sh-4.4$ echo $?
0
sh-4.4$ ./test ./ccache KCM:
Acquiring creds from: ./ccache
Storing creds into: KCM:
Problem with dest ccache - maybe it wasn't empty?
sh-4.4$ echo $?
0
sh-4.4$ klist -l
Principal name                 Cache name
--------------                 ----------
lslebodn     KCM:1000:34275
lslebodn     KCM:1000:69393
lslebodn            KCM:1000:91818
sh-4.4$ klist -c KCM:1000:34275
Ticket cache: KCM:1000:34275
Default principal: lslebodn

Valid starting       Expires              Service principal
12/06/2017 18:24:09  12/07/2017 18:24:03  krbtgt/FEDORAPROJECT.ORG
        renew until 12/13/2017 18:24:03
sh-4.4$ klist -c KCM:1000:69393
Ticket cache: KCM:1000:69393
Default principal: lslebodn

Valid starting       Expires              Service principal
12/06/2017 18:24:09  12/07/2017 18:24:03  krbtgt/FEDORAPROJECT.ORG
        renew until 12/13/2017 18:24:03

Comment 2 Robbie Harwood 2017-12-06 18:51:01 UTC
(In reply to Lukas Slebodnik from comment #1)
> (In reply to Robbie Harwood from comment #0)
> > 90: No KCM server found
>       ^^^^^^^^^^^^^^^^^^^
> I cannot reproduce this error.
> And moreover it passed for me for 1st time

How do I get you more information?  What things are helpful to debug this further?

Comment 3 Robbie Harwood 2017-12-07 16:05:37 UTC
Assuming this was accidentally dropped...

Comment 4 Lukas Slebodnik 2017-12-07 18:23:56 UTC
(In reply to Robbie Harwood from comment #3)
> Assuming this was accidentally dropped...

I am not sure what is a difference in our testing.
It would be good to provide more context. I tried to provide output of klist in my case.

Did you test with empty KCM for that users? 
Were daemons running?
Which versions of sssd-kcm do you use?
Are sssd-{kcm,secrets}.sockets enbled/started?
Is there something intresting in audit.log/journald ?
Is it reproducible only on you machine?
Did you try to reproduce on minimal VM?
...

* debug logs from sssd-kcm or strace might help as well

BTW I tried to reproduce with stopped sssd-kcm.socket and I did a different error then in description of this bug.

sh$ ./test ./ccache KCM:
Acquiring creds from: ./ccache
Storing creds into: KCM:
Problem with dest ccache - maybe it wasn't empty?
90: Connection refused

Comment 5 Lukas Slebodnik 2017-12-07 18:24:40 UTC
(In reply to Robbie Harwood from comment #0)
> Created attachment 1363325 [details]
> test.c
> 
> Calling krb5_cc_cache_match() returns "No KCM server found" on a vanilla
> Fedora installation onto which I install sssd-kcm.  Please see attached
> reproducer.
> 
> Note that this behavior works fine with all other collection types (i.e.,
> KEYRING and DIR); see usage instructions in attachment.  The script should
> run like so:
> 
> ./test /tmp/ccache DIR:/tmp/sdf
> Acquiring creds from: /tmp/ccache
> Storing creds into: DIR:/tmp/sdf
> 
> But instead it does
> 
> ./test /tmp/ccache KCM:
> Acquiring creds from: /tmp/ccache
> Storing creds into: KCM:
> Problem with dest ccache - maybe it wasn't empty?
> 90: No KCM server found

Jakub,
can you see such error message?

Comment 6 Lukas Slebodnik 2018-01-08 21:59:42 UTC
Jakub,
can you reproduce previous behaviour?

Comment 7 Jakub Hrozek 2018-01-09 09:30:51 UTC
(In reply to Lukas Slebodnik from comment #6)
> Jakub,
> can you reproduce previous behaviour?

I didn't try yet and unfortunately RHEL work will prevent me from trying this week, I think.

Comment 8 Lukas Slebodnik 2018-02-09 12:55:38 UTC
(In reply to Lukas Slebodnik from comment #4)
> (In reply to Robbie Harwood from comment #3)
> > Assuming this was accidentally dropped...
> 
> I am not sure what is a difference in our testing.
> It would be good to provide more context. I tried to provide output of klist
> in my case.
> 
> Did you test with empty KCM for that users? 
> Were daemons running?
> Which versions of sssd-kcm do you use?
> Are sssd-{kcm,secrets}.sockets enbled/started?
> Is there something intresting in audit.log/journald ?
> Is it reproducible only on you machine?
> Did you try to reproduce on minimal VM?
> ...
> 
> * debug logs from sssd-kcm or strace might help as well
> 
> BTW I tried to reproduce with stopped sssd-kcm.socket and I did a different
> error then in description of this bug.
> 
> sh$ ./test ./ccache KCM:
> Acquiring creds from: ./ccache
> Storing creds into: KCM:
> Problem with dest ccache - maybe it wasn't empty?
> 90: Connection refused

Fabiano,
You started playing with KCM. Could you try to reproduce error "90: Connection refused" ?

If no then Robbie will need to provide log files from sssd-kcm

Comment 9 Fabiano Fidêncio 2018-02-09 22:53:08 UTC
Lukas, I've assigned the bug to myself and I will work on this one after my PTOs. No need to re-set the needinfo.

Comment 10 Lukas Slebodnik 2018-02-10 12:01:27 UTC
This bugzilla is still assigned to Jakub.
Did I miss something?

Comment 11 Fabiano Fidêncio 2018-02-26 14:01:46 UTC
Robbie,

I can't reproduce the issue on a fresh-installed Fedora27 VM.
I'd like to ask you whether you still have the problematic environment handy. If yes, please, do:
- Create the /etc/sssd/sssd.conf (it must be owned by root:root and has to have permissions as 600);
- Add to this file:
```
[kcm]
debug_level = 9

[secrets]
debug_level = 9
```
- systemctl restart sssd sssd-kcm sssd-secrets
- Reproduce the issue
- Attach: /var/log/sssd_{kcm,secrets}.log


Feel free to ping me on IRC if you prefer to discuss the issue there (or if you have, somehow, a machine you can give me access to to reproduce the issue).

Comment 12 Fabiano Fidêncio 2018-02-26 14:04:32 UTC
Robbie,

Another question is ... did the issue happen in a fresh Fedora27 installation or on a Fedora26 -> Fedora27 upgrade?

Comment 13 Robbie Harwood 2018-02-26 18:57:28 UTC
(In reply to Fabiano Fidêncio from comment #12)
> Robbie,
> 
> Another question is ... did the issue happen in a fresh Fedora27
> installation or on a Fedora26 -> Fedora27 upgrade?

This particular machine was originally f25, and I installed the sssd-kcm package explicitly.

After restarting sssd-kcm, I cannot reproduce the issue.  Based on this, maybe there's some problem with setting the service to auto-start?  It's listed as "active (running)" now and it wasn't before the restart.

Comment 14 Fabiano Fidêncio 2018-02-26 19:56:03 UTC
(In reply to Robbie Harwood from comment #13)
> (In reply to Fabiano Fidêncio from comment #12)
> > Robbie,
> > 
> > Another question is ... did the issue happen in a fresh Fedora27
> > installation or on a Fedora26 -> Fedora27 upgrade?
> 
> This particular machine was originally f25, and I installed the sssd-kcm
> package explicitly.
> 
> After restarting sssd-kcm, I cannot reproduce the issue.  Based on this,
> maybe there's some problem with setting the service to auto-start?  It's
> listed as "active (running)" now and it wasn't before the restart.

Thanks for the info, Robbie.

I'll try to reproduce it here and may get back to you after my tests.

Comment 15 Fabiano Fidêncio 2018-03-21 19:56:58 UTC
Robbie,

I do believe this issue may be related to one that I've found this afternoon and in case you're still able to reproduce it ... would you be wiling to give a try to a test build? If so, please, just install the test build by doing: `dnf copr enable fidencio/sssd-kcm-issues && dnf update sssd`.

In case the issue still persists, I'd like to ask you again for more up-to-date debug logs so I can keep debugging the issue.

Thanks in advance,

Comment 16 Robbie Harwood 2018-03-22 17:59:31 UTC
Works with your copr, thanks!

Comment 17 Fedora Update System 2018-03-30 14:23:35 UTC
sssd-1.16.1-2.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-94e3753451

Comment 18 Fedora Update System 2018-03-30 14:26:58 UTC
sssd-1.16.1-2.fc26 has been submitted as an update to Fedora 26. https://bodhi.fedoraproject.org/updates/FEDORA-2018-5de5bfcbe2

Comment 19 Fedora Update System 2018-03-30 14:55:22 UTC
sssd-1.16.1-2.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-495d60f679

Comment 20 Fedora Update System 2018-04-01 04:28:39 UTC
sssd-1.16.1-2.fc26 has been pushed to the Fedora 26 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-5de5bfcbe2

Comment 21 Fedora Update System 2018-04-01 04:52:26 UTC
sssd-1.16.1-2.fc27 has been pushed to the Fedora 27 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-495d60f679

Comment 22 Fedora Update System 2018-04-01 04:57:20 UTC
sssd-1.16.1-2.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-94e3753451

Comment 23 Fedora Update System 2018-04-02 13:01:59 UTC
sssd-1.16.1-2.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.

Comment 24 Fedora Update System 2018-04-05 11:46:53 UTC
sssd-1.16.1-2.fc28 has been pushed to the Fedora 28 stable repository. If problems still persist, please make note of it in this bug report.

Comment 25 Fedora Update System 2018-04-05 15:00:53 UTC
sssd-1.16.1-2.fc26 has been pushed to the Fedora 26 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.