KDC HA Failure with krb5-1.9.1 and pam-krb5 4.4
Tom Parker
tparker at cbnco.com
Fri Nov 18 17:41:44 EST 2011
Hi Greg.
Thanks for your quick reply. I have attached my results below. When
one of my KDCs is down the client kinit fails with: kinit:
sendto_kdc.c:617: cm_get_ssflags: Assertion `i < selstate->nfds' failed.
Tom
Successfull Auth with SSH
TCP Dump on Client
19:30:12.740632 IP 172.20.23.20.42116 > 172.20.23.10.88: v5
19:30:12.744175 IP 172.20.23.10.88 > 172.20.23.20.42116:
19:30:12.762438 IP 172.20.23.20.42801 > 172.30.26.12.88: v5
19:30:12.836960 IP 172.30.26.12.88 > 172.20.23.20.42801: v5
19:30:12.840186 IP 172.20.23.20.45158 > 172.30.26.12.88:
19:30:12.901922 IP 172.30.26.12.88 > 172.20.23.20.45158:
krb5kdc.log on 172.20.23.10
Nov 18 17:30:12 172.20.23.10 krb5kdc[4237](info): AS_REQ (4 etypes {18
17 16 23}) 172.20.23.20: NEEDED_PREAUTH: tparker at LS.CBN for
krbtgt/LS.CBN at LS.CBN, Additional pre-authentication required
krb5kdc.log on 172.20.26.12
Nov 18 17:30:13 172.20.26.12 krb5kdc[4044](info): AS_REQ (4 etypes {18
17 16 23}) 172.20.23.20: ISSUE: authtime 1321655413, etypes {rep=18
tkt=18 ses=18}, tparker at LS.CBN for krbtgt/LS.CBN at LS.CBN
Nov 18 17:30:13 172.20.26.12 krb5kdc[4044](info): TGS_REQ (4 etypes {18
17 16 23}) 172.20.23.20: ISSUE: authtime 1321655413, etypes {rep=18
tkt=18 ses=18}, tparker at LS.CBN for host/surdrdb.ls.cbn at LS.CBN
Successfull kinit.
KRB5_TRACE=/dev/stdout kinit tparker at LS.CBN
[19374] 1321655632.205079: Getting initial credentials for
tparker at LS.CBN
[19374] 1321655632.205605: Sending request (170 bytes) to LS.CBN
[19374] 1321655632.209155: Sending initial UDP request to dgram
172.20.23.10:88
[19374] 1321655632.213507: Received answer from dgram 172.20.23.10:88
[19374] 1321655632.215186: Response was from master KDC
[19374] 1321655632.215214: Received error from KDC:
-1765328359/Additional pre-authentication required
[19374] 1321655632.215251: Processing preauth types: 2, 136, 19, 133
[19374] 1321655632.215276: Selected etype info: etype aes256-cts, salt
"LS.CBNtparker", params ""
[19374] 1321655632.215286: Received cookie: MIT
Password for tparker at LS.CBN:
[19374] 1321655637.330098: AS key obtained for encrypted timestamp:
aes256-cts/50AF
[19374] 1321655637.330185: Encrypted timestamp (for 1321655637.330115):
plain 301AA011180F32303131313131383232333335375AA1050203050983,
encrypted
CA622361D07C6903871D405F8994A9D6FB657B9DE44BA07160089299EEA57E6F4B57A03B931D246337B85B4B619BBA2680829FF3231A1DDE
[19374] 1321655637.330278: Produced preauth for next request: 133, 2
[19374] 1321655637.330316: Sending request (265 bytes) to LS.CBN
(master)
[19374] 1321655637.332844: Sending initial UDP request to dgram
172.20.23.10:88
[19374] 1321655637.348289: Received answer from dgram 172.20.23.10:88
[19374] 1321655637.348377: Processing preauth types: 19
[19374] 1321655637.348393: Selected etype info: etype aes256-cts, salt
"LS.CBNtparker", params ""
[19374] 1321655637.348403: Produced preauth for next request: (empty)
[19374] 1321655637.348423: AS key determined by preauth: aes256-cts/50AF
[19374] 1321655637.348526: Decrypted AS reply; session key is:
aes256-cts/AC68
[19374] 1321655637.348559: FAST negotiation: available
[19374] 1321655637.348608: Initializing FILE:/tmp/krb5cc_0 with default
princ tparker at LS.CBN
[19374] 1321655637.348962: Removing tparker at LS.CBN ->
krbtgt/LS.CBN at LS.CBN from FILE:/tmp/krb5cc_0
[19374] 1321655637.348976: Storing tparker at LS.CBN ->
krbtgt/LS.CBN at LS.CBN in FILE:/tmp/krb5cc_0
[19374] 1321655637.349132: Storing config in FILE:/tmp/krb5cc_0 for
krbtgt/LS.CBN at LS.CBN: fast_avail: yes
[19374] 1321655637.349179: Removing tparker at LS.CBN ->
krb5_ccache_conf_data/fast_avail/krbtgt\/LS.CBN\@LS.CBN at X-CACHECONF:
from FILE:/tmp/krb5cc_0
[19374] 1321655637.349193: Storing tparker at LS.CBN ->
krb5_ccache_conf_data/fast_avail/krbtgt\/LS.CBN\@LS.CBN at X-CACHECONF: in
FILE:/tmp/krb5cc_0
Failed Auth with SSH. KDC at 172.20.23.10 is down. Server is up.
TCP Dump on client. Only gets to PREAUTH stage.
19:36:05.333234 IP 172.20.23.20.55700 > 172.20.23.10.88: v5
19:36:05.333515 IP 172.20.23.20.50287 > 172.30.26.12.88: v5
19:36:05.341416 IP 172.30.26.12.88 > 172.20.23.20.50287:
krb5kdc.log on 172.20.26.12
Nov 18 17:36:05 172.20.26.12 krb5kdc[4044](info): AS_REQ (4 etypes {18
17 16 23}) 172.20.23.20: NEEDED_PREAUTH: tparker at LS.CBN for
krbtgt/LS.CBN at LS.CBN, Additional pre-authentication required
OR
TCP Dump on client. Does PREAUTH but doesn't request TGS.
19:36:59.903015 IP 172.20.23.20.39162 > 172.30.26.12.88: v5
19:36:59.911296 IP 172.30.26.12.88 > 172.20.23.20.39162:
19:36:59.929261 IP 172.20.23.20.34569 > 172.20.23.10.88: v5
19:36:59.929532 IP 172.20.23.20.43634 > 172.30.26.12.88: v5
19:36:59.943513 IP 172.30.26.12.88 > 172.20.23.20.43634: v5
krb5kdc.log on 172.20.26.12
Nov 18 17:37:00 charon krb5kdc[4044](info): AS_REQ (4 etypes {18 17 16
23}) 172.20.23.20: NEEDED_PREAUTH: tparker at LS.CBN for
krbtgt/LS.CBN at LS.CBN, Additional pre-authentication required
Nov 18 17:37:00 charon krb5kdc[4044](info): AS_REQ (4 etypes {18 17 16
23}) 172.20.23.20: ISSUE: authtime 1321655820, etypes {rep=18 tkt=18
ses=18}, tparker at LS.CBN for krbtgt/LS.CBN at LS.CBN
Failed Kinit
KRB5_TRACE=/dev/stdout kinit tparker at LS.CBN
[19527] 1321655960.781081: Getting initial credentials for
tparker at LS.CBN
[19527] 1321655960.781611: Sending request (170 bytes) to LS.CBN
[19527] 1321655960.785069: Sending initial UDP request to dgram
172.20.23.10:88
[19527] 1321655960.785418: UDP error receiving from dgram
172.20.23.10:88: 111/Connection refused
[19527] 1321655960.785444: Sending initial UDP request to dgram
172.30.26.12:88
kinit: sendto_kdc.c:617: cm_get_ssflags: Assertion `i < selstate->nfds'
failed.
Aborted
OR
KRB5_TRACE=/dev/stdout kinit tparker at LS.CBN
[19556] 1321656003.985359: Getting initial credentials for
tparker at LS.CBN
[19556] 1321656003.986030: Sending request (170 bytes) to LS.CBN
[19556] 1321656003.989288: Sending initial UDP request to dgram
172.30.26.12:88
[19556] 1321656004.6014: Received answer from dgram 172.30.26.12:88
[19556] 1321656004.7915: Response was from master KDC
[19556] 1321656004.7942: Received error from KDC:
-1765328359/Additional pre-authentication required
[19556] 1321656004.7979: Processing preauth types: 2, 136, 19, 133
[19556] 1321656004.8004: Selected etype info: etype aes256-cts, salt
"LS.CBNtparker", params ""
[19556] 1321656004.8013: Received cookie: MIT
Password for tparker at LS.CBN:
[19556] 1321656006.934701: AS key obtained for encrypted timestamp:
aes256-cts/50AF
[19556] 1321656006.934789: Encrypted timestamp (for 1321656006.934719):
plain 301AA011180F32303131313131383232343030365AA10502030E433F,
encrypted
9A5FB6660876E593B7C7833F94B5FCFDE45D24C392EC1C5E2C5FD0FA1EC3FBE9CE1F65B564EE4FBF9E6E805B5A2F0FBD7E3108D9EDE3EB22
[19556] 1321656006.934812: Produced preauth for next request: 133, 2
[19556] 1321656006.934842: Sending request (265 bytes) to LS.CBN
(master)
[19556] 1321656006.937555: Sending initial UDP request to dgram
172.20.23.10:88
[19556] 1321656006.937943: UDP error receiving from dgram
172.20.23.10:88: 111/Connection refused
[19556] 1321656006.937969: Sending initial UDP request to dgram
172.30.26.12:88
kinit: sendto_kdc.c:617: cm_get_ssflags: Assertion `i < selstate->nfds'
failed.
Aborted
On Fri 18 Nov 2011 05:13:16 PM EST, Greg Hudson wrote:
> On 11/18/2011 02:17 PM, Tom Parker wrote:
>> The problem I have is that if I update my client from 1.8.3 to 1.9.1 my
>> High Availability breaks. A 1.9.1 client will not successfully
>> authenticate if one of my KDCs is down. My 1.8.3 clients work fine.
>
> Unfortunately, I'm unable to reproduce this. I created two SRV records,
> one pointing to a test server and one pointing to an invalid point, and
> 1.9.x clients were able to make successful AS and TGS requests to that
> zone regardless of whether they tried the incorrect or correct port first.
>
> There weren't very many changes to the KDC location or communication
> code between 1.8 and 1.9 (although there were a few mostly innocuous
> ones) and there haven't been any since the 1.9 branch.
>
> 1.9 supports a new tracing facility which might provide a little
> additional information, although it's not possibly to use in concert
> with pam_krb5. But you can use it with kinit or kvno, e.g.:
>
> KRB5_TRACE=/dev/stdout kinit tparker at LS.CBN
> KRB5_TRACE=/dev/stdout kvno host/arudrdb.ls.cbn at LS.CBN
>
> When I do this in my test scenario, I see stuff like:
>
> [6252] 1321653654.244586: Sending initial UDP request to dgram
> 18.18.1.59:50799
> [6252] 1321653654.244628: UDP error receiving from dgram
> 18.18.1.59:50799: 111/Connection refused
> [6252] 1321653654.244641: Sending initial UDP request to dgram
> 18.18.1.59:50800
> [6252] 1321653654.247219: Received answer from dgram 18.18.1.59:50800
>
> Or, if the wrong entry goes to a black hole, I see (note the one-second
> delay between the first and second entries):
>
> [6652] 1321654279.235052: Sending initial UDP request to dgram
> 18.70.0.200:50799
> [6652] 1321654280.236097: Sending initial UDP request to dgram
> 127.0.1.1:50800
> [6652] 1321654280.236639: Received answer from dgram 127.0.1.1:50800
>
More information about the Kerberos
mailing list