[Freeipa-users] Valid Sender ? - Re: ipa-otpd: timeout from kerberos when talking to an external 'slow' RADIUS server

Tue Dec 20 22:32:27 UTC 2016

Alexander Bokovoy <abokovoy at redhat.com> writes:

>>1. KDC to ipa-otd: this can be changed in
>>/var/kerberos/krb5kdc/kdc.conf. I think the timeout should be larger
>>then the (largest) second timeout - and I think retries=0 is best.
>>This is for communication between KDC and ipa-otd.
>>
>>2. There is a timeout in each RADIUS server config in IPA for the
>>communication from ipa-otp to external RADIUS servers:
>>`----
>>Again I think that for OTPs we are probably best with retries=0.
>>
>>On older clients it might be helpful to add "udp_preference_limit = 0"
>>to /etc/krb5.conf - at least on my Debian/Ubuntu machines.

> Ok. It would probably make sense to file a ticket to FreeIPA tracker to
> get these changes in FreeIPA 4.5.

I think I've won my fight...  Here's what I've learned.  The short story is
that probably no timeout should be changed. Shall I still file a ticket
concerning retry counts?

Authentication of IPA users against RADIUS were mostly failing, but
not always. There were hints about timeouts almost everywhere.
Multiple authentication requests from kerberos, timeouts from sssd,
but that should have sent me on the right track from the start:

Dec 19 22:11:51 freeipa1 ipa-otpd: LDAP: ldapi://%2Fvar%2Frun%2Fslapd-JOCHEN-ORG.socket
Dec 19 22:11:51 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: request received
Dec 19 22:11:51 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: user query start
Dec 19 22:11:51 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: user query end: uid=jkellner,cn=users,cn=accounts,dc=jochen,dc=org
Dec 19 22:11:51 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: radius query start: cn=athene,cn=radiusproxy,dc=jochen,dc=org
Dec 19 22:11:51 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: radius query end: athene.jochen.org
Dec 19 22:11:51 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: forward start: jkellner at jochen.org / athene.jochen.org
Dec 19 22:12:01 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: forward end: Connection timed out
Dec 19 22:12:01 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: response sent: Access-Reject

or:

Dec 20 22:40:23 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: request received
Dec 20 22:40:23 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: user query start
Dec 20 22:40:23 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: user query end: uid=jkellner,cn=users,cn=accounts,dc=jochen,dc=org
Dec 20 22:40:23 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: radius query start: cn=athene,cn=radiusproxy,dc=jochen,dc=org
Dec 20 22:40:23 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: radius query end: athene.jochen.org
Dec 20 22:40:23 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: forward start: jkellner at jochen.org / athene.jochen.org
Dec 20 22:40:31 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: forward end: Access-Accept
Dec 20 22:40:31 freeipa1 ipa-otpd: jkellner at JOCHEN.ORG: response sent: Access-Accept

Why is there such a long delay?  The Log of the RADIUS server has:

Tue Dec 20 22:40:30 2016 : Info: rlm_perl: Config File /opt/privacyIDEA/rlm_perl.ini found!
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: Debugging config: true
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: Default URL https://athene.jochen.org/validate/check 
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: Looking for config for auth-type Perl
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: Auth-Type: Perl
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: url: https://athene.jochen.org/validate/check
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: user sent to privacyidea: jkellner at jochen.org
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: realm sent to privacyidea: jochen.org
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: resolver sent to privacyidea: 
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: client sent to privacyidea: 192.168.30.121
Tue Dec 20 22:40:30 2016 : Info: rlm_perl: state sent to privacyidea: 
Tue Dec 20 22:40:31 2016 : Info: rlm_perl: privacyIDEA access granted
Tue Dec 20 22:40:31 2016 : Info: rlm_perl: return RLM_MODULE_OK

So RADIUS thinks, it got a request a 30 seconds, but why did we wait so long?
I took a tcpdump and saw:

22:40:23.364355 IP6 freeipa1.jochen.org.41198 > athene.jochen.org.radius: RADIUS, Access-Request (1), id: 0x10 length: 134
22:40:30.872136 IP freeipa1.jochen.org.44314 > athene.jochen.org.radius: RADIUS, Access-Request (1), id: 0x9c length: 134
22:40:31.572217 IP athene.jochen.org.radius > freeipa1.jochen.org.44314: RADIUS, Access-Accept (2), id: 0x9c length: 48

So, we received an IPv6 packet, but didn't react. Some seconds later IPA-OTP
retried with IPv4 and succeeded.  A quick check showed that freeradius
did not listen on IPv6. After fixing that, a request looks like this:

Dec 20 22:54:57 freeipa2 ipa-otpd: jkellner at JOCHEN.ORG: request received
Dec 20 22:54:57 freeipa2 ipa-otpd: jkellner at JOCHEN.ORG: user query start
Dec 20 22:54:57 freeipa2 ipa-otpd: jkellner at JOCHEN.ORG: user query end: uid=jkellner,cn=users,cn=accounts,dc=jochen,dc=org
Dec 20 22:54:57 freeipa2 ipa-otpd: jkellner at JOCHEN.ORG: radius query start: cn=athene,cn=radiusproxy,dc=jochen,dc=org
Dec 20 22:54:57 freeipa2 ipa-otpd: jkellner at JOCHEN.ORG: radius query end: athene.jochen.org
Dec 20 22:54:57 freeipa2 ipa-otpd: jkellner at JOCHEN.ORG: forward start: jkellner at jochen.org / athene.jochen.org
Dec 20 22:54:58 freeipa2 ipa-otpd: jkellner at JOCHEN.ORG: forward end: Access-Accept
Dec 20 22:54:58 freeipa2 ipa-otpd: jkellner at JOCHEN.ORG: response sent: Access-Accept

and

Tue Dec 20 22:54:57 2016 : Info: rlm_perl: Config File /opt/privacyIDEA/rlm_perl.ini found!
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: Debugging config: true
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: Default URL https://athene.jochen.org/validate/check 
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: Looking for config for auth-type Perl
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: Auth-Type: Perl
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: url: https://athene.jochen.org/validate/check
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: user sent to privacyidea: jkellner at jochen.org
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: realm sent to privacyidea: jochen.org
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: resolver sent to privacyidea: 
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: client sent to privacyidea: 
Tue Dec 20 22:54:57 2016 : Info: rlm_perl: state sent to privacyidea: 
Tue Dec 20 22:54:58 2016 : Info: rlm_perl: privacyIDEA access granted
Tue Dec 20 22:54:58 2016 : Info: rlm_perl: return RLM_MODULE_OK

22:54:57.623116 IP6 fd23:e163:19f7:1234:5054:ff:fe07:ff5a.39817 > athene.jochen.org.radius: RADIUS, Access-Request (1), id: 0x23 length: 134
22:54:58.778278 IP6 athene.jochen.org.radius > fd23:e163:19f7:1234:5054:ff:fe07:ff5a.39817: RADIUS, Access-Accept (2), id: 0x23 length: 48

Runtime is quite short and stable, so I'll go mostly back to the default timeouts.

I've learned about the following timeouts for RADIUS authentication,
every single one can hit you when RADIUS takes a long time (which it souldn't):

* sssd has a default kerberos timeout of six seconds.
  Can be changed in /etc/sssd/sssd.conf: krb5_auth_timeout, 
  which also seems to work for auth_provider = ipa, but is not
  documented in sssd-ipa(5).

* There is a timeout for krb5kdc talking to ipa-otpd.
  Can be change in /var/kerberos/krb5kdc/kdc.conf with:
[otp]
 DEFAULT = {
  timeout = 15
  retries = 0
  strip_realm = false
 }

* In IPA there is also a radius-timeout which can be changed in the webui
  or with "ipa radiusproxy-mod <radius> --timeout=INT"

I found it quite challenging to wrap my head around the hole process
from PAM/SSS/KRB5/IPA-OTPD to FreeRADIUS/privacyidea, but now I'm quite
happy with what I've learned.

Thanks for you help.

Jochen

-- 
The only problem with troubleshooting is that the trouble shoots back.