EAP through proxy not working

6 Sep 2016

      I am trying to proxy eap requests from my wireless users (Cisco 5500 controller) but I'm getting error messages. When I point the controller directly at the radius server and not the proxy, it works fine. Here's the debug from the back-end radius server, I can give the proxy debug too, if necessary. I'm sure the answer I'm  missing is somewhere in this section:

<snip>
(8) Found Auth-Type = EAP
(8) # Executing group from file /etc/raddb/sites-enabled/default
(8)   authenticate {
rlm_eap (EAP): No EAP session matching state 0x8acdf80a8acffcab
(8)  eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
(8)  eap : Failed in handler
(8)   [eap] = invalid
(8)  } #  authenticate = invalid
(8) Failed to authenticate the user
(8) Login incorrect: [sgardne] (from client radproxy01.uark.edu port 4 cli 88:63:df:a5:2a:c7)
</snip>

Full debug here:

Received Access-Request Id 19 from 10.7.0.28:32775 to 10.7.0.29:1812 length 315
	User-Name = 'myUsername'
	Chargeable-User-Identity = 0x00
	Location-Capable = Civix-Location
	Calling-Station-Id = '22:44:66:88:00:11'
	Called-Station-Id = '00:22:11:44:33:66:mySite Test'
	NAS-Port = 4
	Cisco-AVPair = 'audit-session-id=1300fa0a011b7b5a57cece57'
	Acct-Session-Id = '57cece57/22:44:66:88:00:11/12055956'
	Cisco-AVPair = 'mDNS=true'
	NAS-IP-Address = 10.0.0.19
	NAS-Identifier = 'Red 8510'
	Airespace-Wlan-Id = 8
	Service-Type = Framed-User
	Framed-MTU = 1300
	NAS-Port-Type = Wireless-802.11
	Tunnel-Type:0 = VLAN
	Tunnel-Medium-Type:0 = IEEE-802
	Tunnel-Private-Group-Id:0 = '477'
	EAP-Message = 0x020900080319152b
	State = 0xad99bf40ad90bb81ebfc470b102b754e
	Message-Authenticator = 0x6951ea386bc9c4de5deb4c75ad04312e
	Event-Timestamp = 'Sep  6 2016 09:10:46 CDT'
	Proxy-State = 0x313234
(5) Received Access-Request packet from host 10.7.0.28 port 32775, id=19, length=315
(5) 	User-Name = 'myUsername'
(5) 	Chargeable-User-Identity = 0x00
(5) 	Location-Capable = Civix-Location
(5) 	Calling-Station-Id = '22:44:66:88:00:11'
(5) 	Called-Station-Id = '00:22:11:44:33:66:mySite Test'
(5) 	NAS-Port = 4
(5) 	Cisco-AVPair = 'audit-session-id=1300fa0a011b7b5a57cece57'
(5) 	Acct-Session-Id = '57cece57/22:44:66:88:00:11/12055956'
(5) 	Cisco-AVPair = 'mDNS=true'
(5) 	NAS-IP-Address = 10.0.0.19
(5) 	NAS-Identifier = 'Red 8510'
(5) 	Airespace-Wlan-Id = 8
(5) 	Service-Type = Framed-User
(5) 	Framed-MTU = 1300
(5) 	NAS-Port-Type = Wireless-802.11
(5) 	Tunnel-Type:0 = VLAN
(5) 	Tunnel-Medium-Type:0 = IEEE-802
(5) 	Tunnel-Private-Group-Id:0 = '477'
(5) 	EAP-Message = 0x020900080319152b
(5) 	State = 0xad99bf40ad90bb81ebfc470b102b754e
(5) 	Message-Authenticator = 0x6951ea386bc9c4de5deb4c75ad04312e
(5) 	Event-Timestamp = 'Sep  6 2016 09:10:46 CDT'
(5) 	Proxy-State = 0x313234
(5) # Executing section authorize from file /etc/raddb/sites-enabled/default
(5)   authorize {
(5)   filter_username filter_username {
(5)     if (!&User-Name) 
(5)     if (!&User-Name)  -> FALSE
(5)     if (&User-Name =~ / /) 
(5)     if (&User-Name =~ / /)  -> FALSE
(5)     if (&User-Name =~ /@.*@/ ) 
(5)     if (&User-Name =~ /@.*@/ )  -> FALSE
(5)     if (&User-Name =~ /\\.\\./ ) 
(5)     if (&User-Name =~ /\\.\\./ )  -> FALSE
(5)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))  
(5)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))   -> FALSE
(5)     if (&User-Name =~ /\\.$/)  
(5)     if (&User-Name =~ /\\.$/)   -> FALSE
(5)     if (&User-Name =~ /@\\./)  
(5)     if (&User-Name =~ /@\\./)   -> FALSE
(5)   } # filter_username filter_username = notfound
(5)   [preprocess] = ok
(5)  auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
(5)  auth_log :    --> /var/log/radius/radacct/10.7.0.28/auth-detail-20160906
(5)  auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/10.7.0.28/auth-detail-20160906
(5)  auth_log : EXPAND %t
(5)  auth_log :    --> Tue Sep  6 09:10:46 2016
(5)   [auth_log] = ok
(5)   [mschap] = noop
(5)  suffix : Checking for suffix after "@"
(5)  suffix : No '@' in User-Name = "myUsername", looking up realm NULL
(5)  suffix : No such realm "NULL"
(5)   [suffix] = noop
(5)  eap : Peer sent code Response (2) ID 9 length 8
(5)  eap : No EAP Start, assuming it's an on-going EAP conversation
(5)   [eap] = updated
rlm_ldap (ldap): Reserved connection (8)
(5)  ldap : EXPAND (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})
(5)  ldap :    --> (sAMAccountName=myUsername)
(5)  ldap : EXPAND dc=mySite,dc=org
(5)  ldap :    --> dc=mySite,dc=org
(5)  ldap : Performing search in 'dc=mySite,dc=org' with filter '(sAMAccountName=myUsername)', scope 'sub'
(5)  ldap : Waiting for search result...
Unable to chase referral "ldaps://walton.mySite.org/DC=walton,DC=mySite,DC=org" (-1: Can't contact LDAP server)
Unable to chase referral "ldaps://cast.mySite.org/DC=cast,DC=mySite,DC=org" (-1: Can't contact LDAP server)
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://ForestDnsZones.mySite.org/DC=ForestDnsZones,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://DomainDnsZones.mySite.org/DC=DomainDnsZones,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://mySite.org/CN=Configuration,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
(5)  ldap : User object found at DN "CN=myUsername,OU=mySiteUsers,DC=mySite,DC=org"
(5)  ldap : Processing user attributes
(5)  WARNING: ldap : No "known good" password added. Ensure the admin user has permission to read the password attribute
(5)  WARNING: ldap : PAP authentication will *NOT* work with Active Directory (if that is what you were trying to configure)
rlm_ldap (ldap): Deleting connection (8)
rlm_ldap (ldap): 0 of 3 connections in use.  Need more spares
rlm_ldap (ldap): Opening additional connection (9)
rlm_ldap (ldap): Connecting to adServer01.mySite.org:636
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
(5)   [ldap] = ok
(5)   [expiration] = noop
(5)   [logintime] = noop
(5)  WARNING: pap : No "known good" password found for the user.  Not setting Auth-Type
(5)  WARNING: pap : Authentication will fail unless a "known good" password is available
(5)   [pap] = noop
(5)  } #  authorize = updated
(5) Found Auth-Type = EAP
(5) # Executing group from file /etc/raddb/sites-enabled/default
(5)   authenticate {
rlm_eap (EAP): No EAP session matching state 0xad99bf40ad90bb81
(5)  eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
(5)  eap : Failed in handler
(5)   [eap] = invalid
(5)  } #  authenticate = invalid
(5) Failed to authenticate the user
(5) Login incorrect: [myUsername] (from client radproxy01.mySite.org port 4 cli 22:44:66:88:00:11)
(5) Using Post-Auth-Type Reject
(5) # Executing group from file /etc/raddb/sites-enabled/default
(5)  Post-Auth-Type REJECT {
(5)  attr_filter.access_reject : EXPAND %{User-Name}
(5)  attr_filter.access_reject :    --> myUsername
(5)  attr_filter.access_reject : Matched entry DEFAULT at line 11
(5)   [attr_filter.access_reject] = updated
rlm_eap (EAP): No EAP session matching state 0xad99bf40ad90bb81
(5)  eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
(5)  eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(5)   [eap] = noop
(5)   remove_reply_message_if_eap remove_reply_message_if_eap {
(5)     if (&reply:EAP-Message && &reply:Reply-Message) 
(5)     if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
(5)    else else {
(5)     [noop] = noop
(5)    } # else else = noop
(5)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(5)  } # Post-Auth-Type REJECT = updated
(5) Delaying response for 1 seconds
Waking up in 0.9 seconds.
Received Access-Request Id 19 from 10.7.0.28:32775 to 10.7.0.29:1812 length 315
(5) Discarding duplicate request from client radproxy01.mySite.org port 32775 - ID: 19 due to delayed response
(5) Sending delayed response
(5) Sending Access-Reject packet to host 10.7.0.28 port 32775, id=19, length=0
(5) 	Proxy-State = 0x313234
Sending Access-Reject Id 19 from 10.7.0.29:1812 to 10.7.0.28:32775
	Proxy-State = 0x313234
Waking up in 3.9 seconds.
Received Access-Request Id 242 from 10.7.0.28:32775 to 10.7.0.29:1812 length 315
	User-Name = 'myUsername'
	Chargeable-User-Identity = 0x00
	Location-Capable = Civix-Location
	Calling-Station-Id = '22:44:66:88:00:11'
	Called-Station-Id = '00:22:11:44:33:66:mySite Test'
	NAS-Port = 4
	Cisco-AVPair = 'audit-session-id=1300fa0a011b7b5a57cece57'
	Acct-Session-Id = '57cece57/22:44:66:88:00:11/12055956'
	Cisco-AVPair = 'mDNS=true'
	NAS-IP-Address = 10.0.0.19
	NAS-Identifier = 'Red 8510'
	Airespace-Wlan-Id = 8
	Service-Type = Framed-User
	Framed-MTU = 1300
	NAS-Port-Type = Wireless-802.11
	Tunnel-Type:0 = VLAN
	Tunnel-Medium-Type:0 = IEEE-802
	Tunnel-Private-Group-Id:0 = '477'
	EAP-Message = 0x020f00080319152b
	State = 0xbc6406acbc6b02b16e73611e9c1c8af8
	Message-Authenticator = 0x88428ea4082430ec78f14d881ffae5c9
	Event-Timestamp = 'Sep  6 2016 09:10:50 CDT'
	Proxy-State = 0x313238
(6) Received Access-Request packet from host 10.7.0.28 port 32775, id=242, length=315
(6) 	User-Name = 'myUsername'
(6) 	Chargeable-User-Identity = 0x00
(6) 	Location-Capable = Civix-Location
(6) 	Calling-Station-Id = '22:44:66:88:00:11'
(6) 	Called-Station-Id = '00:22:11:44:33:66:mySite Test'
(6) 	NAS-Port = 4
(6) 	Cisco-AVPair = 'audit-session-id=1300fa0a011b7b5a57cece57'
(6) 	Acct-Session-Id = '57cece57/22:44:66:88:00:11/12055956'
(6) 	Cisco-AVPair = 'mDNS=true'
(6) 	NAS-IP-Address = 10.0.0.19
(6) 	NAS-Identifier = 'Red 8510'
(6) 	Airespace-Wlan-Id = 8
(6) 	Service-Type = Framed-User
(6) 	Framed-MTU = 1300
(6) 	NAS-Port-Type = Wireless-802.11
(6) 	Tunnel-Type:0 = VLAN
(6) 	Tunnel-Medium-Type:0 = IEEE-802
(6) 	Tunnel-Private-Group-Id:0 = '477'
(6) 	EAP-Message = 0x020f00080319152b
(6) 	State = 0xbc6406acbc6b02b16e73611e9c1c8af8
(6) 	Message-Authenticator = 0x88428ea4082430ec78f14d881ffae5c9
(6) 	Event-Timestamp = 'Sep  6 2016 09:10:50 CDT'
(6) 	Proxy-State = 0x313238
(6) # Executing section authorize from file /etc/raddb/sites-enabled/default
(6)   authorize {
(6)   filter_username filter_username {
(6)     if (!&User-Name) 
(6)     if (!&User-Name)  -> FALSE
(6)     if (&User-Name =~ / /) 
(6)     if (&User-Name =~ / /)  -> FALSE
(6)     if (&User-Name =~ /@.*@/ ) 
(6)     if (&User-Name =~ /@.*@/ )  -> FALSE
(6)     if (&User-Name =~ /\\.\\./ ) 
(6)     if (&User-Name =~ /\\.\\./ )  -> FALSE
(6)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))  
(6)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))   -> FALSE
(6)     if (&User-Name =~ /\\.$/)  
(6)     if (&User-Name =~ /\\.$/)   -> FALSE
(6)     if (&User-Name =~ /@\\./)  
(6)     if (&User-Name =~ /@\\./)   -> FALSE
(6)   } # filter_username filter_username = notfound
(6)   [preprocess] = ok
(6)  auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
(6)  auth_log :    --> /var/log/radius/radacct/10.7.0.28/auth-detail-20160906
(6)  auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/10.7.0.28/auth-detail-20160906
(6)  auth_log : EXPAND %t
(6)  auth_log :    --> Tue Sep  6 09:10:50 2016
(6)   [auth_log] = ok
(6)   [mschap] = noop
(6)  suffix : Checking for suffix after "@"
(6)  suffix : No '@' in User-Name = "myUsername", looking up realm NULL
(6)  suffix : No such realm "NULL"
(6)   [suffix] = noop
(6)  eap : Peer sent code Response (2) ID 15 length 8
(6)  eap : No EAP Start, assuming it's an on-going EAP conversation
(6)   [eap] = updated
rlm_ldap (ldap): Reserved connection (9)
(6)  ldap : EXPAND (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})
(6)  ldap :    --> (sAMAccountName=myUsername)
(6)  ldap : EXPAND dc=mySite,dc=org
(6)  ldap :    --> dc=mySite,dc=org
(6)  ldap : Performing search in 'dc=mySite,dc=org' with filter '(sAMAccountName=myUsername)', scope 'sub'
(6)  ldap : Waiting for search result...
Unable to chase referral "ldaps://walton.mySite.org/DC=walton,DC=mySite,DC=org" (-1: Can't contact LDAP server)
Unable to chase referral "ldaps://cast.mySite.org/DC=cast,DC=mySite,DC=org" (-1: Can't contact LDAP server)
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://ForestDnsZones.mySite.org/DC=ForestDnsZones,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://DomainDnsZones.mySite.org/DC=DomainDnsZones,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://mySite.org/CN=Configuration,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
(6)  ldap : User object found at DN "CN=myUsername,OU=mySiteUsers,DC=mySite,DC=org"
(6)  ldap : Processing user attributes
(6)  WARNING: ldap : No "known good" password added. Ensure the admin user has permission to read the password attribute
(6)  WARNING: ldap : PAP authentication will *NOT* work with Active Directory (if that is what you were trying to configure)
rlm_ldap (ldap): Deleting connection (9)
rlm_ldap (ldap): 0 of 3 connections in use.  Need more spares
rlm_ldap (ldap): Opening additional connection (10)
rlm_ldap (ldap): Connecting to adServer01.mySite.org:636
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
(6)   [ldap] = ok
(6)   [expiration] = noop
(6)   [logintime] = noop
(6)  WARNING: pap : No "known good" password found for the user.  Not setting Auth-Type
(6)  WARNING: pap : Authentication will fail unless a "known good" password is available
(6)   [pap] = noop
(6)  } #  authorize = updated
(6) Found Auth-Type = EAP
(6) # Executing group from file /etc/raddb/sites-enabled/default
(6)   authenticate {
rlm_eap (EAP): No EAP session matching state 0xbc6406acbc6b02b1
(6)  eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
(6)  eap : Failed in handler
(6)   [eap] = invalid
(6)  } #  authenticate = invalid
(6) Failed to authenticate the user
(6) Login incorrect: [myUsername] (from client radproxy01.mySite.org port 4 cli 22:44:66:88:00:11)
(6) Using Post-Auth-Type Reject
(6) # Executing group from file /etc/raddb/sites-enabled/default
(6)  Post-Auth-Type REJECT {
(6)  attr_filter.access_reject : EXPAND %{User-Name}
(6)  attr_filter.access_reject :    --> myUsername
(6)  attr_filter.access_reject : Matched entry DEFAULT at line 11
(6)   [attr_filter.access_reject] = updated
rlm_eap (EAP): No EAP session matching state 0xbc6406acbc6b02b1
(6)  eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
(6)  eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(6)   [eap] = noop
(6)   remove_reply_message_if_eap remove_reply_message_if_eap {
(6)     if (&reply:EAP-Message && &reply:Reply-Message) 
(6)     if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
(6)    else else {
(6)     [noop] = noop
(6)    } # else else = noop
(6)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(6)  } # Post-Auth-Type REJECT = updated
(6) Delaying response for 1 seconds
Received Access-Request Id 6 from 10.7.0.28:32775 to 10.7.0.29:1812 length 315
	User-Name = 'myUsername'
	Chargeable-User-Identity = 0x00
	Location-Capable = Civix-Location
	Calling-Station-Id = '22:44:66:88:00:11'
	Called-Station-Id = '00:22:11:44:33:66:mySite Test'
	NAS-Port = 4
	Cisco-AVPair = 'audit-session-id=1300fa0a011b7b5a57cece57'
	Acct-Session-Id = '57cece57/22:44:66:88:00:11/12055956'
	Cisco-AVPair = 'mDNS=true'
	NAS-IP-Address = 10.0.0.19
	NAS-Identifier = 'Red 8510'
	Airespace-Wlan-Id = 8
	Service-Type = Framed-User
	Framed-MTU = 1300
	NAS-Port-Type = Wireless-802.11
	Tunnel-Type:0 = VLAN
	Tunnel-Medium-Type:0 = IEEE-802
	Tunnel-Private-Group-Id:0 = '477'
	EAP-Message = 0x020c00080319152b
	State = 0x023da4930231a0622bbcbfb8ac594c59
	Message-Authenticator = 0x20a6424d738dd104865b66aa51f1af3e
	Event-Timestamp = 'Sep  6 2016 09:10:51 CDT'
	Proxy-State = 0x313236
(7) Received Access-Request packet from host 10.7.0.28 port 32775, id=6, length=315
(7) 	User-Name = 'myUsername'
(7) 	Chargeable-User-Identity = 0x00
(7) 	Location-Capable = Civix-Location
(7) 	Calling-Station-Id = '22:44:66:88:00:11'
(7) 	Called-Station-Id = '00:22:11:44:33:66:mySite Test'
(7) 	NAS-Port = 4
(7) 	Cisco-AVPair = 'audit-session-id=1300fa0a011b7b5a57cece57'
(7) 	Acct-Session-Id = '57cece57/22:44:66:88:00:11/12055956'
(7) 	Cisco-AVPair = 'mDNS=true'
(7) 	NAS-IP-Address = 10.0.0.19
(7) 	NAS-Identifier = 'Red 8510'
(7) 	Airespace-Wlan-Id = 8
(7) 	Service-Type = Framed-User
(7) 	Framed-MTU = 1300
(7) 	NAS-Port-Type = Wireless-802.11
(7) 	Tunnel-Type:0 = VLAN
(7) 	Tunnel-Medium-Type:0 = IEEE-802
(7) 	Tunnel-Private-Group-Id:0 = '477'
(7) 	EAP-Message = 0x020c00080319152b
(7) 	State = 0x023da4930231a0622bbcbfb8ac594c59
(7) 	Message-Authenticator = 0x20a6424d738dd104865b66aa51f1af3e
(7) 	Event-Timestamp = 'Sep  6 2016 09:10:51 CDT'
(7) 	Proxy-State = 0x313236
(7) # Executing section authorize from file /etc/raddb/sites-enabled/default
(7)   authorize {
(7)   filter_username filter_username {
(7)     if (!&User-Name) 
(7)     if (!&User-Name)  -> FALSE
(7)     if (&User-Name =~ / /) 
(7)     if (&User-Name =~ / /)  -> FALSE
(7)     if (&User-Name =~ /@.*@/ ) 
(7)     if (&User-Name =~ /@.*@/ )  -> FALSE
(7)     if (&User-Name =~ /\\.\\./ ) 
(7)     if (&User-Name =~ /\\.\\./ )  -> FALSE
(7)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))  
(7)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))   -> FALSE
(7)     if (&User-Name =~ /\\.$/)  
(7)     if (&User-Name =~ /\\.$/)   -> FALSE
(7)     if (&User-Name =~ /@\\./)  
(7)     if (&User-Name =~ /@\\./)   -> FALSE
(7)   } # filter_username filter_username = notfound
(7)   [preprocess] = ok
(7)  auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
(7)  auth_log :    --> /var/log/radius/radacct/10.7.0.28/auth-detail-20160906
(7)  auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/10.7.0.28/auth-detail-20160906
(7)  auth_log : EXPAND %t
(7)  auth_log :    --> Tue Sep  6 09:10:51 2016
(7)   [auth_log] = ok
(7)   [mschap] = noop
(7)  suffix : Checking for suffix after "@"
(7)  suffix : No '@' in User-Name = "myUsername", looking up realm NULL
(7)  suffix : No such realm "NULL"
(7)   [suffix] = noop
(7)  eap : Peer sent code Response (2) ID 12 length 8
(7)  eap : No EAP Start, assuming it's an on-going EAP conversation
(7)   [eap] = updated
rlm_ldap (ldap): Reserved connection (10)
(7)  ldap : EXPAND (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})
(7)  ldap :    --> (sAMAccountName=myUsername)
(7)  ldap : EXPAND dc=mySite,dc=org
(7)  ldap :    --> dc=mySite,dc=org
(7)  ldap : Performing search in 'dc=mySite,dc=org' with filter '(sAMAccountName=myUsername)', scope 'sub'
(7)  ldap : Waiting for search result...
Unable to chase referral "ldaps://walton.mySite.org/DC=walton,DC=mySite,DC=org" (-1: Can't contact LDAP server)
Unable to chase referral "ldaps://cast.mySite.org/DC=cast,DC=mySite,DC=org" (-1: Can't contact LDAP server)
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://ForestDnsZones.mySite.org/DC=ForestDnsZones,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://DomainDnsZones.mySite.org/DC=DomainDnsZones,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://mySite.org/CN=Configuration,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
(7)  ldap : User object found at DN "CN=myUsername,OU=mySiteUsers,DC=mySite,DC=org"
(7)  ldap : Processing user attributes
(7)  WARNING: ldap : No "known good" password added. Ensure the admin user has permission to read the password attribute
(7)  WARNING: ldap : PAP authentication will *NOT* work with Active Directory (if that is what you were trying to configure)
rlm_ldap (ldap): Deleting connection (10)
rlm_ldap (ldap): 0 of 3 connections in use.  Need more spares
rlm_ldap (ldap): Opening additional connection (11)
rlm_ldap (ldap): Connecting to adServer01.mySite.org:636
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
(7)   [ldap] = ok
(7)   [expiration] = noop
(7)   [logintime] = noop
(7)  WARNING: pap : No "known good" password found for the user.  Not setting Auth-Type
(7)  WARNING: pap : Authentication will fail unless a "known good" password is available
(7)   [pap] = noop
(7)  } #  authorize = updated
(7) Found Auth-Type = EAP
(7) # Executing group from file /etc/raddb/sites-enabled/default
(7)   authenticate {
rlm_eap (EAP): No EAP session matching state 0x023da4930231a062
(7)  eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
(7)  eap : Failed in handler
(7)   [eap] = invalid
(7)  } #  authenticate = invalid
(7) Failed to authenticate the user
(7) Login incorrect: [myUsername] (from client radproxy01.mySite.org port 4 cli 22:44:66:88:00:11)
(7) Using Post-Auth-Type Reject
(7) # Executing group from file /etc/raddb/sites-enabled/default
(7)  Post-Auth-Type REJECT {
(7)  attr_filter.access_reject : EXPAND %{User-Name}
(7)  attr_filter.access_reject :    --> myUsername
(7)  attr_filter.access_reject : Matched entry DEFAULT at line 11
(7)   [attr_filter.access_reject] = updated
rlm_eap (EAP): No EAP session matching state 0x023da4930231a062
(7)  eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
(7)  eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(7)   [eap] = noop
(7)   remove_reply_message_if_eap remove_reply_message_if_eap {
(7)     if (&reply:EAP-Message && &reply:Reply-Message) 
(7)     if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
(7)    else else {
(7)     [noop] = noop
(7)    } # else else = noop
(7)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(7)  } # Post-Auth-Type REJECT = updated
(7) Delaying response for 1 seconds
(6) Sending delayed response
(6) Sending Access-Reject packet to host 10.7.0.28 port 32775, id=242, length=0
(6) 	Proxy-State = 0x313238
Sending Access-Reject Id 242 from 10.7.0.29:1812 to 10.7.0.28:32775
	Proxy-State = 0x313238
(5) Cleaning up request packet ID 19 with timestamp +359
Received Access-Request Id 242 from 10.7.0.28:32775 to 10.7.0.29:1812 length 315
Sending Access-Reject Id 242 from 10.7.0.29:1812 to 10.7.0.28:32775
	Proxy-State = 0x313238
Waking up in 0.9 seconds.
Received Access-Request Id 6 from 10.7.0.28:32775 to 10.7.0.29:1812 length 315
(7) Discarding duplicate request from client radproxy01.mySite.org port 32775 - ID: 6 due to delayed response
Waking up in 0.1 seconds.
(7) Sending delayed response
(7) Sending Access-Reject packet to host 10.7.0.28 port 32775, id=6, length=0
(7) 	Proxy-State = 0x313236
Sending Access-Reject Id 6 from 10.7.0.29:1812 to 10.7.0.28:32775
	Proxy-State = 0x313236
Waking up in 3.9 seconds.
(7) Cleaning up request packet ID 6 with timestamp +364
Waking up in 1999658.5 seconds.
Received Access-Request Id 110 from 10.7.0.28:32775 to 10.7.0.29:1812 length 315
	User-Name = 'myUsername'
	Chargeable-User-Identity = 0x00
	Location-Capable = Civix-Location
	Calling-Station-Id = '22:44:66:88:00:11'
	Called-Station-Id = '00:22:11:44:33:66:mySite Test'
	NAS-Port = 4
	Cisco-AVPair = 'audit-session-id=1300fa0a011b7b5a57cece57'
	Acct-Session-Id = '57cece57/22:44:66:88:00:11/12055956'
	Cisco-AVPair = 'mDNS=true'
	NAS-IP-Address = 10.0.0.19
	NAS-Identifier = 'Red 8510'
	Airespace-Wlan-Id = 8
	Service-Type = Framed-User
	Framed-MTU = 1300
	NAS-Port-Type = Wireless-802.11
	Tunnel-Type:0 = VLAN
	Tunnel-Medium-Type:0 = IEEE-802
	Tunnel-Private-Group-Id:0 = '477'
	EAP-Message = 0x020200080319152b
	State = 0x8acdf80a8acffcabc84459d3446a7597
	Message-Authenticator = 0xcbc7ca966e6720ceb5bb735d7c76d697
	Event-Timestamp = 'Sep  6 2016 09:11:00 CDT'
	Proxy-State = 0x313330
(8) Received Access-Request packet from host 10.7.0.28 port 32775, id=110, length=315
(8) 	User-Name = 'myUsername'
(8) 	Chargeable-User-Identity = 0x00
(8) 	Location-Capable = Civix-Location
(8) 	Calling-Station-Id = '22:44:66:88:00:11'
(8) 	Called-Station-Id = '00:22:11:44:33:66:mySite Test'
(8) 	NAS-Port = 4
(8) 	Cisco-AVPair = 'audit-session-id=1300fa0a011b7b5a57cece57'
(8) 	Acct-Session-Id = '57cece57/22:44:66:88:00:11/12055956'
(8) 	Cisco-AVPair = 'mDNS=true'
(8) 	NAS-IP-Address = 10.0.0.19
(8) 	NAS-Identifier = 'Red 8510'
(8) 	Airespace-Wlan-Id = 8
(8) 	Service-Type = Framed-User
(8) 	Framed-MTU = 1300
(8) 	NAS-Port-Type = Wireless-802.11
(8) 	Tunnel-Type:0 = VLAN
(8) 	Tunnel-Medium-Type:0 = IEEE-802
(8) 	Tunnel-Private-Group-Id:0 = '477'
(8) 	EAP-Message = 0x020200080319152b
(8) 	State = 0x8acdf80a8acffcabc84459d3446a7597
(8) 	Message-Authenticator = 0xcbc7ca966e6720ceb5bb735d7c76d697
(8) 	Event-Timestamp = 'Sep  6 2016 09:11:00 CDT'
(8) 	Proxy-State = 0x313330
(8) # Executing section authorize from file /etc/raddb/sites-enabled/default
(8)   authorize {
(8)   filter_username filter_username {
(8)     if (!&User-Name) 
(8)     if (!&User-Name)  -> FALSE
(8)     if (&User-Name =~ / /) 
(8)     if (&User-Name =~ / /)  -> FALSE
(8)     if (&User-Name =~ /@.*@/ ) 
(8)     if (&User-Name =~ /@.*@/ )  -> FALSE
(8)     if (&User-Name =~ /\\.\\./ ) 
(8)     if (&User-Name =~ /\\.\\./ )  -> FALSE
(8)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))  
(8)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))   -> FALSE
(8)     if (&User-Name =~ /\\.$/)  
(8)     if (&User-Name =~ /\\.$/)   -> FALSE
(8)     if (&User-Name =~ /@\\./)  
(8)     if (&User-Name =~ /@\\./)   -> FALSE
(8)   } # filter_username filter_username = notfound
(8)   [preprocess] = ok
(8)  auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
(8)  auth_log :    --> /var/log/radius/radacct/10.7.0.28/auth-detail-20160906
(8)  auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/10.7.0.28/auth-detail-20160906
(8)  auth_log : EXPAND %t
(8)  auth_log :    --> Tue Sep  6 09:10:59 2016
(8)   [auth_log] = ok
(8)   [mschap] = noop
(8)  suffix : Checking for suffix after "@"
(8)  suffix : No '@' in User-Name = "myUsername", looking up realm NULL
(8)  suffix : No such realm "NULL"
(8)   [suffix] = noop
(8)  eap : Peer sent code Response (2) ID 2 length 8
(8)  eap : No EAP Start, assuming it's an on-going EAP conversation
(8)   [eap] = updated
rlm_ldap (ldap): Reserved connection (11)
(8)  ldap : EXPAND (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})
(8)  ldap :    --> (sAMAccountName=myUsername)
(8)  ldap : EXPAND dc=mySite,dc=org
(8)  ldap :    --> dc=mySite,dc=org
(8)  ldap : Performing search in 'dc=mySite,dc=org' with filter '(sAMAccountName=myUsername)', scope 'sub'
(8)  ldap : Waiting for search result...
Unable to chase referral "ldaps://walton.mySite.org/DC=walton,DC=mySite,DC=org" (-1: Can't contact LDAP server)
Unable to chase referral "ldaps://cast.mySite.org/DC=cast,DC=mySite,DC=org" (-1: Can't contact LDAP server)
TLS: error: connect - force handshake failure: errno 104 - moznss error -5961
TLS: can't connect: TLS error -5961:TCP connection reset by peer.
Unable to chase referral "ldaps://ForestDnsZones.mySite.org/DC=ForestDnsZones,DC=mySite,DC=org" (-1: Can't contact LDAP server)
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://DomainDnsZones.mySite.org/DC=DomainDnsZones,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Rebinding to URL ldaps://mySite.org/CN=Configuration,DC=mySite,DC=org
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
(8)  ldap : User object found at DN "CN=myUsername,OU=mySiteUsers,DC=mySite,DC=org"
(8)  ldap : Processing user attributes
(8)  WARNING: ldap : No "known good" password added. Ensure the admin user has permission to read the password attribute
(8)  WARNING: ldap : PAP authentication will *NOT* work with Active Directory (if that is what you were trying to configure)
rlm_ldap (ldap): Deleting connection (11)
rlm_ldap (ldap): 0 of 3 connections in use.  Need more spares
rlm_ldap (ldap): Opening additional connection (12)
rlm_ldap (ldap): Connecting to adServer01.mySite.org:636
TLS: certificate [CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US] is not valid - error -8179:Peer's Certificate issuer is not recognized..
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
(8)   [ldap] = ok
(8)   [expiration] = noop
(8)   [logintime] = noop
(8)  WARNING: pap : No "known good" password found for the user.  Not setting Auth-Type
(8)  WARNING: pap : Authentication will fail unless a "known good" password is available
(8)   [pap] = noop
(8)  } #  authorize = updated
(8) Found Auth-Type = EAP
(8) # Executing group from file /etc/raddb/sites-enabled/default
(8)   authenticate {
rlm_eap (EAP): No EAP session matching state 0x8acdf80a8acffcab
(8)  eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
(8)  eap : Failed in handler
(8)   [eap] = invalid
(8)  } #  authenticate = invalid
(8) Failed to authenticate the user
(8) Login incorrect: [myUsername] (from client radproxy01.mySite.org port 4 cli 22:44:66:88:00:11)
(8) Using Post-Auth-Type Reject
(8) # Executing group from file /etc/raddb/sites-enabled/default
(8)  Post-Auth-Type REJECT {
(8)  attr_filter.access_reject : EXPAND %{User-Name}
(8)  attr_filter.access_reject :    --> myUsername
(8)  attr_filter.access_reject : Matched entry DEFAULT at line 11
(8)   [attr_filter.access_reject] = updated
rlm_eap (EAP): No EAP session matching state 0x8acdf80a8acffcab
(8)  eap : Either EAP-request timed out OR EAP-response to an unknown EAP-request
(8)  eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(8)   [eap] = noop
(8)   remove_reply_message_if_eap remove_reply_message_if_eap {
(8)     if (&reply:EAP-Message && &reply:Reply-Message) 
(8)     if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
(8)    else else {
(8)     [noop] = noop
(8)    } # else else = noop
(8)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(8)  } # Post-Auth-Type REJECT = updated
(8) Delaying response for 1 seconds
Waking up in 0.9 seconds.
Received Access-Request Id 110 from 10.7.0.28:32775 to 10.7.0.29:1812 length 315
(8) Discarding duplicate request from client radproxy01.mySite.org port 32775 - ID: 110 due to delayed response
(8) Sending delayed response
(8) Sending Access-Reject packet to host 10.7.0.28 port 32775, id=110, length=0
(8) 	Proxy-State = 0x313330
Sending Access-Reject Id 110 from 10.7.0.29:1812 to 10.7.0.28:32775
	Proxy-State = 0x313330
Waking up in 3.9 seconds.
(8) Cleaning up request packet ID 110 with timestamp +372
Waking up in 1999650.2 seconds.

https://directory.uark.edu/people/sgardne
Senior Network Engineer
University of Arkansas, ITS-NET

EAP through proxy not working

Scott McLane Gardner