I was unable to authenticate against the Fedora Kerberos server for the past couple days, leaving me unable to push updates to a package I maintain. (It's been a little while since one of my packages needed an update, so the last time I successfully logged in via kinit might have been on Fedora 26.) My current system setup: * Fedora 27 Workstation x86_64 * krb5-workstation 1.15.2-4 * sssd 1.16.0-5 * sssd-kcm 1.16.0-5 ↪ KRB5_TRACE=/dev/stdout kinit terrycloth [2427] 1516758561.926258: Getting initial credentials for terrycloth [2427] 1516758561.926260: Sending request (207 bytes) to FEDORAPROJECT.ORG [2427] 1516758561.926261: Resolving hostname id.fedoraproject.org [2427] 1516758567.472270: TLS certificate name matched "id.fedoraproject.org" [2427] 1516758567.472271: Sending HTTPS request to https 209.132.190.2:443 [2427] 1516758567.472272: Received answer (322 bytes) from https 209.132.190.2:443 [2427] 1516758567.472273: Terminating TCP connection to https 209.132.190.2:443 [2427] 1516758573.70353: Response was from master KDC [2427] 1516758573.70354: Received error from KDC: -1765328359/Additional pre-authentication required [2427] 1516758573.70357: Processing preauth types: 16, 15, 14, 136, 19, 147, 2, 133 [2427] 1516758573.70358: Selected etype info: etype aes256-cts, salt "n!=Z/:EV<*{FI8Vc", params "" [2427] 1516758573.70359: Received cookie: MIT Password for terrycloth: [2427] 1516758578.239608: AS key obtained for encrypted timestamp: aes256-cts/6196 [2427] 1516758578.239610: Encrypted timestamp (for 1516758572.941200): plain 301AA011180F32303138303132343031343933325AA10502030E5C90, encrypted A559067B42247DB8A49506ACE343A6D894E1966AF78BB3461DD81C121EF21A2D2B71F3AE2EB9A56943CA5AFFFEF009BCDB10F79D5ED4A615 [2427] 1516758578.239611: Preauth module encrypted_timestamp (2) (real) returned: 0/Success [2427] 1516758578.239612: Produced preauth for next request: 133, 2 [2427] 1516758578.239613: Sending request (302 bytes) to FEDORAPROJECT.ORG [2427] 1516758578.239614: Resolving hostname id.fedoraproject.org [2427] 1516758583.588603: TLS certificate name matched "id.fedoraproject.org" [2427] 1516758583.588604: Sending HTTPS request to https 209.132.190.2:443 [2427] 1516758584.39247: Received answer (795 bytes) from https 209.132.190.2:443 [2427] 1516758584.39248: Terminating TCP connection to https 209.132.190.2:443 [2427] 1516758589.107694: Response was from master KDC [2427] 1516758589.107695: Processing preauth types: 19 [2427] 1516758589.107696: Selected etype info: etype aes256-cts, salt "n!=Z/:EV<*{FI8Vc", params "" [2427] 1516758589.107697: Produced preauth for next request: (empty) [2427] 1516758589.107698: AS key determined by preauth: aes256-cts/6196 [2427] 1516758589.107699: Decrypted AS reply; session key is: aes256-cts/817F [2427] 1516758589.107700: FAST negotiation: available [2427] 1516758589.107701: Initializing KCM:1000 with default princ terrycloth <exit code 141> I can't find anything about what the kinit exit codes mean. As per tibbs's suggestion, I tried commenting out everything in /etc/krb5.conf.d/kcm_default_ccache. Before commenting, the file only contained this: [libdefaults] default_ccache_name = KCM: After commenting, kinit worked again. Possibly related: Bug #1494843 and Bug #1511275.
I am sorry for inconveniences. It would be good if you could provide log files. Add following lines to /etc/sssd/sssd.conf (if file does not exist then create new one) [kcm] debug_level = 10 debug_microseconds = true [secrets] debug_level = 10 debug_microseconds = true And execute following commands * chmod 600 /etc/sssd/sssd.conf * /usr/sbin/sssd --genconf * systemctl stop sssd-secrets and sssd-kcm * reproduce issue with "KRB5_TRACE=/dev/stderr kinit .." * and provide output of previous command + log files /var/log/sssd/sssd_secrets.log /var/log/sssd/sssd_kcm.log
I see this problem too. But running the same command (and entering the same password) a second time works: $ kinit richardfearn Password for richardfearn: $ echo $? 141 $ kinit richardfearn Password for richardfearn: $ echo $? 0 Seems pretty reproducible, so I'll try to get the logs when I do this again.
Huh, you're right, Richard. For some reason, running kinit twice in a row works.
Anyway, Lukas, sorry, I somehow missed the notification for your previous comments. I created /etc/sssd/sssd.conf with the contents you showed. I assumed I also should have uncommented the lines in /etc/krb5.conf.d/kcm_default_ccache, so I did that too. Here's the command output: ↪ KRB5_TRACE=/dev/stderr kinit terrycloth [4883] 1518581736.351548: Getting initial credentials for terrycloth [4883] 1518581736.351550: Sending request (207 bytes) to FEDORAPROJECT.ORG [4883] 1518581736.351551: Resolving hostname id.fedoraproject.org [4883] 1518581736.351552: TLS certificate name matched "id.fedoraproject.org" [4883] 1518581736.351553: Sending HTTPS request to https 140.211.169.206:443 [4883] 1518581737.95572: Received answer (322 bytes) from https 140.211.169.206:443 [4883] 1518581737.95573: Terminating TCP connection to https 140.211.169.206:443 [4883] 1518581737.95574: Response was from master KDC [4883] 1518581737.95575: Received error from KDC: -1765328359/Additional pre-authentication required [4883] 1518581737.95578: Processing preauth types: 16, 15, 14, 136, 19, 147, 2, 133 [4883] 1518581737.95579: Selected etype info: etype aes256-cts, salt "n!=Z/:EV<*{FI8Vc", params "" [4883] 1518581737.95580: Received cookie: MIT Password for terrycloth: [4883] 1518581758.176471: AS key obtained for encrypted timestamp: aes256-cts/6196 [4883] 1518581758.176473: Encrypted timestamp (for 1518581758.134266): plain 301AA011180F32303138303231343034313535385AA1050203020C7A, encrypted 55485BF2C8A59823FC0D09ED40CBE88C8DC4D7988BEE7DFE198481F70531E99ED27369694266781832D4660E74C9F71FA0D31B1E760CF010 [4883] 1518581758.176474: Preauth module encrypted_timestamp (2) (real) returned: 0/Success [4883] 1518581758.176475: Produced preauth for next request: 133, 2 [4883] 1518581758.176476: Sending request (302 bytes) to FEDORAPROJECT.ORG [4883] 1518581758.176477: Resolving hostname id.fedoraproject.org [4883] 1518581758.176478: TLS certificate name matched "id.fedoraproject.org" [4883] 1518581758.176479: Sending HTTPS request to https 209.132.181.16:443 [4883] 1518581758.176480: Received answer (795 bytes) from https 209.132.181.16:443 [4883] 1518581758.176481: Terminating TCP connection to https 209.132.181.16:443 [4883] 1518581758.176482: Response was from master KDC [4883] 1518581758.176483: Processing preauth types: 19 [4883] 1518581758.176484: Selected etype info: etype aes256-cts, salt "n!=Z/:EV<*{FI8Vc", params "" [4883] 1518581758.176485: Produced preauth for next request: (empty) [4883] 1518581758.176486: AS key determined by preauth: aes256-cts/6196 [4883] 1518581758.176487: Decrypted AS reply; session key is: aes256-cts/1853 [4883] 1518581758.176488: FAST negotiation: available [4883] 1518581758.176489: Initializing KCM:1000 with default princ terrycloth
Created attachment 1395749 [details] /var/log/sssd/sssd_kcm.log
Created attachment 1395750 [details] /var/log/sssd/sssd_secrets.log
Do you need any other information from me?
Andrew, 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,
(Sorry, it's been a busy week.) Even without enabling your Copr yet, I'm not able to reproduce the bug anymore. Maybe it was already fixed with the release of krb5-workstation-1.15.2-7.fc27.x86_64 ? Funny though, dnf history shows that I'd apparently installed that update back on February 21, and just hadn't tested again. But yeah, with KCM credential cache enabled in /etc/krb5.conf.d/kcm_default_ccache again, kinit runs without error now.
I think it may have been fixed too. I've been quite careful about running kinit over the past few weeks - also running kdestroy beforehand, to ensure kinit actually does something. But I haven't seen kinit fail for several weeks.
(In reply to Andrew Toskin from comment #9) > Maybe it was already fixed with the release of > krb5-workstation-1.15.2-7.fc27.x86_64 ? Very unlikely - that's a change specific to the LDAP KDC backend.
(In reply to Andrew Toskin from comment #9) > (Sorry, it's been a busy week.) > > Even without enabling your Copr yet, I'm not able to reproduce the bug > anymore. (In reply to Richard Fearn from comment #10) > I think it may have been fixed too. > > I've been quite careful about running kinit over the past few weeks - also > running kdestroy beforehand, to ensure kinit actually does something. But I > haven't seen kinit fail for several weeks. Then possible explanation is that you hit issue with occasional wrong SELinux context for /var/run/.heim_org.h5l.kcm-socket. We were not able to reproduce it but it is already fixed since Tue Feb 20 2018 (selinux-policy-targeted-3.13.1-283.26) BZ1538210
Oh, derp, yesterday I didn't logout or reboot after uncommenting the lines in /etc/krb5.conf.d/kcm_default_ccache. But I'm getting exit code 141 from kinit again today. Okay, so then I did this: ## Uncomment kcm_default_ccache ↪ sudo dnf copr enable fidencio/sssd-kcm-issues ↪ sudo dnf upgrade -y --refresh ## Reboot again to make sure. ↪ kinit "terrycloth" Password for terrycloth: <exit status ok>
...Actually, I have no idea what's happening now. I wanted to dDisabling the "fidencio/sssd-kcm-issues" Copr is what fixed the issue. So I disabled the Copr, ran `dnf distro-sync` to downgrade back to the versions in the main Fedora repos, and rebooted again. But kinit *still* succeeds.
I wanted to confirm that disabling the Copr ... **
... Just noticed kinit failing again when "default_ccache_name = KCM:" in /etc/krb5.conf.d/kcm_default_ccache ...
(In reply to Andrew Toskin from comment #16) > ... Just noticed kinit failing again when "default_ccache_name = KCM:" in > /etc/krb5.conf.d/kcm_default_ccache ... Would you mind uploading new KCM and secrets logs with the copr enabled?
Aaaand today it's working again. Sorry, I'm as confused as anyone. I assume a stack trace won't tell you anything meaningful while it's working, so I'll keep trying kinit over the next few days to see if I can duplicate the error again.
I've run kinit every day this past week without any error. So maybe the problem has been fixed after all? I'll reopen this thread if I ever run into the same issue again.
Not for me; after enabling KCM cache: % KRB5_TRACE=/dev/stdout kinit kinit: Matching credential not found while getting default ccache % rpm -q sssd sssd-1.16.1-2.fc27.x86_64
Although I don't see the log files I provided before in *this* bugreport. I'm just CC here, this may be other problem than mine.
Created attachment 1486132 [details] trace messages from two runs of kinit I have a problem that looks very similar to this bug report: With sssd-kcm installed kinit fails with exit code 141, but a second attempt succeeds. The problem does not occur on another computer where sssd-kcm is not installed. My setup: [root@tag ~]# rpm -q --file `which kinit` krb5-workstation-1.15.2-9.fc27.x86_64 [root@tag ~]# rpm -q sssd-kcm sssd-kcm-1.16.3-2.fc27.x86_64 [root@tag ~]# cat /etc/sssd/sssd.conf [kcm] debug_level = 10
Created attachment 1486133 [details] sssd_kcm.log
Created attachment 1486134 [details] relevant excerpt from the system log
I'm sorry there are still issues around KCM. But I must admit I don't see anything out of ordinary in the log files. Would it be possible to get another set of logs, but this time paired with strace of kinit? Something like this: truncate /var/log/sssd/* date; strace -s 1024 kinit $principal; date then send the contents of /var/log/sssd/* and the strace output. This would show the exact communication. WARNING: the full strace would also log your Kerberos password as kinit reads it from you. Please do not attach the full strace here. I'm only interested in the readv() and writev() calls between kinit and the KCM deamon. This should in theory work: strace -e trace=readv,writev -s 1024 kinit but for some reason the readv call never gets traced on my test system. I don't know why exactly, but you can also just grep the full strace for readv and writev. You can also send the strace to me directly if you prefer over attaching it to a public bugzilla.
Created attachment 1486380 [details] 2: strace excerpt I get no readv at all from strace. There are plenty of reads, but no readv. In this file I have extracted all occurrences of writev and everything else I could find that touched the same file descriptors. I have also made a new discovery: kinit usually succeeds if I paste my passphrase in very quickly. If I wait a few seconds, then it fails. Is KCM too impatient and closes the socket while kinit is working? In the KCM log I see "Terminating idle client" before kinit gets the "broken pipe" signal.
Created attachment 1486381 [details] 2: sssd_kcm.log
Created attachment 1486382 [details] 2: sssd_secrets.log
(In reply to Björn Persson from comment #26) > Created attachment 1486380 [details] > 2: strace excerpt > > I get no readv at all from strace. There are plenty of reads, but no readv. > In this file I have extracted all occurrences of writev and everything else > I could find that touched the same file descriptors. > > I have also made a new discovery: kinit usually succeeds if I paste my > passphrase in very quickly. If I wait a few seconds, then it fails. Is KCM > too impatient and closes the socket while kinit is working? In the KCM log I > see "Terminating idle client" before kinit gets the "broken pipe" signal. Ah, good catch, that's probably it. The strace doesn't show timestamps (sorry, I should have asked for them), but according to the kcm server logs the request begins at: (Mon Sep 24 12:01:47:641117 2018) [sssd[kcm]] [get_client_cred] (0x4000): Client creds: euid[1000] egid[1000] pid[23500]. (Mon Sep 24 12:01:47:641145 2018) [sssd[kcm]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x559740709e40][15] (this also corresponds with the date you recorded) The operation finishes quite quickly: (Mon Sep 24 12:01:47:644618 2018) [sssd[kcm]] [kcm_output_construct] (0x1000): Sending a reply with 47 bytes of payload and then there's nothing except checking if the timer already passed and eventually terminating the client: (Mon Sep 24 12:01:52:646926 2018) [sssd[kcm]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x559740709e40][15] (Mon Sep 24 12:01:57:648000 2018) [sssd[kcm]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x559740709e40][15] (Mon Sep 24 12:02:02:652416 2018) [sssd[kcm]] [client_idle_handler] (0x2000): Terminating idle client [0x559740709e40][15] (Mon Sep 24 12:02:02:652483 2018) [sssd[kcm]] [client_close_fn] (0x2000): Terminated client [0x559740709e40][15] But I'm baffled that the client timeout is so short for you. The default, per the code is 60 seconds. and that's also how long it takes in my local testing to drop the connection. For you, the client is terminated much faster.. Do you have any modifications about "client_idle_timeout" in your sssd.conf ?
Ah, no, there is a Fedora patch that causes this: 0503-Disable-stopping-idle-socket-activated-responders.patch From 232305dd10b81955a3ee9dfc6d56c2d76ad5706f Mon Sep 17 00:00:00 2001 From: Lukas Slebodnik <lslebodn> Date: Fri, 3 Nov 2017 16:18:14 +0100 Subject: [PATCH] Disable stopping idle socket activated responders --- src/confdb/confdb.h | 2 +- src/man/sssd.conf.5.xml | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/confdb/confdb.h b/src/confdb/confdb.h index 1471949623e9dd7a8536e3ac3048a10227a5d857..e30e77bf50b7312b3f660241c92a1b3c03e88259 100644 --- a/src/confdb/confdb.h +++ b/src/confdb/confdb.h @@ -85,7 +85,7 @@ /* Responders */ #define CONFDB_RESPONDER_GET_DOMAINS_TIMEOUT "get_domains_timeout" #define CONFDB_RESPONDER_CLI_IDLE_TIMEOUT "client_idle_timeout" -#define CONFDB_RESPONDER_CLI_IDLE_DEFAULT_TIMEOUT 60 +#define CONFDB_RESPONDER_CLI_IDLE_DEFAULT_TIMEOUT 0 #define CONFDB_RESPONDER_LOCAL_NEG_TIMEOUT "local_negative_timeout" #define CONFDB_RESPONDER_IDLE_TIMEOUT "responder_idle_timeout" #define CONFDB_RESPONDER_IDLE_DEFAULT_TIMEOUT 300 diff --git a/src/man/sssd.conf.5.xml b/src/man/sssd.conf.5.xml index 6be3cd47463ec054276a0b6b2be7ec03eef1f0be..d362ba71cfbeb6271fc87abd9743ca7a77f9f3ec 100644 --- a/src/man/sssd.conf.5.xml +++ b/src/man/sssd.conf.5.xml @@ -706,7 +706,7 @@ or dbus activated. </para> <para> - Default: 300 + Default: 0 </para> </listitem> </varlistentry> -- 2.14.3 Lukas, do you remember why you added this patch? What the patch causes is that the idle timeout for clients (kinit in this case) is set to 10 (anything below 10 is set to 10) and then KCM closes the connection to kinit unless the user types in the password in 10 seconds.
btw Bjorn - there should be a workaround for you in setting responder_idle_timeout to some value. The upstream default is 60.
(In reply to Jakub Hrozek from comment #30) > Ah, no, there is a Fedora patch that causes this: > > 0503-Disable-stopping-idle-socket-activated-responders.patch > From 232305dd10b81955a3ee9dfc6d56c2d76ad5706f Mon Sep 17 00:00:00 2001 > From: Lukas Slebodnik <lslebodn> > Date: Fri, 3 Nov 2017 16:18:14 +0100 > Subject: [PATCH] Disable stopping idle socket activated responders > > --- > src/confdb/confdb.h | 2 +- > src/man/sssd.conf.5.xml | 2 +- > 2 files changed, 2 insertions(+), 2 deletions(-) > > diff --git a/src/confdb/confdb.h b/src/confdb/confdb.h > index > 1471949623e9dd7a8536e3ac3048a10227a5d857.. > e30e77bf50b7312b3f660241c92a1b3c03e88259 100644 > --- a/src/confdb/confdb.h > +++ b/src/confdb/confdb.h > @@ -85,7 +85,7 @@ > /* Responders */ > #define CONFDB_RESPONDER_GET_DOMAINS_TIMEOUT "get_domains_timeout" > #define CONFDB_RESPONDER_CLI_IDLE_TIMEOUT "client_idle_timeout" > -#define CONFDB_RESPONDER_CLI_IDLE_DEFAULT_TIMEOUT 60 > +#define CONFDB_RESPONDER_CLI_IDLE_DEFAULT_TIMEOUT 0 > #define CONFDB_RESPONDER_LOCAL_NEG_TIMEOUT "local_negative_timeout" > #define CONFDB_RESPONDER_IDLE_TIMEOUT "responder_idle_timeout" > #define CONFDB_RESPONDER_IDLE_DEFAULT_TIMEOUT 300 > diff --git a/src/man/sssd.conf.5.xml b/src/man/sssd.conf.5.xml > index > 6be3cd47463ec054276a0b6b2be7ec03eef1f0be.. > d362ba71cfbeb6271fc87abd9743ca7a77f9f3ec 100644 > --- a/src/man/sssd.conf.5.xml > +++ b/src/man/sssd.conf.5.xml > @@ -706,7 +706,7 @@ > or dbus activated. > </para> > <para> > - Default: 300 > + Default: 0 > </para> > </listitem> > </varlistentry> > -- > 2.14.3 > Hmm, It seems I mixed two things. I changed man page for responder_idle_timeout but constant was changed for client_idle_timeout. That patch was planned as a workaround for https://pagure.io/SSSD/sssd/issue/3633 So, yes that patch should be removed. Because 1.16.2 contains fix for upstream#3633 > Lukas, do you remember why you added this patch? What the patch causes is > that the idle timeout for clients (kinit in this case) is set to 10 > (anything below 10 is set to 10) and then KCM closes the connection to kinit > unless the user types in the password in 10 seconds. That will partially help. But somebody can wait 60, 120 seconds and will hit the same issue. So maybe some changes will need to be done also in krb5-client code.
(In reply to Jakub Hrozek from comment #31) > btw Bjorn - there should be a workaround for you in setting > responder_idle_timeout to some value. The upstream default is 60. Workaround is to increase client_idle_timeout in [kcm] section.
(In reply to Lukas Slebodnik from comment #33) > (In reply to Jakub Hrozek from comment #31) > > btw Bjorn - there should be a workaround for you in setting > > responder_idle_timeout to some value. The upstream default is 60. > > Workaround is to increase client_idle_timeout in [kcm] section. btw this is what I get for looking at the change in the manpage diff because I didn't know what does CONFDB_RESPONDER_CLI_IDLE_DEFAULT_TIMEOUT stand for..
(In reply to Lukas Slebodnik from comment #32) > But somebody can wait 60, 120 seconds and will hit > the same issue. So maybe some changes will need to be done also in > krb5-client code. If the protocol allows KCM to drop the connection, then it seems to me that clients must be capable of reconnecting as needed. That's how it's normally done in all kinds of protocols where a connection is used for more than a single quick transaction.
This message is a reminder that Fedora 29 is nearing its end of life. Fedora will stop maintaining and issuing updates for Fedora 29 on 2019-11-26. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a Fedora 'version' of '29'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 29 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
Fedora 29 changed to end-of-life (EOL) status on 2019-11-26. Fedora 29 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. If you experience problems, please add a comment to this bug. Thank you for reporting this bug and we are sorry it could not be fixed.