PEAP auth rejected due to different inner and outer user-id

[douglas eseng]

Encountered the following issue.

Running FR 2.2.3. PEAP tunneled authentication was successful. But get
rejected due to username mismatch. No issue when both username are the same.

Snippet of the debug log. Full debug.log for the attempt and radiusd -X
attached.

Tue Feb 11 09:58:32 2014 : Debug: ++update outer.reply {
Tue Feb 11 09:58:32 2014 : Debug:       expand: %{request:User-Name} ->
jacquegp
Tue Feb 11 09:58:32 2014 : Debug: ++} # update outer.reply = noop
Tue Feb 11 09:58:32 2014 : Debug: +} # group post-auth = noop
Tue Feb 11 09:58:32 2014 : Debug: [peap] Tunneled authentication was
successful.
Tue Feb 11 09:58:32 2014 : Debug: [peap] SUCCESS
Tue Feb 11 09:58:32 2014 : Debug: [peap] Saving tunneled attributes for
later
Tue Feb 11 09:58:32 2014 : Debug: ++[eap_custom] = handled
Tue Feb 11 09:58:32 2014 : Debug: +} # group authenticate = handled
Tue Feb 11 09:58:32 2014 : Debug: Sending Access-Challenge packet to host
172.23.12.254 port 1645, id=101, length=0
Tue Feb 11 09:58:32 2014 : Debug:       User-Name = "jacquegp"
Tue Feb 11 09:58:32 2014 : Debug:       EAP-Message =
0x010a002b190017030100201278d8b49e1c026b2f34d961bf660de263813d0f9033639f146fe5baf2675fcf
Tue Feb 11 09:58:32 2014 : Debug:       Message-Authenticator =
0x00000000000000000000000000000000
Tue Feb 11 09:58:32 2014 : Debug:       State =
0x1873098d1079106583e3066b1fd4db72
Tue Feb 11 09:58:32 2014 : Debug: Finished request 556186.
Tue Feb 11 09:58:32 2014 : Debug: Received Access-Request packet from host
172.23.12.254 port 1645, id=102, length=283
Tue Feb 11 09:58:32 2014 : Debug:       User-Name = "jacquegp"
Tue Feb 11 09:58:32 2014 : Debug:       Framed-MTU = 1400
Tue Feb 11 09:58:32 2014 : Debug:       Called-Station-Id = "003a.9aba.7bf0"
Tue Feb 11 09:58:32 2014 : Debug:       Calling-Station-Id =
"8832.9b40.493a"
Tue Feb 11 09:58:32 2014 : Debug:       Cisco-AVPair = "ssid=Wireless"
Tue Feb 11 09:58:32 2014 : Debug:       WISPr-Location-Name = "Location"
Tue Feb 11 09:58:32 2014 : Debug:       Service-Type = Login-User
Tue Feb 11 09:58:32 2014 : Debug:       Message-Authenticator =
0xd3c7bd34fe6ab7510f2d1c529f4e9513
Tue Feb 11 09:58:32 2014 : Debug:       EAP-Message =
0x020a005019001703010020090e5ecf84ca7daf04c43eff2c62dffd490c3165926acddb05e42bca4a2feae7170301002084ce26a1c964a6ab6f8a698a7731102564f9c8867a7a05ddd592d015c17d6649
Tue Feb 11 09:58:32 2014 : Debug:       NAS-Port-Type = Wireless-802.11
Tue Feb 11 09:58:32 2014 : Debug:       NAS-Port = 4351
Tue Feb 11 09:58:32 2014 : Debug:       NAS-Port-Id = "4351"
Tue Feb 11 09:58:32 2014 : Debug:       State =
0x1873098d1079106583e3066b1fd4db72
Tue Feb 11 09:58:32 2014 : Debug:       NAS-IP-Address = 172.23.12.254
Tue Feb 11 09:58:32 2014 : Debug:       NAS-Identifier = "Site"
Tue Feb 11 09:58:32 2014 : Debug: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
Tue Feb 11 09:58:32 2014 : Debug: +group authorize {
Tue Feb 11 09:58:32 2014 : Debug: ++[preprocess] = ok
Tue Feb 11 09:58:32 2014 : Debug: [suffix] No '@' in User-Name =
"jacquegp", looking up realm NULL
Tue Feb 11 09:58:32 2014 : Debug: [suffix] No such realm "NULL"
Tue Feb 11 09:58:32 2014 : Debug: ++[suffix] = noop
Tue Feb 11 09:58:32 2014 : Debug: ++? if (Aruba-Essid-Name == "Visitor")
Tue Feb 11 09:58:32 2014 : Debug:     (Attribute Aruba-Essid-Name was not
found)
Tue Feb 11 09:58:32 2014 : Debug: ? Evaluating (Aruba-Essid-Name ==
"Visitor") -> FALSE
Tue Feb 11 09:58:32 2014 : Debug: ++? if (Aruba-Essid-Name == "Visitor") ->
FALSE
Tue Feb 11 09:58:32 2014 : Debug: ++else else {
Tue Feb 11 09:58:32 2014 : Debug: [eap_custom] EAP packet type response id
10 length 80
Tue Feb 11 09:58:32 2014 : Debug: [eap_custom] Continuing tunnel setup.
Tue Feb 11 09:58:32 2014 : Debug: +++[eap_custom] = ok
Tue Feb 11 09:58:32 2014 : Debug: ++} # else else = ok
Tue Feb 11 09:58:32 2014 : Debug: ++[expiration] = noop
Tue Feb 11 09:58:32 2014 : Debug: ++[logintime] = noop
Tue Feb 11 09:58:32 2014 : Debug: ++[pap] = noop
Tue Feb 11 09:58:32 2014 : Debug: +} # group authorize = ok
Tue Feb 11 09:58:32 2014 : Debug: Found Auth-Type = eap_custom
Tue Feb 11 09:58:32 2014 : Debug: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Tue Feb 11 09:58:32 2014 : Debug: +group authenticate {
Tue Feb 11 09:58:32 2014 : Debug: [eap_custom] Request found, released from
the list
Tue Feb 11 09:58:32 2014 : Debug: [eap_custom] Identity does not match
User-Name.  Authentication failed.
Tue Feb 11 09:58:32 2014 : Debug: [eap_custom] Failed in handler
Tue Feb 11 09:58:32 2014 : Debug: ++[eap_custom] = invalid
Tue Feb 11 09:58:32 2014 : Debug: +} # group authenticate = invalid
Tue Feb 11 09:58:32 2014 : Debug: Failed to authenticate the user.
Tue Feb 11 09:58:32 2014 : Debug: Using Post-Auth-Type REJECT
Tue Feb 11 09:58:32 2014 : Debug: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Tue Feb 11 09:58:32 2014 : Debug: +group REJECT {
Tue Feb 11 09:58:32 2014 : Debug: [attr_filter.access_reject]   expand:
%{User-Name} -> jacquegp
Tue Feb 11 09:58:32 2014 : Debug: ++[attr_filter.access_reject] = updated
Tue Feb 11 09:58:32 2014 : Debug: +} # group REJECT = updated
Tue Feb 11 09:58:32 2014 : Debug: Delaying reject of request 556187 for 1
seconds
Tue Feb 11 09:58:33 2014 : Debug: Cleaning up request 556177 ID 92 with
timestamp +1110040
Tue Feb 11 09:58:33 2014 : Debug: Sending delayed reject for request 556187
Tue Feb 11 09:58:33 2014 : Debug: Sending Access-Reject packet to host
172.23.12.254 port 1645, id=102, length=0

Anyone seen this issue before?

Thanks.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20140211/38efda7c/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: startup.log.gz
Type: application/x-gzip
Size: 5845 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20140211/38efda7c/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: debug.log.gz
Type: application/x-gzip
Size: 7575 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20140211/38efda7c/attachment-0003.bin>