Bug 1088163 - kadmin is unresponsive in FreeIPA installation
Summary: kadmin is unresponsive in FreeIPA installation
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: krb5
Version: 20
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Roland Mainz
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-04-16 07:30 UTC by Martin Kosek
Modified: 2015-09-08 17:27 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-06-29 20:07:37 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Martin Kosek 2014-04-16 07:30:20 UTC
Description of problem:
After FreeIPA installation finishes, kadmin seems to be unresponsive:

{{{
# ipa-server-install --hostname ipa.mkosek-fedora20.test
...
Be sure to back up the CA certificate stored in /root/cacert.p12
This file is required to create replicas. The password for this
file is the Directory Manager password
# echo Secret123 | ipa user-add --first Foo --last=Bar fbar --password && echo -e "Secret123\nSecret123\nSecret123" | kpasswd fbar
-----------------
Added user "fbar"
-----------------
  User login: fbar
  First name: Foo
  Last name: Bar
  Full name: Foo Bar
  Display name: Foo Bar
  Initials: FB
  Home directory: /home/fbar
  GECOS: Foo Bar
  Login shell: /bin/sh
  Kerberos principal: fbar
  Email address: fbar
  UID: 273800001
  GID: 273800001
  Password: True
  Member of groups: ipausers
  Kerberos keys available: True
Password for fbar: 
Enter new password: 
Enter it again: 

^C
# KRB5_TRACE=/dev/stdout kinit fbar
[4437] 1397632503.14631: Getting initial credentials for fbar
[4437] 1397632503.17649: Sending request (182 bytes) to MKOSEK-FEDORA20.TEST
[4437] 1397632503.18182: Sending initial UDP request to dgram 10.0.0.236:88
[4437] 1397632503.20577: Received answer from dgram 10.0.0.236:88
[4437] 1397632503.20755: Response was from master KDC
[4437] 1397632503.20846: Received error from KDC: -1765328361/Password has expired
[4437] 1397632503.20930: Principal expired; getting changepw ticket
[4437] 1397632503.21017: Getting initial credentials for fbar
[4437] 1397632503.21112: Setting initial creds service to kadmin/changepw
[4437] 1397632503.21207: Sending request (170 bytes) to MKOSEK-FEDORA20.TEST (master)
[4437] 1397632503.21357: Sending initial UDP request to dgram 10.0.0.236:88
[4437] 1397632503.23748: Received answer from dgram 10.0.0.236:88
[4437] 1397632503.23845: Received error from KDC: -1765328359/Additional pre-authentication required
[4437] 1397632503.23935: Processing preauth types: 136, 19, 2, 133
[4437] 1397632503.24039: Selected etype info: etype aes256-cts, salt ":Om<'$wA^O5P-s&d", params ""
[4437] 1397632503.24131: Received cookie: MIT
Password for fbar: 
[4437] 1397632506.410881: AS key obtained for encrypted timestamp: aes256-cts/7109
[4437] 1397632506.411076: Encrypted timestamp (for 1397632506.410721): plain 301AA011180F32303134303431363037313530365AA1050203064461, encrypted FA642E2A6FAB40792FADB324C2E4294D2FB3C475B5DD3B1CBAD0507BF7CE49F892C06731AB814C5845EBCD546B420510ED48B94596DFF35B
[4437] 1397632506.411207: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success
[4437] 1397632506.411327: Produced preauth for next request: 133, 2
[4437] 1397632506.411415: Sending request (265 bytes) to MKOSEK-FEDORA20.TEST (master)
[4437] 1397632506.411710: Sending initial UDP request to dgram 10.0.0.236:88
[4437] 1397632506.471752: Received answer from dgram 10.0.0.236:88
[4437] 1397632506.471823: Processing preauth types: 19
[4437] 1397632506.471839: Selected etype info: etype aes256-cts, salt ":Om<'$wA^O5P-s&d", params ""
[4437] 1397632506.471850: Produced preauth for next request: (empty)
[4437] 1397632506.471864: AS key determined by preauth: aes256-cts/7109
[4437] 1397632506.471940: Decrypted AS reply; session key is: aes256-cts/FA55
[4437] 1397632506.471962: FAST negotiation: available
[4437] 1397632506.472006: Attempting password change; 3 tries remaining
Password expired.  You must change it now.
Enter new password: 
Enter it again: 
[4437] 1397632515.793203: Creating authenticator for fbar -> kadmin/changepw, seqnum 0, subkey aes256-cts/61BA, session key aes256-cts/FA55
[4437] 1397632515.793581: Sending initial UDP request to dgram 10.0.0.236:464
[4437] 1397632518.796812: Sending retry UDP request to dgram 10.0.0.236:464
[4437] 1397632523.802128: Sending retry UDP request to dgram 10.0.0.236:464
[4437] 1397632532.811788: Initiating TCP connection to stream 10.0.0.236:464
[4437] 1397632532.811959: Sending TCP request to stream 10.0.0.236:464
kinit: Cannot contact any KDC for requested realm while getting initial credentials
}}}

There are kadmin errors in the journalctl:
Apr 16 09:22:36 ipa.mkosek-fedora20.test systemd[1]: Stopping Kerberos 5 Password-changing and Administration...
Apr 16 09:22:36 ipa.mkosek-fedora20.test systemd[1]: kadmin.service: main process exited, code=exited, status=2/INVALIDARGUMENT
Apr 16 09:22:36 ipa.mkosek-fedora20.test systemd[1]: Unit kadmin.service entered failed state.
Apr 16 09:22:36 ipa.mkosek-fedora20.test systemd[1]: Starting Kerberos 5 Password-changing and Administration...
Apr 16 09:22:37 ipa.mkosek-fedora20.test systemd[1]: PID file /var/run/kadmind.pid not readable (yet?) after start.
Apr 16 09:22:37 ipa.mkosek-fedora20.test systemd[1]: Started Kerberos 5 Password-changing and Administration.

The error may not be related as it happens only during restart of kadmin, but it is still suspicious.

netstat shows that kadmin should indeed be listening on given port:
# netstat -putna | grep 464
tcp        2      0 0.0.0.0:464             0.0.0.0:*               LISTEN      4687/kadmind        
tcp      633      0 10.0.0.236:464        10.0.0.236:52668      CLOSE_WAIT  -                   
tcp        0      0 10.0.0.236:52668      10.0.0.236:464        FIN_WAIT2   -                   
tcp      633      0 10.0.0.236:464        10.0.0.236:52667      CLOSE_WAIT  -                   
tcp6       0      0 :::464                  :::*                    LISTEN      4687/kadmind        
udp     7680      0 0.0.0.0:464             0.0.0.0:*                           4687/kadmind        

krb5kdc log does not contain anything interesting as well:
Apr 16 09:30:57 ipa.mkosek-fedora20.test krb5kdc[4681](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 10.0.0.236: NEEDED_PREAUTH: fbar for kadmin/changepw, Additional pre-authentication required
Apr 16 09:30:57 ipa.mkosek-fedora20.test krb5kdc[4681](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 10.0.0.236: ISSUE: authtime 1397633457, etypes {rep=18 tkt=18 ses=18}, fbar for kadmin/changepw


Version-Release number of selected component (if applicable):
krb5-workstation-1.11.5-4.fc20.x86_64

How reproducible:
Always in my VM.

Steps to Reproduce:
1. Install FreeIPA on Fedora 20
2. Add a user
3. Try to change user's password with kpasswd

Actual results:
kpasswd time outs

Expected results:
kpasswd succeeds.

Additional info:

Comment 1 Martin Kosek 2014-04-16 11:56:01 UTC
I finally found the root cause - kadmin is reading from /dev/random. See strace output:

close(31)                               = 0
munmap(0x7f2a725a6000, 4096)            = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
write(3, "Apr 16 13:55:43 ipa.mkosek-fedor"..., 94) = 94
open("/dev/random", O_RDONLY)           = 31
fcntl(31, F_SETFD, FD_CLOEXEC)          = 0
fstat(31, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 8), ...}) = 0
read(31, 

<-- waiting for a really long until I increased the entropy

"\376\27\372>\227\v", 64)      = 6
read(31, "\7\34n\323\261u", 58)         = 6
read(31, "a\203\276\264J\305", 52)      = 6
read(31, "\304Y\332\177\360\23", 46)    = 6
read(31, "\304\22_yr\313", 40)          = 6
read(31, "\323\213\v\323\216c", 34)     = 6
read(31, "fD\272\250\207\332", 28)      = 6
read(31, "ux\r\223\10f", 22)            = 6
read(31, "\250\17\217\356w\33", 16)     = 6
read(31, "\217\1\327w\336\222", 10)     = 6
read(31, "\1R%\302", 4)                 = 4
close(31)                               = 0
open("/dev/urandom", O_RDONLY)          = 31
fcntl(31, F_SETFD, FD_CLOEXEC)          = 0
fstat(31, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) = 0
read(31, "'\312@B\217\234PB\252?\27x\367'A\333\345\224,\306\6Dz;_@\326:\230\2%\372"..., 64) = 64
close(31)                               = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
write(3, "Apr 16 13:56:31 ipa.mkosek-fedor"..., 71) = 71
write(2, "kadmind: starting...\n", 21kadmind: starting...
)  = 21


I assume this is something that have changed lately as I did not notice this problem before. Question is if we can even do about it.

Shouldn't for example kadmin's systemd start command return when the kadmind is really initialized and functional? I.e. when it is ready to accept password changes instead of throwing out all requests?

Comment 2 Nalin Dahyabhai 2014-04-17 13:33:10 UTC
(In reply to Martin Kosek from comment #1)
> Shouldn't for example kadmin's systemd start command return when the kadmind
> is really initialized and functional? I.e. when it is ready to accept
> password changes instead of throwing out all requests?

I believe the alternative would block system startup indefinitely in a VM if sysvinit is used, and time out fatally on systemd boxes.  That first possibility is highly undesirable.

Comment 3 Martin Kosek 2014-06-03 08:57:27 UTC
Ok. Would it make then sense to at least to follow a similar approach as in FreeIPA (https://fedorahosted.org/freeipa/ticket/4210) and at least add a log? Something like:

"Initializing some-crypto-subsystem (requires entropy)"

to give admin a hint why kadmin is not responding when he types "systemctl status kadmin.service" and tries to see what is happening?

Comment 4 Fedora Admin XMLRPC Client 2014-10-06 16:38:02 UTC
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Comment 5 Fedora End Of Life 2015-05-29 11:35:18 UTC
This message is a reminder that Fedora 20 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 20. 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 '20'.

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 20 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.

Comment 6 Fedora End Of Life 2015-06-29 20:07:37 UTC
Fedora 20 changed to end-of-life (EOL) status on 2015-06-23. Fedora 20 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.


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