Intermittent failures of mod_krb5

Thu Mar 1 14:56:51 CET 2018

Many thanks for the hints, especially KRB5_TRACE.

It certainly looks like the KDC (Samba4) is taking a long time to reply. 
In the example below, when freeradius gets a UDP response saying the 
data is too big for UDP, it reconnects over TCP. This happens twice - 
once to get a TGT for the authenticating user and once to get a service 
ticket - and these are taking 2.4 and 6.2 seconds respectively. With 
additional UDP round-trips, the whole thing is taking nearly 12 seconds 
in the example below.

My suspicion is something DNS-related, although Samba4 is authoritative 
for both the forward and reverse domains in question.

Anyway, I've got some good clues where to look now - thanks again!

Cheers,

Brian.

[27351] 1519910160.403074: Getting initial credentials for 
nagiostest at AD.EXAMPLE.NET
[27351] 1519910160.403135: Sending request (182 bytes) to AD.EXAMPLE.NET
[27351] 1519910160.403644: Resolving hostname wrn-dc1.ad.example.net.
[27351] 1519910160.404048: Sending initial UDP request to dgram 
192.168.5.86:88
[27351] 1519910161.404942: Resolving hostname ix-dc1.ad.example.net.
[27351] 1519910161.405719: Sending initial UDP request to dgram 10.0.0.86:88
[27351] 1519910161.418027: Received answer (299 bytes) from dgram 
10.0.0.86:88
[27351] 1519910161.418438: Response was not from master KDC
[27351] 1519910161.418482: Received error from KDC: 
-1765328359/Additional pre-authentication required
[27351] 1519910161.418542: Processing preauth types: 16, 15, 2, 19
[27351] 1519910161.418568: Selected etype info: etype aes256-cts, salt 
"AD.EXAMPLE.NETnagiostest", params "\x00\x00\x10\x00"
[27351] 1519910161.435098: AS key obtained for encrypted timestamp: 
aes256-cts/CAB6
[27351] 1519910161.435188: Encrypted timestamp (for 1519910161.431749): 
plain XXXXX, encrypted XXXXX
[27351] 1519910161.435229: Preauth module encrypted_timestamp (2) (real) 
returned: 0/Success
[27351] 1519910161.435244: Produced preauth for next request: 2
[27351] 1519910161.435293: Sending request (261 bytes) to AD.EXAMPLE.NET
[27351] 1519910161.435987: Resolving hostname wrn-dc1.ad.example.net.
[27351] 1519910161.436459: Sending initial UDP request to dgram 
192.168.5.86:88
[27351] 1519910162.437490: Resolving hostname ix-dc1.ad.example.net.
[27351] 1519910162.438420: Sending initial UDP request to dgram 10.0.0.86:88
[27351] 1519910162.468691: Received answer (180 bytes) from dgram 
10.0.0.86:88
[27351] 1519910162.469143: Response was not from master KDC
[27351] 1519910162.469190: Received error from KDC: -1765328332/Response 
too big for UDP, retry with TCP
[27351] 1519910162.469211: Request or response is too big for UDP; 
retrying with TCP
[27351] 1519910162.469258: Sending request (261 bytes) to AD.EXAMPLE.NET 
(tcp only)
[27351] 1519910162.469551: Resolving hostname wrn-dc1.ad.example.net.
[27351] 1519910162.470127: Initiating TCP connection to stream 
192.168.5.86:88
[27351] 1519910162.470653: Sending TCP request to stream 192.168.5.86:88
[27351] 1519910164.887084: Received answer (1452 bytes) from stream 
192.168.5.86:88
[27351] 1519910164.887119: Terminating TCP connection to stream 
192.168.5.86:88
[27351] 1519910164.888635: Response was not from master KDC
[27351] 1519910164.888691: Processing preauth types: 3
[27351] 1519910164.888756: Received salt "AD.EXAMPLE.NETnagiostest" via 
padata type 3
[27351] 1519910164.888778: Produced preauth for next request: (empty)
[27351] 1519910164.888844: AS key determined by preauth: aes256-cts/CAB6
[27351] 1519910164.888915: Decrypted AS reply; session key is: 
aes256-cts/C850
[27351] 1519910164.888944: FAST negotiation: unavailable
[27351] 1519910164.889301: Retrieving 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET from 
FILE:/etc/krb5.keytab (vno 0, enctype 0) with result: 0/Success
[27351] 1519910164.889326: Resolving unique ccache of type MEMORY
[27351] 1519910164.889353: Initializing MEMORY:WkltsUd with default 
princ nagiostest at AD.EXAMPLE.NET
[27351] 1519910164.889376: Storing nagiostest at AD.EXAMPLE.NET -> 
krbtgt/AD.EXAMPLE.NET at AD.EXAMPLE.NET in MEMORY:WkltsUd
[27351] 1519910164.889408: Getting credentials nagiostest at AD.EXAMPLE.NET 
-> host/wrn-radius2.ad.example.net@ using ccache MEMORY:WkltsUd
[27351] 1519910164.889452: Retrieving nagiostest at AD.EXAMPLE.NET -> 
host/wrn-radius2.ad.example.net@ from MEMORY:WkltsUd with result: 
-1765328243/Matching credential not found
[27351] 1519910164.889485: Retrying nagiostest at AD.EXAMPLE.NET -> 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET with result: 
-1765328243/Matching credential not found
[27351] 1519910164.889503: Server has referral realm; starting with 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET
[27351] 1519910164.889535: Retrieving nagiostest at AD.EXAMPLE.NET -> 
krbtgt/AD.EXAMPLE.NET at AD.EXAMPLE.NET from MEMORY:WkltsUd with result: 
0/Success
[27351] 1519910164.889555: Starting with TGT for client realm: 
nagiostest at AD.EXAMPLE.NET -> krbtgt/AD.EXAMPLE.NET at AD.EXAMPLE.NET
[27351] 1519910164.889573: Requesting tickets for 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET, referrals on
[27351] 1519910164.889615: Generated subkey for TGS request: aes256-cts/5AA2
[27351] 1519910164.889676: etypes requested in TGS request: aes256-cts, 
aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
[27351] 1519910164.889764: Encoding request body and padata into FAST 
request
[27351] 1519910164.889876: Sending request (1723 bytes) to AD.EXAMPLE.NET
[27351] 1519910164.890488: Resolving hostname wrn-dc1.ad.example.net.
[27351] 1519910164.891279: Sending initial UDP request to dgram 
192.168.5.86:88
[27351] 1519910165.892059: Resolving hostname ix-dc1.ad.example.net.
[27351] 1519910165.892983: Sending initial UDP request to dgram 10.0.0.86:88
[27351] 1519910165.925317: Received answer (107 bytes) from dgram 
10.0.0.86:88
[27351] 1519910165.925699: Response was not from master KDC
[27351] 1519910165.925740: Request or response is too big for UDP; 
retrying with TCP
[27351] 1519910165.925771: Sending request (1723 bytes) to 
AD.EXAMPLE.NET (tcp only)
[27351] 1519910165.926102: Resolving hostname wrn-dc1.ad.example.net.
[27351] 1519910165.926648: Initiating TCP connection to stream 
192.168.5.86:88
[27351] 1519910165.927270: Sending TCP request to stream 192.168.5.86:88
[27351] 1519910172.12661: Received answer (1437 bytes) from stream 
192.168.5.86:88
[27351] 1519910172.12785: Terminating TCP connection to stream 
192.168.5.86:88
[27351] 1519910172.13234: Response was not from master KDC
[27351] 1519910172.13273: Decoding FAST response
[27351] 1519910172.13358: TGS reply is for nagiostest at AD.EXAMPLE.NET -> 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET with session key 
rc4-hmac/45B6
[27351] 1519910172.13410: TGS request result: 0/Success
[27351] 1519910172.13428: Received creds for desired service 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET
[27351] 1519910172.13448: Storing nagiostest at AD.EXAMPLE.NET -> 
host/wrn-radius2.ad.example.net@ in MEMORY:WkltsUd
[27351] 1519910172.13473: Also storing nagiostest at AD.EXAMPLE.NET -> 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET based on ticket
[27351] 1519910172.13490: Removing nagiostest at AD.EXAMPLE.NET -> 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET from MEMORY:WkltsUd
[27351] 1519910172.13539: Creating authenticator for 
nagiostest at AD.EXAMPLE.NET -> host/wrn-radius2.ad.example.net@, seqnum 0, 
subkey (null), session key rc4-hmac/45B6
[27351] 1519910172.13748: Decrypted AP-REQ with server principal 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET: rc4-hmac/B770
[27351] 1519910172.13797: AP-REQ ticket: nagiostest at AD.EXAMPLE.NET -> 
host/wrn-radius2.ad.example.net at AD.EXAMPLE.NET, session key rc4-hmac/45B6
[27351] 1519910172.13873: Negotiated enctype based on authenticator: 
rc4-hmac
[27351] 1519910172.13904: Destroying ccache MEMORY:WkltsUd