Intermittent failures of mod_krb5
Hello, I have been setting up freeradius-3.0.15 (from PPA) under Ubuntu 16.04, and using mod_krb5 to authenticate against Samba4. There are four freeradius servers, each with a Samba replica behind it. Once every few days, I get alerts from nagios saying one or more RADIUS servers has stopped working for a few minutes, and then they recover. There are two nagios servers making RADIUS checks across all four RADIUS servers, and both nagios servers see the problem simultaneously. I now have authentication logging turn on, and at the time of the last event I see: ... all OK Thu Feb 22 17:21:51 2018 : Auth: (273) Login OK: [nagiostest] (from client ix_nagios port 0) Thu Feb 22 17:22:38 2018 : Auth: (274) Login OK: [nagiostest] (from client wrn_mon2 port 0) Thu Feb 22 17:23:00 2018 : Error: Unresponsive child for request 275, in component authenticate module krb5 Thu Feb 22 17:23:10 2018 : WARNING: (275) WARNING: Module rlm_krb5 became unblocked Thu Feb 22 17:23:38 2018 : Auth: (276) Login OK: [nagiostest] (from client wrn_mon2 port 0) Thu Feb 22 17:24:00 2018 : Error: Unresponsive child for request 277, in component authenticate module krb5 Thu Feb 22 17:24:01 2018 : WARNING: (277) WARNING: Module rlm_krb5 became unblocked Thu Feb 22 17:24:46 2018 : Error: Unresponsive child for request 278, in component authenticate module krb5 Thu Feb 22 17:24:52 2018 : Info: Need 1 more connections to reach 5 spares Thu Feb 22 17:24:52 2018 : Info: rlm_krb5 (krb5): Opening additional connection (5), 1 of 5 pending slots used Thu Feb 22 17:24:52 2018 : WARNING: (278) WARNING: Module rlm_krb5 became unblocked Thu Feb 22 17:25:00 2018 : Error: Unresponsive child for request 279, in component authenticate module krb5 Thu Feb 22 17:25:01 2018 : WARNING: (279) WARNING: Module rlm_krb5 became unblocked Thu Feb 22 17:25:45 2018 : Info: rlm_krb5 (krb5): Closing connection (4), from 1 unused connections Thu Feb 22 17:25:45 2018 : Auth: (280) Login OK: [nagiostest] (from client wrn_mon2 port 0) Thu Feb 22 17:26:00 2018 : Error: Unresponsive child for request 281, in component authenticate module krb5 Thu Feb 22 17:26:10 2018 : WARNING: (281) WARNING: Module rlm_krb5 became unblocked Thu Feb 22 17:26:46 2018 : Error: Unresponsive child for request 282, in component authenticate module krb5 Thu Feb 22 17:26:56 2018 : Info: Need 1 more connections to reach 5 spares Thu Feb 22 17:26:56 2018 : Info: rlm_krb5 (krb5): Opening additional connection (6), 1 of 5 pending slots used Thu Feb 22 17:26:56 2018 : WARNING: (282) WARNING: Module rlm_krb5 became unblocked Thu Feb 22 17:27:00 2018 : Error: Unresponsive child for request 283, in component authenticate module krb5 Thu Feb 22 17:27:10 2018 : WARNING: (283) WARNING: Module rlm_krb5 became unblocked Thu Feb 22 17:27:43 2018 : Info: rlm_krb5 (krb5): Closing connection (1), from 1 unused connections Thu Feb 22 17:27:43 2018 : Auth: (284) Login OK: [nagiostest] (from client wrn_mon2 port 0) Thu Feb 22 17:28:00 2018 : Auth: (285) Login OK: [nagiostest] (from client ix_nagios port 0) ... all OK again I'm not sure about the meaning of the message "became unblocked". Looking at the source of call_modsingle() blocked = (request->master_state == REQUEST_STOP_PROCESSING); if (blocked) return RLM_MODULE_NOOP; ... blocked = (request->master_state == REQUEST_STOP_PROCESSING); if (blocked) { RWARN("Module %s became unblocked", sp->modinst->entry->name); } It seems to me that the module has unexpectedly become blocked (not unblocked!) But does this simply mean that the module is taking longer to respond than expected? Or if not, what else does it indicate? Apart from this: I wondered if you had any pointers to narrowing down the problem. There are four servers so I can probably leave one running under freeradius -X until it recurs. Now, of course the problem *could* be with Samba4. However I have a separate nagios script (below) which performs LDAP queries using krb5 authentication, and it never reports a problem - not even an occasional "soft" error; that suggests that KRB5 is reliable. It considered if it was a problem with the RADIUS checking plugin (check_radius_adv), but this seems very unlikely given that (a) both nagios servers see the same problem simultaneously, and (b) freeradius itself is logging problems around the time of the issue. I have: [radiusd.conf] max_request_time = 10 thread pool { start_servers = 3 ----------- #!/bin/sh host="$1" if [ "$host" = "" ]; then echo "Missing hostname" exit 2 fi export KRB5_CONFIG="/tmp/krb5.config.$$" export KRB5CCNAME="/tmp/krb5.cc_cache.$$" if expr "$host" : ".*:" >/dev/null; then khost="[$host]" else khost="$host" fi cat <<EOS >"$KRB5_CONFIG" [realms] AD.EXAMPLE.NET = { kdc = $khost } EOS # 1. Can we get a ticket from this host? kinit -k -t /etc/nagiostest.keytab nagiostest@AD.EXAMPLE.NET if [ "$?" != "0" ]; then echo "KINIT FAILED" rm "$KRB5_CONFIG" exit 2 fi # 2. Can we use this ticket to do an LDAP query to this host? res="$(ldapsearch -LLLQ -Y GSSAPI -h "$host" -b "cn=users,dc=ad,dc=example,dc=net" "(samaccountname=nagiostest)" samaccountname userprincipalname)" if [ "$?" != "0" ]; then echo "LDAPSEARCH FAILED" kdestroy rm "$KRB5_CONFIG" exit 2 fi if ! expr "$res" : ".*userPrincipalName: nagiostest@ad.example.net"
/dev/null; then echo "LDAPSEARCH BAD RESULT: $res" kdestroy rm "$KRB5_CONFIG" exit 2 fi
# 3. Clean up kdestroy rm "$KRB5_CONFIG" echo "OK"
Sorry, hit send too early by accident. Relevant bits of config: [radiusd.conf] max_request_time = 10 thread pool { start_servers = 3 min_spare_servers = 2 max_spare_servers = 5 max_requests_per_server = 0 } [sites-available/default] authorize { ... ldap ... # NOTE: ldap module does not set a Cleartext-Password so "pap" # is not enabled automatically. But we are fine to use PAP+krb5 update control { Auth-Type = PAP } } authenticate { Auth-Type PAP { krb5 } } [mods-available/krb5] krb5 { keytab = /etc/krb5.keytab service_principal = 'host/ix-radius1.ad.example.net' # different for each radius server pool { ... everything as defaults ... } } I wonder if there is some sort of leak and I should set "uses" or "lifetime" to limit how long each krb5 instance is used for? I also have these environment variables set in systemd: [Service] Environment=KRB5_CLIENT_KTNAME=/etc/radius.keytab Environment=KRB5CCNAME=MEMORY: Restart=always RestartSec=5 This is so that freeradius can authenticate to the LDAP server for LDAP queries. But I don't think the problem is to do with LDAP queries from freeradius, since the log messages are specifically about rlm_krb5, not rlm_ldap. Cheers, Brian.
[mods-available/krb5] krb5 { keytab = /etc/krb5.keytab service_principal = 'host/ix-radius1.ad.example.net' # different for each radius server pool { ... everything as defaults ... } }
I wonder if there is some sort of leak and I should set "uses" or "lifetime" to limit how long each krb5 instance is used for?
Go for it. I’m not sure that kerberos handles are actually bound to connections though i.e. destroying a handle might not actually do anything helpful if libkerberos does its own connection management. -Arran
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@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@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@AD.EXAMPLE.NET [27351] 1519910164.889376: Storing nagiostest@AD.EXAMPLE.NET -> krbtgt/AD.EXAMPLE.NET@AD.EXAMPLE.NET in MEMORY:WkltsUd [27351] 1519910164.889408: Getting credentials nagiostest@AD.EXAMPLE.NET -> host/wrn-radius2.ad.example.net@ using ccache MEMORY:WkltsUd [27351] 1519910164.889452: Retrieving nagiostest@AD.EXAMPLE.NET -> host/wrn-radius2.ad.example.net@ from MEMORY:WkltsUd with result: -1765328243/Matching credential not found [27351] 1519910164.889485: Retrying nagiostest@AD.EXAMPLE.NET -> host/wrn-radius2.ad.example.net@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@AD.EXAMPLE.NET [27351] 1519910164.889535: Retrieving nagiostest@AD.EXAMPLE.NET -> krbtgt/AD.EXAMPLE.NET@AD.EXAMPLE.NET from MEMORY:WkltsUd with result: 0/Success [27351] 1519910164.889555: Starting with TGT for client realm: nagiostest@AD.EXAMPLE.NET -> krbtgt/AD.EXAMPLE.NET@AD.EXAMPLE.NET [27351] 1519910164.889573: Requesting tickets for host/wrn-radius2.ad.example.net@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@AD.EXAMPLE.NET -> host/wrn-radius2.ad.example.net@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@AD.EXAMPLE.NET [27351] 1519910172.13448: Storing nagiostest@AD.EXAMPLE.NET -> host/wrn-radius2.ad.example.net@ in MEMORY:WkltsUd [27351] 1519910172.13473: Also storing nagiostest@AD.EXAMPLE.NET -> host/wrn-radius2.ad.example.net@AD.EXAMPLE.NET based on ticket [27351] 1519910172.13490: Removing nagiostest@AD.EXAMPLE.NET -> host/wrn-radius2.ad.example.net@AD.EXAMPLE.NET from MEMORY:WkltsUd [27351] 1519910172.13539: Creating authenticator for nagiostest@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@AD.EXAMPLE.NET: rc4-hmac/B770 [27351] 1519910172.13797: AP-REQ ticket: nagiostest@AD.EXAMPLE.NET -> host/wrn-radius2.ad.example.net@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
On Mar 1, 2018, at 8:56 AM, Brian Candler <b.candler@pobox.com> wrote:
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.
Yeah. There's little you can do to FreeRADIUS to fix that.
My suspicion is something DNS-related, although Samba4 is authoritative for both the forward and reverse domains in question.
Maybe not DNS... DNS timeouts are usually 30s. A 2-4s delay is likely something else. Alan DeKok.
On Mar 1, 2018, at 8:56 AM, Brian Candler <b.candler@pobox.com> wrote:
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.
This is fairly common with Windows Kerberos - the size of the ticket is directly proportional to the the number of times certain changes have been made to the principal, and the number of groups the principal is a member of. Microsoft's implementation has a setting to allow larger payloads (not sure about Samba), but that can cause other issues if you have e.g. a VPN in play, so the best solution is just to prefer TCP if speed is an issue. Have you looked at building FreeRADIUS with libwbclient instead, or maybe looking at if you could use sssd to cache? Regards, Adam Bishop gpg: E75B 1F92 6407 DFDF 9F1C BF10 C993 2504 6609 D460 jisc.ac.uk Jisc is a registered charity (number 1149740) and a company limited by guarantee which is registered in England under Company No. 5747339, VAT No. GB 197 0632 86. Jisc’s registered office is: One Castlepark, Tower Hill, Bristol, BS2 0JA. T 0203 697 5800. Jisc Services Limited is a wholly owned Jisc subsidiary and a company limited by guarantee which is registered in England under company number 2881024, VAT number GB 197 0632 86. The registered office is: One Castle Park, Tower Hill, Bristol BS2 0JA. T 0203 697 5800.
On Thu, Mar 1, 2018 at 3:56 PM, Brian Candler <b.candler@pobox.com> wrote:
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.
You can try to prefer TCP by setting 'udp_preference_limit' in krb.conf, see the man page (I didn't test, but it sounds it should work).
On Feb 23, 2018, at 7:43 AM, Brian Candler <b.candler@pobox.com> wrote:
I have been setting up freeradius-3.0.15 (from PPA) under Ubuntu 16.04, and using mod_krb5 to authenticate against Samba4. There are four freeradius servers, each with a Samba replica behind it.
Once every few days, I get alerts from nagios saying one or more RADIUS servers has stopped working for a few minutes, and then they recover. There are two nagios servers making RADIUS checks across all four RADIUS servers, and both nagios servers see the problem simultaneously.
I now have authentication logging turn on, and at the time of the last event I see:
... all OK Thu Feb 22 17:21:51 2018 : Auth: (273) Login OK: [nagiostest] (from client ix_nagios port 0) Thu Feb 22 17:22:38 2018 : Auth: (274) Login OK: [nagiostest] (from client wrn_mon2 port 0) Thu Feb 22 17:23:00 2018 : Error: Unresponsive child for request 275, in component authenticate module krb5 Thu Feb 22 17:23:10 2018 : WARNING: (275) WARNING: Module rlm_krb5 became unblocked
That means that the krb5 module was blocked in an IO call. i.e. rlm_krb5 made a call to a kerberos library, which took a LONG time to respond.
It seems to me that the module has unexpectedly become blocked (not unblocked!)
The code catches the case where the request is running, but notices that something else set the "stop processing" flag. This means that something else determined that the module was blocked, and told the module to stop. Then at a *later* time, the module was unblocked, and was able to continue.
But does this simply mean that the module is taking longer to respond than expected?
Yes. Where "longer" means 30s or more... If you want to narrow it down, you'll have to instrument the krb5 module. Poke at it so that it records the current time before doing a krb5 API call, and then looks at the time after it does that call. If the difference is more than a second, that's the problem. This is one of the situations where we can't really do much. We hand program execution off to a third-party library, and hope for the best. If that library blocks the request for 30s, there is very little we can do in the server to make *that library* run faster. As for your scripts running fine, well... they must be doing something different. That's all I can guess. Alan DeKok.
On Fri, Feb 23, 2018 at 2:43 PM, Brian Candler <b.candler@pobox.com> wrote:
Hello,
I have been setting up freeradius-3.0.15 (from PPA) under Ubuntu 16.04, and using mod_krb5 to authenticate against Samba4. There are four freeradius servers, each with a Samba replica behind it.
Once every few days, I get alerts from nagios saying one or more RADIUS servers has stopped working for a few minutes, and then they recover. There are two nagios servers making RADIUS checks across all four RADIUS servers, and both nagios servers see the problem simultaneously.
I now have authentication logging turn on, and at the time of the last event I see:
... all OK Thu Feb 22 17:21:51 2018 : Auth: (273) Login OK: [nagiostest] (from client ix_nagios port 0) Thu Feb 22 17:22:38 2018 : Auth: (274) Login OK: [nagiostest] (from client wrn_mon2 port 0) Thu Feb 22 17:23:00 2018 : Error: Unresponsive child for request 275, in component authenticate module krb5 Thu Feb 22 17:23:10 2018 : WARNING: (275) WARNING: Module rlm_krb5 became unblocked
In addition to radiusd debugs you can export KRB5_TRACE environment variable and have the library print traces into a log file. Also try to avoid dns (and rdns) lookups in krb5.conf, may help.
participants (5)
-
Adam Bishop -
Alan DeKok -
Arran Cudbard-Bell -
Brian Candler -
Isaac Boukris