eap: Freeradius proxy doesn't work with EAP PEAP auth

Danilo Raspa danilo.raspa at gmail.com
Wed Jul 5 15:12:57 CEST 2017


Hi everybody,
I have a problem with radius. This my architecture:
1. AP 192.168.0.210
2. Radius proxy: 192.168.0.158
3. Radius server: 192.168.0.243

The operating system of both radius server and radius proxy is CentOS 7, I
have installed freeradius 3.0.4.
I use MySQL to store the users.
When I try to connect by using the command "radtest" everything works
perfectly, here the command: "radtest danilo.raspa at realm_example.com 1234
192.168.0.158 18120 password"
The problem is that when I try to connect from my phone using EAP
PEAP(using same danilo.raspa at realm_example.com/1234) I recieve an "Access
Reject" message from the radius server (this is the error: "eap : Identity
does not match User-Name, setting from EAP Identity").
Here are some other info:

proxy.conf (from radius proxy)
[.. default part ..]

home_server server1 {
    type = auth
ipaddr = 192.168.0.243
port = 1812
secret = password
}

home_server_pool server_pool {
      type = fail-over
      home_server = server1
}

realm "realm_example.com" {
      auth_pool = server_pool
}
---------------------------------
mods-enabled/eap
eap {

        default_eap_type = peap
        proxy_tunneled_request_as_eap = no
        [..]
}
---------------------------------
User in table radcheck from schema radius:
username: danilo.raspa
attribute: Cleartext-Password
op: :=
val: 1234
---------------------------------
Log request from RADIUS PROXY:


Received Access-Request Id 168 from 192.168.0.210:3126 to 192.168.0.158:1812
length 168
User-Name = 'danilo.raspa at realm_example.com'
NAS-IP-Address = 192.168.0.210
NAS-Identifier = 'RalinkAP0'
NAS-Port = 0
Called-Station-Id = '80-1F-02-E0-D9-00'
Calling-Station-Id = 'EC-9B-F3-64-E8-00'
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x0201001d0164616e696c6f2e7261737061406d6f76656e64612e636f6d
Message-Authenticator = 0x450b54bc468fdabb50573826f97ac97a
(0) Received Access-Request packet from host 192.168.0.210 port 3126,
id=168, length=168
(0) User-Name = 'danilo.raspa at realm_example.com'
(0) NAS-IP-Address = 192.168.0.210
(0) NAS-Identifier = 'RalinkAP0'
(0) NAS-Port = 0
(0) Called-Station-Id = '80-1F-02-E0-D9-00'
(0) Calling-Station-Id = 'EC-9B-F3-64-E8-00'
(0) Framed-MTU = 1400
(0) NAS-Port-Type = Wireless-802.11
(0) EAP-Message =
0x0201001d0164616e696c6f2e7261737061406d6f76656e64612e636f6d
(0) Message-Authenticator = 0x450b54bc468fdabb50573826f97ac97a
(0) # Executing section authorize from file /etc/raddb/sites-enabled/default
(0)   authorize {
(0)   filter_username filter_username {
(0)     if (!&User-Name)
(0)     if (!&User-Name)  -> FALSE
(0)     if (&User-Name =~ / /)
(0)     if (&User-Name =~ / /)  -> FALSE
(0)     if (&User-Name =~ /@.*@/ )
(0)     if (&User-Name =~ /@.*@/ )  -> FALSE
(0)     if (&User-Name =~ /\\.\\./ )
(0)     if (&User-Name =~ /\\.\\./ )  -> FALSE
(0)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(0)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))   ->
FALSE
(0)     if (&User-Name =~ /\\.$/)
(0)     if (&User-Name =~ /\\.$/)   -> FALSE
(0)     if (&User-Name =~ /@\\./)
(0)     if (&User-Name =~ /@\\./)   -> FALSE
(0)   } # filter_username filter_username = notfound
(0)   [preprocess] = ok
(0)  auth_log : EXPAND
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
(0)  auth_log :    --> /var/log/radius/radacct/
192.168.0.210/auth-detail-20170705
(0)  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/192.168.0.210/auth-detail-20170705
(0)  auth_log : EXPAND %t
(0)  auth_log :    --> Wed Jul  5 14:55:26 2017
(0)   [auth_log] = ok
(0)   [chap] = noop
(0)   [mschap] = noop
(0)   [digest] = noop
(0)  suffix : Checking for suffix after "@"
(0)  suffix : Looking up realm "realm_example.com" for User-Name = "
danilo.raspa at realm_example.com"
(0)  suffix : Found realm "realm_example.com"
(0)  suffix : Adding Stripped-User-Name = "danilo.raspa"
(0)  suffix : Adding Realm = "realm_example.com"
(0)  suffix : Proxying request from user danilo.raspa to realm
realm_example.com
(0)  suffix : Preparing to proxy authentication request to realm "
realm_example.com"
(0)   [suffix] = updated
(0)  eap : Request is supposed to be proxied to Realm realm_example.com.
Not doing EAP.
(0)   [eap] = noop
(0)  sql : EXPAND %{User-Name}
(0)  sql :    --> danilo.raspa at realm_example.com
(0)  sql : SQL-User-Name set to 'danilo.raspa at realm_example.com'
rlm_sql (sql): Reserved connection (4)
(0)  sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck
WHERE username = '%{SQL-User-Name}' ORDER BY id
(0)  sql :    --> SELECT id, username, attribute, value, op FROM radcheck
WHERE username = 'danilo.raspa at realm_example.com' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op
FROM radcheck WHERE username = 'danilo.raspa at realm_example.com' ORDER BY id'
(0)  sql : User found in radcheck table
(0)  sql : Check items matched
(0)  sql : EXPAND SELECT id, username, attribute, value, op FROM radreply
WHERE username = '%{SQL-User-Name}' ORDER BY id
(0)  sql :    --> SELECT id, username, attribute, value, op FROM radreply
WHERE username = 'danilo.raspa at realm_example.com' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op
FROM radreply WHERE username = 'danilo.raspa at realm_example.com' ORDER BY id'
(0)  sql : EXPAND SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority
(0)  sql :    --> SELECT groupname FROM radusergroup WHERE username = '
danilo.raspa at realm_example.com' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE
username = 'danilo.raspa at realm_example.com' ORDER BY priority'
(0)  sql : User not found in any groups
rlm_sql (sql): Released connection (4)
rlm_sql (sql): Closing connection (0), from 1 unused connections
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 88
seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 88
seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (1): Hit idle_timeout, was idle for 88
seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
(0)   [sql] = ok
(0)   [expiration] = noop
(0)   [logintime] = noop
(0)   [pap] = noop
(0)  } #  authorize = updated
Opening new proxy socket 'proxy address * port 0'
Listening on proxy address * port 41438
(0) Proxying request to home server 192.168.0.243 port 1812 timeout
30.000000
(0) Sending Access-Request packet to host 192.168.0.243 port 1812, id=158,
length=0
(0) User-Name = 'danilo.raspa'
(0) NAS-IP-Address = 192.168.0.210
(0) NAS-Identifier = 'RalinkAP0'
(0) NAS-Port = 0
(0) Called-Station-Id = '80-1F-02-E0-D9-A0'
(0) Calling-Station-Id = 'EC-9B-F3-64-E8-D8'
(0) Framed-MTU = 1400
(0) NAS-Port-Type = Wireless-802.11
(0) EAP-Message =
0x0201001d0164616e696c6f2e7261737061406d6f76656e64612e636f6d
(0) Message-Authenticator = 0x450b54bc468fdabb50573826f97ac97a
(0) Event-Timestamp = 'Jul  5 2017 14:55:26 CEST'
(0) Stripped-User-Name = 'danilo.raspa'
(0) Realm = 'realm_example.com'
(0) EAP-Type = Identity
(0) Proxy-State = 0x313638
Sending Access-Request Id 158 from 0.0.0.0:41438 to 192.168.0.243:1812
User-Name = 'danilo.raspa'
NAS-IP-Address = 192.168.0.210
NAS-Identifier = 'RalinkAP0'
NAS-Port = 0
Called-Station-Id = '80-1F-02-E0-D9-00'
Calling-Station-Id = 'EC-9B-F3-64-E8-00'
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x0201001d0164616e696c6f2e7261737061406d6f76656e64612e636f6d
Message-Authenticator = 0x450b54bc468fdabb50573826f97ac97a
Event-Timestamp = 'Jul  5 2017 14:55:26 CEST'
Proxy-State = 0x313638
Waking up in 0.3 seconds.
Waking up in 0.1 seconds.
(0) Expecting proxy response no later than 29.499665 seconds from now
Waking up in 29.4 seconds.
Received Access-Request Id 168 from 192.168.0.210:3126 to 192.168.0.158:1812
length 168
Suppressing duplicate proxied request (too fast) to home server
192.168.0.243 port 1812 proto TCP - ID: 158
Waking up in 29.0 seconds.
Received Access-Reject Id 158 from 192.168.0.243:1812 to 192.168.0.158:41438
length 25
Proxy-State = 0x313638
(0) Received Access-Reject packet from host 192.168.0.243 port 1812,
id=158, length=25
(0) Proxy-State = 0x313638
(0) # Executing section post-proxy from file
/etc/raddb/sites-enabled/default
(0)   post-proxy {
(0)  eap : No pre-existing handler found
(0)   [eap] = noop
(0)  } #  post-proxy = noop
(0) Login incorrect (Home Server says so): [danilo.raspa at realm_example.com]
(from client company-intranet port 0 cli EC-9B-F3-64-E8-00)
(0) Using Post-Auth-Type Reject
(0) # Executing group from file /etc/raddb/sites-enabled/default
(0)  Post-Auth-Type REJECT {
(0)  sql : EXPAND .query
(0)  sql :    --> .query
(0)  sql : Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(0)  sql : EXPAND %{User-Name}
(0)  sql :    --> danilo.raspa at realm_example.com
(0)  sql : SQL-User-Name set to 'danilo.raspa at realm_example.com'
(0)  sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S')
(0)  sql :    --> INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( 'danilo.raspa at realm_example.com', '', 'Access-Reject', '2017-07-05
14:55:26')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass,
reply, authdate) VALUES ( 'danilo.raspa at realm_example.com', '',
'Access-Reject', '2017-07-05 14:55:26')'
rlm_sql (sql): Released connection (4)
rlm_sql (sql): 0 of 1 connections in use.  Need more spares
rlm_sql (sql): Opening additional connection (5)
rlm_sql_mysql: Starting connect to MySQL server
(0)   [sql] = ok
(0)  attr_filter.access_reject : EXPAND %{User-Name}
(0)  attr_filter.access_reject :    --> danilo.raspa at realm_example.com
(0)  attr_filter.access_reject : Matched entry DEFAULT at line 11
(0)   [attr_filter.access_reject] = updated
(0)  eap : Request was previously rejected, inserting EAP-Failure
(0)   [eap] = updated
(0)   remove_reply_message_if_eap remove_reply_message_if_eap {
(0)     if (&reply:EAP-Message && &reply:Reply-Message)
(0)     if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
(0)    else else {
(0)     [noop] = noop
(0)    } # else else = noop
(0)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(0)  } # Post-Auth-Type REJECT = updated
(0) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(0) Sending delayed response
(0) Sending Access-Reject packet to host 192.168.0.210 port 3126, id=168,
length=0
(0) EAP-Message = 0x04010004
(0) Message-Authenticator = 0x00000000000000000000000000000000
Sending Access-Reject Id 168 from 192.168.0.158:1812 to 192.168.0.210:3126
EAP-Message = 0x04010004
Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 3.9 seconds.
(0) Cleaning up request packet ID 168 with timestamp +88
Ready to process requests

---------------------------------
Log request from RADIUS SERVER:

Received Access-Request Id 158 from 192.168.0.158:41438 to
192.168.0.243:1812 length 167
User-Name = 'danilo.raspa'
NAS-IP-Address = 192.168.0.210
NAS-Identifier = 'RalinkAP0'
NAS-Port = 0
Called-Station-Id = '80-1F-02-E0-D9-00'
Calling-Station-Id = 'EC-9B-F3-64-E8-00'
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x0201001d0164616e696c6f2e7261737061406d6f76656e64612e636f6d
Message-Authenticator = 0x1a099d1b62181477dc9bd471b56d829e
Event-Timestamp = 'Jul  5 2017 14:55:26 CEST'
Proxy-State = 0x313638
(0) Received Access-Request packet from host 192.168.0.158 port 41438,
id=158, length=167
(0) User-Name = 'danilo.raspa'
(0) NAS-IP-Address = 192.168.0.210
(0) NAS-Identifier = 'RalinkAP0'
(0) NAS-Port = 0
(0) Called-Station-Id = '80-1F-02-E0-D9-00'
(0) Calling-Station-Id = 'EC-9B-F3-64-E8-00'
(0) Framed-MTU = 1400
(0) NAS-Port-Type = Wireless-802.11
(0) EAP-Message =
0x0201001d0164616e696c6f2e7261737061406d6f76656e64612e636f6d
(0) Message-Authenticator = 0x1a099d1b62181477dc9bd471b56d829e
(0) Event-Timestamp = 'Jul  5 2017 14:55:26 CEST'
(0) Proxy-State = 0x313638
(0) # Executing section authorize from file /etc/raddb/sites-enabled/default
(0)   authorize {
(0)   filter_username filter_username {
(0)     if (!&User-Name)
(0)     if (!&User-Name)  -> FALSE
(0)     if (&User-Name =~ / /)
(0)     if (&User-Name =~ / /)  -> FALSE
(0)     if (&User-Name =~ /@.*@/ )
(0)     if (&User-Name =~ /@.*@/ )  -> FALSE
(0)     if (&User-Name =~ /\\.\\./ )
(0)     if (&User-Name =~ /\\.\\./ )  -> FALSE
(0)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(0)     if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))   ->
FALSE
(0)     if (&User-Name =~ /\\.$/)
(0)     if (&User-Name =~ /\\.$/)   -> FALSE
(0)     if (&User-Name =~ /@\\./)
(0)     if (&User-Name =~ /@\\./)   -> FALSE
(0)   } # filter_username filter_username = notfound
(0)   [preprocess] = ok
(0)  auth_log : EXPAND
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
(0)  auth_log :    --> /var/log/radius/radacct/
192.168.0.158/auth-detail-20170705
(0)  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/192.168.0.158/auth-detail-20170705
(0)  auth_log : EXPAND %t
(0)  auth_log :    --> Wed Jul  5 14:55:26 2017
(0)   [auth_log] = ok
(0)   [chap] = noop
(0)   [mschap] = noop
(0)   [digest] = noop
(0)  suffix : Checking for suffix after "@"
(0)  suffix : No '@' in User-Name = "danilo.raspa", looking up realm NULL
(0)  suffix : No such realm "NULL"
(0)   [suffix] = noop
(0)  eap : Peer sent code Response (2) ID 1 length 29
(0)  eap : EAP-Identity reply, returning 'ok' so we can short-circuit the
rest of authorize
(0)   [eap] = ok
(0)  } #  authorize = ok
(0) Found Auth-Type = EAP
(0) # Executing group from file /etc/raddb/sites-enabled/default
(0)   authenticate {
(0)  eap : Identity does not match User-Name, setting from EAP Identity
 <-----[I think that the problem is HERE!!]
(0)  eap : Failed in handler
(0)   [eap] = invalid
(0)  } #  authenticate = invalid
(0) Failed to authenticate the user
(0) Using Post-Auth-Type Reject
(0) # Executing group from file /etc/raddb/sites-enabled/default
(0)  Post-Auth-Type REJECT {
(0)  sql : EXPAND .query
(0)  sql :    --> .query
(0)  sql : Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(0)  sql : EXPAND %{User-Name}
(0)  sql :    --> danilo.raspa
(0)  sql : SQL-User-Name set to 'danilo.raspa'
(0)  sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S')
(0)  sql :    --> INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( 'danilo.raspa', '', 'Access-Reject', '2017-07-05 14:55:26')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass,
reply, authdate) VALUES ( 'danilo.raspa', '', 'Access-Reject', '2017-07-05
14:55:26')'
rlm_sql (sql): Released connection (4)
(0)   [sql] = ok
(0)  attr_filter.access_reject : EXPAND %{User-Name}
(0)  attr_filter.access_reject :    --> danilo.raspa
(0)  attr_filter.access_reject : Matched entry DEFAULT at line 11
(0)   [attr_filter.access_reject] = updated
(0)  eap : Identity does not match User-Name, setting from EAP Identity
(0)  eap : Failed to get handler, probably already removed, not inserting
EAP-Failure
(0)   [eap] = noop
(0)   remove_reply_message_if_eap remove_reply_message_if_eap {
(0)     if (&reply:EAP-Message && &reply:Reply-Message)
(0)     if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
(0)    else else {
(0)     [noop] = noop
(0)    } # else else = noop
(0)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(0)  } # Post-Auth-Type REJECT = updated
(0) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(0) Sending delayed response
(0) Sending Access-Reject packet to host 192.168.0.158 port 41438, id=158,
length=0
(0) Proxy-State = 0x313638
Sending Access-Reject Id 158 from 192.168.0.243:1812 to 192.168.0.158:41438
Proxy-State = 0x313638
Waking up in 3.9 seconds.
(0) Cleaning up request packet ID 158 with timestamp +7
Ready to process requests
----------------------------------------


Thanks in advance

Danilo Raspa


More information about the Freeradius-Users mailing list