too many "No EAP session matching state 0x…" with FR 3.0.x

[Michael Simon]

Am 13.06.2014 13:42, schrieb Alan DeKok:
> Michael Simon wrote:
>> After running FR 3.0.3 from GIT (FR 3.0.2 as well) for a while (a few
>> hours)
>> lots of “Error: rlm_eap (EAP): No EAP session matching state 0x…” appear
>> in the log file.
>>
>> A restart of FR and the error messages are gone for the present.
>>
>
>   The debug output would be a lot more helpful.
>

Here is the debug output.

The whole log size is 3.7MB (bz2 compressed)

I also have a valgrind output.

==00:01:39:12.597 24025== LEAK SUMMARY:
==00:01:39:12.597 24025==    definitely lost: 12,573 bytes in 34 blocks
==00:01:39:12.597 24025==    indirectly lost: 53,791 bytes in 586 blocks
==00:01:39:12.597 24025==      possibly lost: 2,049 bytes in 1 blocks
==00:01:39:12.597 24025==    still reachable: 2,363,837 bytes in 22 blocks
==00:01:39:12.597 24025==         suppressed: 0 bytes in 0 blocks


==00:01:33:10.179 24025== Conditional jump or move depends on 
uninitialised value(s)
==00:01:33:10.179 24025==    at 0x40F4A4C: ??? (in 
/usr/lib/i386-linux-gnu/i686/cmov/libcrypto.so.1.0.0)
==00:01:33:10.179 24025==    by 0x3801EE69: 
vgMemCheck_detect_memory_leaks (mc_leakcheck.c:1714)
==00:01:33:10.179 24025==    by 0x42BE414: talloc_check_name (in 
/usr/lib/i386-linux-gnu/libtalloc.so.2.1.1)


summary of an example:

(1609)  Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 34543 cli 0026.08dc.a8eb via TLS tunnel)
(1610) Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 34543 cli 0026.08dc.a8eb)
(1627)  Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 751 cli 00-26-08-DC-A8-EB via TLS tunnel)
(1628) Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 751 cli 00-26-08-DC-A8-EB)
(1696)  Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 34547 cli 80ea.96ad.cae3 via TLS tunnel)
(1697) Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 34547 cli 80ea.96ad.cae3)
(2132)  Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 34566 cli 80ea.96ad.cae3 via TLS tunnel)
(2133) Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 34566 cli 80ea.96ad.cae3)
(2147)  Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 744 cli 80-EA-96-AD-CA-E3 via TLS tunnel)
(2148) Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 744 cli 80-EA-96-AD-CA-E3)
(2602) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 498 cli 80-EA-96-AD-CA-E3)
(2671) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 759 cli 80-EA-96-AD-CA-E3)
(2994) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 21111 cli 80-EA-96-AD-CA-E3)
(2996) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 21111 cli 80-EA-96-AD-CA-E3)
(3002) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 21113 cli 80-EA-96-AD-CA-E3)
(3012) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 21113 cli 80-EA-96-AD-CA-E3)
(3018) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 48469 cli 80-EA-96-AD-CA-E3)
(3019) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 48469 cli 80-EA-96-AD-CA-E3)
(3039) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 21118 cli 80-EA-96-AD-CA-E3)
(3040) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 21118 cli 80-EA-96-AD-CA-E3)

example last "Login OK":

(2148) # Executing section authorize from file 
/etc/freeradius/sites-enabled/default
(2148)   authorize {
(2148)   filter_username filter_username {
(2148)     if (!User-Name)
(2148)     if (!User-Name)  -> FALSE
(2148)     if (User-Name =~ / /)
(2148)     if (User-Name =~ / /)  -> FALSE
(2148)     if (User-Name =~ /@.*@/ )
(2148)     if (User-Name =~ /@.*@/ )  -> FALSE
(2148)     if (User-Name =~ /\\.\\./ )
(2148)     if (User-Name =~ /\\.\\./ )  -> FALSE
(2148)     if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/))
(2148)     if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/)) 
-> FALSE
(2148)     if (User-Name =~ /\\.$/)
(2148)     if (User-Name =~ /\\.$/)   -> FALSE
(2148)     if (User-Name =~ /@\\./)
(2148)     if (User-Name =~ /@\\./)   -> FALSE
(2148)   } # filter_username filter_username = notfound
(2148)    if ( User-Name && ( User-Name !~ 
/^([a-z0-9._-]+)@([a-z0-9._-]+)[.]([a-z]{2,4})$/i ) || ( User-Name =~ 
/@wlan\\.[[:alnum:]]+\\.[[:alnum:]]+\\.3gppnetwork\\.org$/i ) )
(2148)    if ( User-Name && ( User-Name !~ 
/^([a-z0-9._-]+)@([a-z0-9._-]+)[.]([a-z]{2,4})$/i ) || ( User-Name =~ 
/@wlan\\.[[:alnum:]]+\\.[[:alnum:]]+\\.3gppnetwork\\.org$/i ) ) -> FALSE
(2148)   [preprocess] = ok
(2148)  suffix : Looking up realm "uni-wuppertal.de" for User-Name = 
"user294 at uni-wuppertal.de"
(2148)  suffix : Found realm "uni-wuppertal.de"
(2148)  suffix : Adding Stripped-User-Name = "user294"
(2148)  suffix : Adding Realm = "uni-wuppertal.de"
(2148)  suffix : Authentication realm is LOCAL
(2148)   [suffix] = ok
(2148)  eap : EAP packet type response id 12 length 43
(2148)  eap : Continuing tunnel setup
(2148)   [eap] = ok
(2148)  } #  authorize = ok
(2148) Found Auth-Type = EAP
(2148) # Executing group from file /etc/freeradius/sites-enabled/default
(2148)   authenticate {
Waking up in 0.1 seconds.
(2148)  eap : Expiring EAP session with state 0x11574ddc115d54e6
(2148)  eap : Finished EAP session with state 0x1e66753c156a6c95
(2148)  eap : Previous EAP request found for state 0x1e66753c156a6c95, 
released from the list
(2148)  eap : Peer sent PEAP (25)
(2148)  eap : EAP PEAP (25)
(2148)  eap : Calling eap_peap to process EAP data
(2148)  eap_peap : processing EAP-TLS
(2148)  eap_peap : eaptls_verify returned 7
(2148)  eap_peap : Done initial handshake
(2148)  eap_peap : eaptls_process returned 7
(2148)  eap_peap : FR_TLS_OK
(2148)  eap_peap : Session established.  Decoding tunneled attributes
(2148)  eap_peap : Peap state send tlv success
(2148)  eap_peap : Received EAP-TLV response
(2148)  eap_peap : Success
(2148)  eap_peap : Using saved attributes from the original Access-Accept
Sending Access-Challenge Id 149 from 0.0.0.0:2083 to 192.178.71.138:27485
         EAP-Message = 
0x010c002b19001703010020a61f43fe889948870718b6d9a4375a8bc74af77ef47c7c4b6521c5f855157f5f
         Message-Authenticator = 0x00000000000000000000000000000000
         State = 0x1e66753c156a6c9510f0431d79ab79e0
         Proxy-State = 0x3130
         User-Name = 'user294 at uni-wuppertal.de'
         NAS-IP-Address = 10.41.1.41
         NAS-Port = 744
         Called-Station-Id = '00-0F-7D-C7-BD-F2:eduroam'
         Calling-Station-Id = '80-EA-96-AD-CA-E3'
         Framed-MTU = 1400
         NAS-Port-Type = Wireless-802.11
         Connect-Info = 'CONNECT 28Mbps/1Mbps 802.11n'
         EAP-Message = 
0x020c002b19001703010020ef84b95ede65e49ded032fd66b6bdafc81ed37235630c269c9885ecdced372d5
         State = 0x1e66753c156a6c9510f0431d79ab79e0
         Message-Authenticator = 0xd314db0076e4a7e688ef1a0c3f018b94
         Proxy-State = 0x3131
         Stripped-User-Name = 'user294'
         User-Name = 'user294 at uni-wuppertal.de'
(2148)  eap : Freeing handler
(2148)   [eap] = ok
(2148)  } #  authenticate = ok
(2148) Login OK: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 744 cli 80-EA-96-AD-CA-E3)
(2148) # Executing section post-auth from file 
/etc/freeradius/sites-enabled/default
(2148)   post-auth {
(2148)   remove_reply_message_if_eap remove_reply_message_if_eap {
(2148)     if (reply:EAP-Message && reply:Reply-Message)
(2148)     if (reply:EAP-Message && reply:Reply-Message) -> FALSE
(2148)    else else {
(2148)     [noop] = noop
(2148)    } # else else = noop
(2148)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(2148)   update reply {
(2148)  Tunnel-Type := VLAN
(2148)  Tunnel-Medium-Type := IEEE-802
(2148)  Tunnel-Private-Group-Id := 'eduroam'
(2148)   } # update reply = noop
(2148)  } #  post-auth = noop
(2148) Finished request


example "No EAP session matching state"

(3039) # Executing section authorize from file 
/etc/freeradius/sites-enabled/default
(3039)   authorize {
(3039)   filter_username filter_username {
(3039)     if (!User-Name)
(3039)     if (!User-Name)  -> FALSE
(3039)     if (User-Name =~ / /)
(3039)     if (User-Name =~ / /)  -> FALSE
(3039)     if (User-Name =~ /@.*@/ )
(3039)     if (User-Name =~ /@.*@/ )  -> FALSE
(3039)     if (User-Name =~ /\\.\\./ )
Waking up in 0.3 seconds.
(3039)     if (User-Name =~ /\\.\\./ )  -> FALSE
(3039)     if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/))
(3039)     if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/)) 
-> FALSE
(3039)     if (User-Name =~ /\\.$/)
(3039)     if (User-Name =~ /\\.$/)   -> FALSE
(3039)     if (User-Name =~ /@\\./)
(3039)     if (User-Name =~ /@\\./)   -> FALSE
(3039)   } # filter_username filter_username = notfound
(3039)    if ( User-Name && ( User-Name !~ 
/^([a-z0-9._-]+)@([a-z0-9._-]+)[.]([a-z]{2,4})$/i ) || ( User-Name =~ 
/@wlan\\.[[:alnum:]]+\\.[[:alnum:]]+\\.3gppnetwork\\.org$/i ) )
(3039)    if ( User-Name && ( User-Name !~ 
/^([a-z0-9._-]+)@([a-z0-9._-]+)[.]([a-z]{2,4})$/i ) || ( User-Name =~ 
/@wlan\\.[[:alnum:]]+\\.[[:alnum:]]+\\.3gppnetwork\\.org$/i ) ) -> FALSE
(3039)   [preprocess] = ok
(3039)  suffix : Looking up realm "uni-wuppertal.de" for User-Name = 
"user294 at uni-wuppertal.de"
(3039)  suffix : Found realm "uni-wuppertal.de"
(3039)  suffix : Adding Stripped-User-Name = "user294"
(3039)  suffix : Adding Realm = "uni-wuppertal.de"
(3039)  suffix : Authentication realm is LOCAL
(3039)   [suffix] = ok
(3039)  eap : EAP packet type response id 9 length 6
(3039)  eap : Continuing tunnel setup
(3039)   [eap] = ok
(3039)  } #  authorize = ok
(3039) Found Auth-Type = EAP
(3039) # Executing group from file /etc/freeradius/sites-enabled/default
(3039)   authenticate {
(3039)  eap : Expiring EAP session with state 0x048451e3058748ec
rlm_eap (EAP): No EAP session matching state 0x893a58798e334141
(3039)  eap : Either EAP-request timed out OR EAP-response to an unknown 
EAP-request
(3039)  eap : Failed in handler
(3039)   [eap] = invalid
(3039)  } #  authenticate = invalid
(3039) Failed to authenticate the user
(3039) Login incorrect: [user294 at uni-wuppertal.de] (from client 
radius2.eduroam.xy port 21118 cli 80-EA-96-AD-CA-E3)
(3039) Using Post-Auth-Type Reject
(3039) # Executing group from file /etc/freeradius/sites-enabled/default
(3039)  Post-Auth-Type REJECT {
(3039)  attr_filter.access_reject : EXPAND %{User-Name}
(3039)  attr_filter.access_reject :    --> user294 at uni-wuppertal.de
(3039)  attr_filter.access_reject : Matched entry DEFAULT at line 11
(3039)   [attr_filter.access_reject] = updated
(3039)  eap : Expiring EAP session with state 0x048451e3058748ec
rlm_eap (EAP): No EAP session matching state 0x893a58798e334141
(3039)  eap : Either EAP-request timed out OR EAP-response to an unknown 
EAP-request
(3039)  eap : Failed to get handler, probably already removed, not 
inserting EAP-Failure
(3039)   [eap] = noop
(3039)   remove_reply_message_if_eap remove_reply_message_if_eap {
(3039)     if (reply:EAP-Message && reply:Reply-Message)
(3039)     if (reply:EAP-Message && reply:Reply-Message) -> FALSE
(3039)    else else {
(3039)     [noop] = noop
(3039)    } # else else = noop
(3039)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(3039)  } # Post-Auth-Type REJECT = updated
(3039) Delaying response for 1 seconds
Thread 5 waiting to be assigned a request
Waking up in 0.6 seconds.
(3039) Sending delayed response
Waking up in 3.9 seconds.
(3039) Cleaning up request packet ID 4 with timestamp +3458


another user with "No EAP session matching state"


(2925) # Executing section authorize from file 
/etc/freeradius/sites-enabled/default
(2925)   authorize {
(2925)   filter_username filter_username {
(2925)     if (!User-Name)
(2925)     if (!User-Name)  -> FALSE
(2925)     if (User-Name =~ / /)
(2925)     if (User-Name =~ / /)  -> FALSE
(2925)     if (User-Name =~ /@.*@/ )
(2925)     if (User-Name =~ /@.*@/ )  -> FALSE
(2925)     if (User-Name =~ /\\.\\./ )
(2925)     if (User-Name =~ /\\.\\./ )  -> FALSE
(2925)     if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/))
(2925)     if ((User-Name =~ /@/) && (User-Name !~ /@(.+)\\.(.+)$/)) 
-> FALSE
(2925)     if (User-Name =~ /\\.$/)
(2925)     if (User-Name =~ /\\.$/)   -> FALSE
(2925)     if (User-Name =~ /@\\./)
(2925)     if (User-Name =~ /@\\./)   -> FALSE
(2925)   } # filter_username filter_username = notfound
(2925)    if ( User-Name && ( User-Name !~ 
/^([a-z0-9._-]+)@([a-z0-9._-]+)[.]([a-z]{2,4})$/i ) || ( User-Name =~ 
/@wlan\\.[[:alnum:]]+\\.[[:alnum:]]+\\.3gppnetwork\\.org$/i ) )
(2925)    if ( User-Name && ( User-Name !~ 
/^([a-z0-9._-]+)@([a-z0-9._-]+)[.]([a-z]{2,4})$/i ) || ( User-Name =~ 
/@wlan\\.[[:alnum:]]+\\.[[:alnum:]]+\\.3gppnetwork\\.org$/i ) ) -> FALSE
(2925)   [preprocess] = ok
(2925)  suffix : Looking up realm "uni-wuppertal.de" for User-Name = 
"user940 at uni-wuppertal.de"
(2925)  suffix : Found realm "uni-wuppertal.de"
(2925)  suffix : Adding Stripped-User-Name = "user940"
(2925)  suffix : Adding Realm = "uni-wuppertal.de"
(2925)  suffix : Authentication realm is LOCAL
(2925)   [suffix] = ok
(2925)  eap : EAP packet type response id 6 length 6
(2925)  eap : Continuing tunnel setup
(2925)   [eap] = ok
(2925)  } #  authorize = ok
(2925) Found Auth-Type = EAP
(2925) # Executing group from file /etc/freeradius/sites-enabled/default
(2925)   authenticate {
(2925)  eap : Expiring EAP session with state 0xc2b31edcc2b10778
rlm_eap (EAP): No EAP session matching state 0xea2b54dbee2d4d20
(2925)  eap : Either EAP-request timed out OR EAP-response to an unknown 
EAP-request
(2925)  eap : Failed in handler
(2925)   [eap] = invalid
(2925)  } #  authenticate = invalid
(2925) Failed to authenticate the user
(2925) Login incorrect: [user940 at uni-wuppertal.de] (from client 
radius1.eduroam.xy port 13 cli 58:1f:aa:a5:7f:1a)
(2925) Using Post-Auth-Type Reject
(2925) # Executing group from file /etc/freeradius/sites-enabled/default
(2925)  Post-Auth-Type REJECT {
(2925)  attr_filter.access_reject : EXPAND %{User-Name}
(2925)  attr_filter.access_reject :    --> user940 at uni-wuppertal.de
(2925)  attr_filter.access_reject : Matched entry DEFAULT at line 11
(2925)   [attr_filter.access_reject] = updated
(2925)  eap : Expiring EAP session with state 0xc2b31edcc2b10778
rlm_eap (EAP): No EAP session matching state 0xea2b54dbee2d4d20
(2925)  eap : Either EAP-request timed out OR EAP-response to an unknown 
EAP-request
(2925)  eap : Failed to get handler, probably already removed, not 
inserting EAP-Failure
(2925)   [eap] = noop
(2925)   remove_reply_message_if_eap remove_reply_message_if_eap {
(2925)     if (reply:EAP-Message && reply:Reply-Message)
(2925)     if (reply:EAP-Message && reply:Reply-Message) -> FALSE
(2925)    else else {
(2925)     [noop] = noop
(2925)    } # else else = noop
(2925)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(2925)  } # Post-Auth-Type REJECT = updated
(2925) Delaying response for 1 seconds
Thread 3 waiting to be assigned a request
Waking up in 0.7 seconds.
(2925) Sending delayed response