Kerberos GSSAPI negotiation suddenly stops working

Openfire Openfire Dev
1

Hello,

Our small openfire server had kerberos GSSAPI negotiation working without problems for few months, but suddenly two days ago it stopped working - it asks for password even with a valid kerberos ticket. There was no change of configuration of any kind. Any idea? This is Openfire 3.4.5, so it may be also an old bug, but I did not found anything in issue tracker.

Thank you,

Config name: /etc/krb5.conf
Debug is true storeKey true useTicketCache false useKeyTab true doNotPrompt true ticketCache is null isInitiator true KeyTab is /etc/krb5.keytab refreshKrb5Config is false principal is xmpp/chat.corp.mycompany.com tryFirstPass is false useFirstPass is false storePass is false clearPass is false

KeyTabInputStream, readName(): mycompany.com
KeyTabInputStream, readName(): host
KeyTabInputStream, readName(): chat.corp.mycompany.com
KeyTab: load() entry length: 63; type: 1
KeyTabInputStream, readName(): mycompany.com
KeyTabInputStream, readName(): host
KeyTabInputStream, readName(): chat.corp.mycompany.com
KeyTab: load() entry length: 79; type: 6
KeyTabInputStream, readName(): mycompany.com
KeyTabInputStream, readName(): xmpp
KeyTabInputStream, readName(): chat.corp.mycompany.com
KeyTab: load() entry length: 63; type: 1
KeyTabInputStream, readName(): mycompany.com
KeyTabInputStream, readName(): xmpp
KeyTabInputStream, readName(): chat.corp.mycompany.com
KeyTab: load() entry length: 79; type: 6
Found unsupported keytype (6) for xmpp/chat.corp.mycompany.com@mycompany.com
Added key: 1version: 3
Ordering keys wrt default_tkt_enctypes list
Using builtin default etypes for default_tkt_enctypes
default etypes for default_tkt_enctypes: 3 1 23 16 17.
principal’s key obtained from the keytab
Acquire TGT using AS Exchange
Using builtin default etypes for default_tkt_enctypes
default etypes for default_tkt_enctypes: 3 1 23 16 17.
KrbAsReq calling createMessage
KrbAsReq in createMessage
KrbKdcReq send: kdc=kerberos.corp.mycompany.com UDP:88, timeout=30000, number of retries =3, #bytes=156
KDCCommunication: kdc=kerberos.corp.mycompany.com UDP:88, timeout=30000,Attempt =1, #bytes=156
KrbKdcReq send: #bytes read=561
KrbKdcReq send: #bytes read=561
EType: sun.security.krb5.internal.crypto.DesCbcMd5EType
KrbAsRep cons in KrbAsReq.getReply xmpp/chat.corp.mycompany.com
principal is xmpp/chat.corp.mycompany.com@mycompany.com
EncryptionKey: keyType=1 keyBytes (hex dump)=0000: 07 B6 38 AB 76 0E AB E6
Added server’s keyKerberos Principal xmpp/chat.corp.mycompany.com@mycompany.comKey Version 3key EncryptionKey: keyType=1 keyBytes (hex dump)=
0000: 07 B6 38 AB 76 0E AB E6

            [Krb5LoginModule] added Krb5Principal  xmpp/chat.corp.mycompany.com@mycompany.com to Subject

Commit Succeeded

Found key for xmpp/chat.corp.mycompany.com@mycompany.com(1)
Entered Krb5Context.acceptSecContext with state=STATE_NEW

EType: sun.security.krb5.internal.crypto.DesCbcCrcEType
crc32: d6aebca9
crc32: 11010110101011101011110010101001
Using builtin default etypes for permitted_enctypes
default etypes for permitted_enctypes: 3 1 23 16 17.
EType: sun.security.krb5.internal.crypto.DesCbcCrcEType
crc32: 456381ad
crc32: 1000101011000111000000110101101
Config reset default kdc mycompany.com
replay cache for mcepl@mycompany.com is null.
object 0: 1233444450865/865804
object 0: 1233444450865/865804
KrbApReq: authenticate succeed.
Krb5Context setting peerSeqNumber to: 587121143
EType: sun.security.krb5.internal.crypto.DesCbcCrcEType
crc32: 2721508e
crc32: 100111001000010101000010001110
Krb5Context setting mySeqNumber to: 322025892
Krb5Context.wrap: data=[01 01 00 00 ]
Krb5Context.wrap: token=[60 33 06 09 2a 86 48 86 f7 12 01 02 02 02 01 00 00 ff ff ff ff 10 49 5c 97 8d 59 c5 24 69 71 e9 e2 13 e7 77 91 ad 01 22 f9 6a 3f 25 0f 01 01 00 00 04 04 04 04 ]
Krb5Context.unwrap: token=[60 43 06 09 2a 86 48 86 f7 12 01 02 02 02 01 00 00 ff ff ff ff 5a e8 8d 1d 09 1a 25 28 13 cc 2c ae 7d fb 9c 4d 37 c0 d2 3c 04 98 9c 29 01 01 00 00 6d 63 65 70 6c 40 52 45 44 48 41 54 2e 43 4f 4d 00 03 03 03 ]
Krb5Context.unwrap: data=[01 01 00 00 6d 63 65 70 6c 40 52 45 44 48 41 54 2e 43 4f 4d 00 ]
Debug is true storeKey true useTicketCache false useKeyTab true doNotPrompt true ticketCache is null isInitiator true KeyTab is /etc/krb5.keytab refreshKrb5Config is false principal is xmpp/chat.corp.mycompany.com tryFirstPass is false useFirstPass is false storePass is false clearPass is false
KeyTab instance already exists
Found unsupported keytype (6) for xmpp/chat.corp.mycompany.com@mycompany.com
Added key: 1version: 3
Ordering keys wrt default_tkt_enctypes list
Using builtin default etypes for default_tkt_enctypes
default etypes for default_tkt_enctypes: 3 1 23 16 17.
principal’s key obtained from the keytab
Acquire TGT using AS Exchange
Using builtin default etypes for default_tkt_enctypes
default etypes for default_tkt_enctypes: 3 1 23 16 17.
KrbAsReq calling createMessage
KrbAsReq in createMessage
KrbKdcReq send: kdc=kerberos.corp.mycompany.com UDP:88, timeout=30000, number of retries =3, #bytes=156
KDCCommunication: kdc=kerberos.corp.mycompany.com UDP:88, timeout=30000,Attempt =1, #bytes=156
KrbKdcReq send: #bytes read=561
KrbKdcReq send: #bytes read=561
EType: sun.security.krb5.internal.crypto.DesCbcMd5EType
KrbAsRep cons in KrbAsReq.getReply xmpp/chat.corp.mycompany.com
principal is xmpp/chat.corp.mycompany.com@mycompany.com
EncryptionKey: keyType=1 keyBytes (hex dump)=0000: 07 B6 38 AB 76 0E AB E6
Added server’s keyKerberos Principal xmpp/chat.corp.mycompany.com@mycompany.comKey Version 3key EncryptionKey: keyType=1 keyBytes (hex dump)=
0000: 07 B6 38 AB 76 0E AB E6

            [Krb5LoginModule] added Krb5Principal  xmpp/chat.corp.mycompany.com@mycompany.com to Subject

Commit Succeeded

Found key for xmpp/chat.corp.mycompany.com@mycompany.com(1)
Entered Krb5Context.acceptSecContext with state=STATE_NEW

EType: sun.security.krb5.internal.crypto.DesCbcCrcEType
crc32: d771a2e6
crc32: 11010111011100011010001011100110
Using builtin default etypes for permitted_enctypes
default etypes for permitted_enctypes: 3 1 23 16 17.
EType: sun.security.krb5.internal.crypto.DesCbcCrcEType
crc32: ffd878d9
crc32: 11111111110110000111100011011001
Config reset default kdc mycompany.com
replay cache for ebrown@mycompany.com is null.
object 0: 1233460438509/509323
object 0: 1233460438509/509323
KrbApReq: authenticate succeed.
Krb5Context setting peerSeqNumber to: 186531375
EType: sun.security.krb5.internal.crypto.DesCbcCrcEType
crc32: 4ec035ff
crc32: 1001110110000000011010111111111
Krb5Context setting mySeqNumber to: 901848883
Krb5Context.wrap: data=[01 01 00 00 ]
Krb5Context.wrap: token=[60 33 06 09 2a 86 48 86 f7 12 01 02 02 02 01 00 00 ff ff ff ff 45 81 0c 2f 04 23 25 23 7d 26 7d 81 49 a2 6c 12 3a e2 3b 73 0d e8 6a db 01 01 00 00 04 04 04 04 ]
Krb5Context.unwrap: token=[60 33 06 09 2a 86 48 86 f7 12 01 02 02 02 01 00 00 ff ff ff ff e0 e2 be 3a f8 60 1a 9a 75 30 26 bb c5 55 ba 43 94 5a 94 cd fd 1b f2 2b 01 00 00 00 04 04 04 04 ]
Krb5Context.unwrap: data=[01 00 00 00 ]

2

A few things that are hard to tell from your info: What type of Kerberos are you using (MIT? AD?) Did you verify that all principals involved have not expired (both server entities and clients). Is there clock skew between client, server, and KDC? I dont really see anything from the kerberos debug log that indicates failure (in fact, it seems to indicate success). What do the openfire logs show?

3

Thank you for your reply. It is MIT kerberos running on RHEL 5. Principals are not expired and time is synced across all servers. In fact, open fire logs does not provide much of information, I see only this when a client tries to connect.

2009.02.02 16:35:39 NIOConnection: startTLS: using c2s

This is the debug log from client.

client initializelogin procedure

(22:31:24) account: Connecting to account mmahut@mycompany.com/Home
(22:31:24) connection: Connecting. gc = 0x8c39f70
(22:31:24) dnssrv: querying SRV record for _xmpp-client._tcp.mycompany.com
(22:31:24) dnssrv: found 1 SRV entries
(22:31:24) dns: DNS query for ‘chat.corp.mycompany.com’ queued
(22:31:24) dns: Created new DNS child 18323, there are now 1 children.
(22:31:24) dns: Successfully sent DNS request to child 18323
(22:31:25) dns: Got response for ‘chat.corp.mycompany.com’
(22:31:25) dnsquery: IP resolved for chat.corp.mycompany.com
(22:31:25) proxy: Attempting connection to 10.11.255.93
(22:31:25) proxy: Connecting to chat.corp.mycompany.com:5222 with no proxy
(22:31:25) proxy: Connection in progress
(22:31:25) proxy: Connected to chat.corp.mycompany.com:5222.
(22:31:25) jabber: Sending: <?xml version='1.0' ?>
(22:31:25) jabber: Sending: <stream:stream to=‘mycompany.com’ xmlns=‘jabber:client’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’>
(22:31:25) jabber: Recv (183): <?xml version='1.0' encoding='UTF-8'?><stream:stream xmlns:stream=“http://etherx.jabber.org/streams” xmlns=“jabber:client” from=“mycompany.com” id=“86d92ec6” xml:lang=“en” version=“1.0”>
(22:31:25) jabber: Recv (230): stream:featuresGSSAPIPLAIN</stream:features>
(22:31:25) jabber: Sending:
(22:31:26) jabber: Recv (50):
(22:31:26) nss: subject=CN=chat.corp.mycompany.com issuer=CN=chat.corp.mycompany.com
(22:31:26) certificate/x509/tls_cached: Starting verify for mycompany.com
(22:31:26) certificate/x509/tls_cached: Checking for cached cert…
(22:31:26) certificate/x509/tls_cached: …Found cached cert
(22:31:26) nss/x509: Loading certificate from /home/mmahut/.purple/certificates/x509/tls_peers/mycompany.com
(22:31:26) certificate/x509/tls_cached: Peer cert matched cached
(22:31:26) certificate: Successfully verified certificate for mycompany.com(22:31:26) jabber: XML parser error for JabberStream 0x8b2c010: Domain 1, code 5, level 3: Extra content at the end of the document

(22:31:26) jabber: Sending (ssl): <stream:stream to=‘mycompany.com’ xmlns=‘jabber:client’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’>
(22:31:26) jabber: Recv (ssl)(483): <?xml version='1.0' encoding='UTF-8'?><stream:stream xmlns:stream=“http://etherx.jabber.org/streams” xmlns=“jabber:client” from=“mycompany.com” id=“86d92ec6” xml:lang=“en” version=“1.0”>stream:featuresGSSAPIPLAINzlib</stream:features>
(22:31:26) sasl: Mechs found: GSSAPI PLAIN
(22:31:26) sasl: No worthy mechs found

client is asked for a password, no xmpp keytab offered from the server

When I’m starting openfire server, it looks intialized. The keytab configuration is correct for sure, as I’m able to use it ssh into it.

2009.02.02 16:41:34 SunJGSS 1.0: Sun (Kerberos v5, SPNEGO)
2009.02.02 16:41:34 SunSASL 1.5: Sun SASL provider(implements client mechanisms for: DIGEST-MD5, GSSAPI, EXTERNAL, PLAIN, CRAM-MD5; server mechanisms for: DIGEST-MD5, GSSAPI, CRAM-MD5)

…

2009.02.02 16:41:39 SASLAuthentication: Added GSSAPI to mech list
2009.02.02 16:41:39 SASLAuthentication: Added PLAIN to mech list

In fact, nothing useful to debug and my java voodoo is too weak

4

The problem is in Pidgin or some supporting SASL lib. Was anything upgraded/removed/whatever? The key evidence here is near the end of the client debug logs:

(22:31:26) sasl: Mechs found: GSSAPI PLAIN

(22:31:26) sasl: No worthy mechs found

The fact that SASL didnt find PLAIN to be worthy sounds like the sasl lib dosnt have any of the modules installed. I presume that after asking for your password it attempts a non-sasl login (iq auth style). The interesting thing here is your server debug info does not match what is going on with the client debug. The server showed what appeared to be a valid GSSAPI login, the client logs show it dosnt even know how to do GSSAPI. Are you SURE the two logs show the same event? If not, please take care to capture the server logs and the client logs for the same event so we can correlate what is going on.

Also- I tend to agree with you that your keytab is correct. It seems so. However, Being able to ssh into the host does not test this in any way, as the “host/chat.corp.mycompany.com” principal is distinctly different from the “xmpp/chat.corp.mycompany.com” principal. A quick “klist -kt” should show all the entries in the keytab. In kadmin you can do “getprinc xmpp/chat.corp.mycompany.com” to see if an expiration date has been set, as well as if the last modified date correlates with when GSSAPI stopped working.

5

In fact, you’re right! Thank you!

https://bugzilla.redhat.com/show_bug.cgi?id=483714