reauth-problem with WPA2-tls

[Andreas Hartmann]

David Mitchell schrieb:
> Alan DeKok wrote:
>> Andreas Hartmann wrote:
>>> In eap.conf, the option eap -> tls -> cache -> enable is switched off
>>> and fast_reauth in wpa_supplicant is enabled.
>>
>>   Uh... that makes no sense.
>>
>>   You've disabled caching (i.e fast re-auth) on the server, and enabled
>> it on the client.  Why are you surprised that fast re-auth isn't working?
> 
> I've seen similar problems between FreeRadius and wpa_supplicant both
> with and without the cache enabled. Getting wpa_supplicant to restart
> seems to clear it temporarily.

Well, I took your realization to implement the following workaround:

Caching is enabled in freeradius, fast_reauth is switched on in
wpa_supplicant.

I set the reauth-timeout of the AP to 2 hours. On the supplicant, I
started a cronjob, which HUP's the supplicant each 59 minutes. That's
the way how the supplicant is prevented to do a fast reauth (which
doesn't really work). A full reauth isn't necessary too, because of the
sig hup all 59 minutes, which is done like this:

rad_recv: Accounting-Request packet from host 192.168.1.9 port 2049,
id=112, length=177
        Acct-Session-Id = "0000001B-00000007"
        Acct-Status-Type = Stop
        Acct-Authentic = RADIUS
        User-Name = "myuser at mydom"
        NAS-Port = 0
        Called-Station-Id = "00-25-...:mylan"
        Calling-Station-Id = "00-13-..."
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        Acct-Session-Time = 358
        Event-Timestamp = "Jan  1 1970 02:26:18 CET"
        Acct-Terminate-Cause = User-Request
Thu Jun  3 05:41:43 2010 : Info: +- entering group preacct {...}
Thu Jun  3 05:41:43 2010 : Info: ++[preprocess] returns ok
Thu Jun  3 05:41:43 2010 : Info: [acct_unique] Hashing 'NAS-Port =
0,Client-IP-Address = 192.168.1.9,NAS-IP-Address =
192.168.1.9,Acct-Session-Id = "0000001B-00000007",User-Name =
"myuser at mydom"'
Thu Jun  3 05:41:43 2010 : Info: [acct_unique] Acct-Unique-Session-ID =
"aba6339d45d8fab1".
Thu Jun  3 05:41:43 2010 : Info: ++[acct_unique] returns ok
Thu Jun  3 05:41:43 2010 : Info: [suffix] Looking up realm "mydom" for
User-Name = "myuser at mydom"
Thu Jun  3 05:41:43 2010 : Info: [suffix] No such realm "mydom"
Thu Jun  3 05:41:43 2010 : Info: ++[suffix] returns noop
Thu Jun  3 05:41:43 2010 : Info: ++[files] returns noop
Thu Jun  3 05:41:43 2010 : Info: +- entering group accounting {...}
Thu Jun  3 05:41:43 2010 : Info: [detail]       expand:
/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d ->
/var/log/radius/radacct/192.168.1.9/detail-20100603
Thu Jun  3 05:41:43 2010 : Info: [detail]
/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to
/var/log/radius/radacct/192.168.1.9/detail-20100603
Thu Jun  3 05:41:43 2010 : Info: [detail]       expand: %t -> Thu Jun  3
05:41:43 2010
Thu Jun  3 05:41:43 2010 : Info: ++[detail] returns ok
Thu Jun  3 05:41:43 2010 : Info: ++[unix] returns ok
Thu Jun  3 05:41:43 2010 : Info: [radutmp]      expand:
/var/log/radius/radutmp -> /var/log/radius/radutmp
Thu Jun  3 05:41:43 2010 : Info: [radutmp]      expand: %{User-Name} ->
myuser at mydom
Thu Jun  3 05:41:43 2010 : Info: ++[radutmp] returns ok
Thu Jun  3 05:41:43 2010 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> myuser at mydom
Thu Jun  3 05:41:43 2010 : Debug:  attr_filter: Matched entry DEFAULT at
line 12
Thu Jun  3 05:41:43 2010 : Info: ++[attr_filter.accounting_response]
returns updated
Sending Accounting-Response of id 112 to 192.168.1.9 port 2049
Thu Jun  3 05:41:43 2010 : Info: Finished request 111.
Thu Jun  3 05:41:43 2010 : Info: Cleaning up request 111 ID 112 with
timestamp +5054
Thu Jun  3 05:41:43 2010 : Debug: Going to the next request
Thu Jun  3 05:41:43 2010 : Info: Ready to process requests.

rad_recv: Accounting-Request packet from host 192.168.1.9 port 2049,
id=113, length=159
        Acct-Session-Id = "0000001B-00000008"
        Acct-Status-Type = Start
        Acct-Authentic = RADIUS
        User-Name = "myuser at mydom"
        NAS-Port = 0
        Called-Station-Id = "00-25-...:mylan"
        Calling-Station-Id = "00-13-..."
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
Thu Jun  3 05:41:44 2010 : Info: +- entering group preacct {...}
Thu Jun  3 05:41:44 2010 : Info: ++[preprocess] returns ok
Thu Jun  3 05:41:44 2010 : Info: [acct_unique] Hashing 'NAS-Port =
0,Client-IP-Address = 192.168.1.9,NAS-IP-Address =
192.168.1.9,Acct-Session-Id = "0000001B-00000008",User-Name =
"myuser at mydom"'
Thu Jun  3 05:41:44 2010 : Info: [acct_unique] Acct-Unique-Session-ID =
"efac47a366ac188f".
Thu Jun  3 05:41:44 2010 : Info: ++[acct_unique] returns ok
Thu Jun  3 05:41:44 2010 : Info: [suffix] Looking up realm "mydom" for
User-Name = "myuser at mydom"
Thu Jun  3 05:41:44 2010 : Info: [suffix] No such realm "mydom"
Thu Jun  3 05:41:44 2010 : Info: ++[suffix] returns noop
Thu Jun  3 05:41:44 2010 : Info: ++[files] returns noop
Thu Jun  3 05:41:44 2010 : Info: +- entering group accounting {...}
Thu Jun  3 05:41:44 2010 : Info: [detail]       expand:
/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d ->
/var/log/radius/radacct/192.168.1.9/detail-20100603
Thu Jun  3 05:41:44 2010 : Info: [detail]
/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to
/var/log/radius/radacct/192.168.1.9/detail-20100603
Thu Jun  3 05:41:44 2010 : Info: [detail]       expand: %t -> Thu Jun  3
05:41:44 2010
Thu Jun  3 05:41:44 2010 : Info: ++[detail] returns ok
Thu Jun  3 05:41:44 2010 : Info: ++[unix] returns ok
Thu Jun  3 05:41:44 2010 : Info: [radutmp]      expand:
/var/log/radius/radutmp -> /var/log/radius/radutmp
Thu Jun  3 05:41:44 2010 : Info: [radutmp]      expand: %{User-Name} ->
myuser at mydom
Thu Jun  3 05:41:44 2010 : Info: ++[radutmp] returns ok
Thu Jun  3 05:41:44 2010 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> myuser at mydom
Thu Jun  3 05:41:44 2010 : Debug:  attr_filter: Matched entry DEFAULT at
line 12
Thu Jun  3 05:41:44 2010 : Info: ++[attr_filter.accounting_response]
returns updated
Sending Accounting-Response of id 113 to 192.168.1.9 port 2049
Thu Jun  3 05:41:44 2010 : Info: Finished request 112.
Thu Jun  3 05:41:44 2010 : Info: Cleaning up request 112 ID 113 with
timestamp +5055
Thu Jun  3 05:41:44 2010 : Debug: Going to the next request
Thu Jun  3 05:41:44 2010 : Info: Ready to process requests.


> My reading of Andreas's message was that
> he has tried it both ways.

Yes :-)

> I haven't yet dug into it enough to try and
> pin down where the problem is. It does seem that problems with the cache
> should just result in a slow authentication taking place, not a total
> failure of authentication.


Kind regards,
Andreas