EAP through proxy not working
Scott McLane Gardner
sgardne at uark.edu
Tue Sep 6 16:22:26 CEST 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
More information about the Freeradius-Users
mailing list