(RADIATOR) "not properly formatted" when proxying EAP-TLS to IAS
Heikki Vatiainen
hvn at archred.com
Mon Jun 13 09:29:12 CDT 2005
Hugh Irvine wrote:
> Does anyone else on the list have any experience with this?
Just today I received a similar report from one organization that had
acquired Radiator through us. The problem surfaced with 2003 SP1 update
and did not go away when Radiator was updated to 3.13.
The Radiator configuration, IAS error message and resulting time out in
the Radiator log file look similar. I have attached some new info too,
IAS log file snippet and Radiator level 4 trace.
The setup is the following:
Laptop (PEAP) <--> WLAN AP <--> Radiator 3.13 (Proxy) <--> IAS
The IP addresses in the sanitized log files are respectively:
somelaptop.intra.org.fi
wlan.ap.org.fi
radiator-proxy.org.fi
ias.ip.org.fi
If the proxying Radiator is bypassed and the AP talks directly to IAS
the authentication succeeds.
Here is a snippet from IAS log (IASSM.LOG):
[2300] 06-13 12:45:37:730: Creating EAP session
[2300] 06-13 12:45:37:730: NT-SAM Names handler received request with
user identity host/somelaptop.intra.org.fi.
[2300] 06-13 12:45:37:746: Successfully cracked username.
[2300] 06-13 12:45:37:746: SAM-Account-Name is "INTRA\SOMELAPTOP$".
[2300] 06-13 12:45:37:746: NT-SAM Authentication handler received
request for INTRA\SOMELAPTOP$.
[2300] 06-13 12:45:37:746: Validating Windows account INTRA\SOMELAPTOP$.
[2300] 06-13 12:45:37:746: Sending LDAP search to ldapserver.org.fi.
[2300] 06-13 12:45:37:746: LDAP ERROR in ldap_search_ext_sW. Code = 81
[2300] 06-13 12:45:37:746: Extended error string: (null)
[2300] 06-13 12:45:37:746: Retrying LDAP search.
[2300] 06-13 12:45:37:871: Opening LDAP connection to ldapserver.org.fi.
[2300] 06-13 12:45:37:871: The registry value DisableLdapEncryption
does not exist. Using default 0
[2300] 06-13 12:45:37:871: Trying to set LDAP encryption = 1
[2300] 06-13 12:45:37:917: LDAP connect succeeded.
[2300] 06-13 12:45:37:917: Sending LDAP search to ldapserver.org.fi.
[2300] 06-13 12:45:37:933: Successfully validated windows account.
[2300] 06-13 12:45:37:933: Allowed EAP type: 25
[2300] 06-13 12:45:37:933: Setting max. packet length to 1492.
[2300] 06-13 12:45:37:933: Processing output from EAP DLL.
[2300] 06-13 12:45:37:933: EAPACTION_Send
[2300] 06-13 12:45:37:933: Inserting outbound EAP-Message of length 6.
[2300] 06-13 12:45:37:933: Issuing Access-Challenge.
[2300] 06-13 12:45:37:933: Saving the response
[4036] 06-13 12:45:38:011: State attribute is present, but unrecognized.
[4036] 06-13 12:45:52:983: State attribute is present, but unrecognized.
[4036] 06-13 12:46:07:970: State attribute is present, but unrecognized.
[4036] 06-13 12:46:22:942: State attribute is present, but unrecognized.
Here is a snippet from Radiator level 4 debug. Just like the time
stamps show, they do not correspond to same event. What is happening
still, is the laptop trying to authenticate over WLAN.
From the log it looks like the AP sends EAP Response/Identity which
causes IAS to respond with EAP Request/PEAP Start + RADIUS State
attribute. This attribute is then returned by the AP with an EAP
Response that includes a TLS Client Hello. This TLS Client Hello
containing EAP Response never causes the IAS to responds and the timeout
occurs.
Taking a closer look at the messages, the AP seems to send its
Response/Identity message with another Response/Identity message
following the first one in quick succession. This makes me think that
EAP Ids and/or Radius Identifiers clash with the State attribute value
since the Access-Request Identifier is the same (120) in the first two
messages from the AP and also the EAP Ids are the same <1> in those two
packets.
Actually, thinking about the situation where Radiator was bypassed I get
the idea that the problem is with Radiator allocating Access-Request
Identifiers (5) and (6) when it is proxying the packets to the IAS. If
there was no Radiator, the IAS would receive two messages with the same
Access-Request Identifier (120). Maybe the IAS remembers just the first
value (starting with "##...") and fails to recognize the first value
(starting with "#!...") that the AP actually later returns. At least I
could convince myself with this scenario.
When Access-Challanges for those two Access-Requests are sent back, the
Access-Challange Identifiers IAS uses are (5) and (6) but Radiator only
uses (120) when it proxies the messages back to the AP.
Hopefully someone more familiar with Radius can make sense if this is
correct behaviour or not.
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: ***
Received from wlan.ap.org.fi port 1028 .... Code: Access-Request
Identifier: 120 Authentic: <snip> Attributes: User-Name =
"host/somelaptop.intra.org.fi" NAS-IP-Address = wlan.ap.org.fi
Framed-MTU = 1496 Called-Station-Id =
"00-a0-c5-c8-04-91" Calling-Station-Id =
"00-0c-f1-05-da-d8" NAS-Port-Type = Wireless-IEEE-802-11
EAP-Message = <2><1><0><31><1>host/somelaptop.intra.org.fi
Message-Authenticator = <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Handling request with
Handler 'User-Name=/^host\/.*\.intra\.org\.fi/i'
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Deleting session for
host/somelaptop.intra.org.fi, wlan.ap.org.fi,
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Handling with
Radius::AuthRADIUS
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: *** Sending
to ias.ip.org.fi port 1812 .... Code: Access-Request Identifier: 5
Authentic: <snip>
Attributes: User-Name = "host/somelaptop.intra.org.fi"
NAS-IP-Address = wlan.ap.org.fi Framed-MTU = 1496
Called-Station-Id = "00-a0-c5-c8-04-91" Calling-Station-Id =
"00-0c-f1-05-da-d8" NAS-Port-Type = Wireless-IEEE-802-11
EAP-Message = <2><1><0><31><1>host/somelaptop.intra.org.fi
Message-Authenticator = <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: AuthBy RADIUS result:
IGNORE,
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: ***
Received from wlan.ap.org.fi port 1028 .... Code: Access-Request
Identifier: 120 Authentic: <snip> Attributes: User-Name =
"host/somelaptop.intra.org.fi" NAS-IP-Address = wlan.ap.org.fi
Framed-MTU = 1496 Called-Station-Id =
"00-a0-c5-c8-04-91" Calling-Station-Id =
"00-0c-f1-05-da-d8" NAS-Port-Type = Wireless-IEEE-802-11
EAP-Message = <2><1><0><31><1>host/somelaptop.intra.org.fi
Message-Authenticator = <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Handling request with
Handler 'User-Name=/^host\/.*\.intra\.org\.fi/i'
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Deleting session for
host/somelaptop.intra.org.fi, wlan.ap.org.fi,
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Handling with
Radius::AuthRADIUS
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: *** Sending
to ias.ip.org.fi port 1812 .... Code: Access-Request Identifier: 6
Authentic: <snip>
Attributes: User-Name = "host/somelaptop.intra.org.fi"
NAS-IP-Address = wlan.ap.org.fi Framed-MTU = 1496
Called-Station-Id = "00-a0-c5-c8-04-91" Calling-Station-Id =
"00-0c-f1-05-da-d8"
NAS-Port-Type = Wireless-IEEE-802-11 EAP-Message =
<2><1><0><31><1>host/somelaptop.intra.org.fi Message-Authenticator
= <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: AuthBy RADIUS result:
IGNORE,
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: ***
Received from ias.ip.org.fi port 1812 .... Code: Access-Challenge
Identifier: 5 Authentic: <snip>
Attributes: Session-Timeout = 30 EAP-Message =
<1><2><0><6><25> State =
"#!<4>}<0><0><1>7<0><1><ias><ip><addr><ess><0><0><0><3>x<139><211>n"
Message-Authenticator = <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Received reply in
AuthRADIUS for req 5 from ias.ip.org.fi:1812
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Access challenged for
host/somelaptop.intra.org.fi: Proxied
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: *** Sending
to wlan.ap.org.fi port 1028 .... Code: Access-Challenge Identifier:
120 Authentic: <snip>
Attributes: Session-Timeout = 30 EAP-Message =
<1><2><0><6><25> State =
"#!<4>}<0><0><1>7<0><1><ias><ip><addr><ess><0><0><0><3>x<139><211>n"
Message-Authenticator = <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: ***
Received from ias.ip.org.fi port 1812 .... Code: Access-Challenge
Identifier: 6 Authentic: <snip>
Attributes: Session-Timeout = 30 EAP-Message =
<1><2><0><6><25> State =
"##<4>~<0><0><1>7<0><1><ias><ip><addr><ess><0><0><0><3>x<139><211>o"
Message-Authenticator = <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Received reply in
AuthRADIUS for req 6 from ias.ip.org.fi:1812
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Access challenged for
host/somelaptop.intra.org.fi: Proxied
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: *** Sending
to wlan.ap.org.fi port 1028 .... Code: Access-Challenge Identifier:
120 Authentic: <snip>
Attributes: Session-Timeout = 30 EAP-Message =
<1><2><0><6><25> State =
"##<4>~<0><0><1>7<0><1><ias><ip><addr><ess><0><0><0><3>x<139><211>o"
Message-Authenticator = <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: ***
Received from wlan.ap.org.fi port 1028 .... Code: Access-Request
Identifier: 121 Authentic: <snip>
Attributes: User-Name = "host/somelaptop.intra.org.fi"
NAS-IP-Address = wlan.ap.org.fi Framed-MTU = 1496
Called-Station-Id = "00-a0-c5-c8-04-91" \
Calling-Station-Id =
"00-0c-f1-05-da-d8" NAS-Port-Type = Wireless-IEEE-802-11
EAP-Message =
<2><2><0>P<25><128><0><0><0>F<22><3><1><0>A<1><0><0>=<3><1>B<173>e<202><147><127>f<224><230>V<146>H<194><173><171><144>[<193><220>+><182><146>;M<11><229><144><193><151><\
145><216><0><0><22><0><4><0><5><0><10><0><9><0>d<0>b<0><3><0><6><0><19><0><18><0>c<1><0>
State =
"#!<4>}<0><0><1>7<0><1><ias><ip><addr><ess><0><0><0><3>x<139><211>n"
Message-Authenticator = <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Handling request with
Handler 'User-Name=/^host\/.*\.intra\.org\.fi/i'
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Deleting session for
host/somelaptop.intra.org.fi, wlan.ap.org.fi,
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Handling with
Radius::AuthRADIUS
Jun 13 13:54:01 radiator-proxy Radiator[25649]: Packet dump: *** Sending
to ias.ip.org.fi port 1812 .... Code: Access-Request Identifier: 7
Authentic: <snip>
Attributes: User-Name = "host/somelaptop.intra.org.fi"
NAS-IP-Address = wlan.ap.org.fi Framed-MTU = 1496
Called-Station-Id = "00-a0-c5-c8-04-91" \
Calling-Station-Id =
"00-0c-f1-05-da-d8" NAS-Port-Type = Wireless-IEEE-802-11
EAP-Message =
<2><2><0>P<25><128><0><0><0>F<22><3><1><0>A<1><0><0>=<3><1>B<173>e<202><147><127>f<224><230>V<146>H<194><173><171><144>[<193><220>+><182><146>;M<11><229><144><193><151><\
145><216><0><0><22><0><4><0><5><0><10><0><9><0>d<0>b<0><3><0><6><0><19><0><18><0>c<1><0>
State =
"#!<4>}<0><0><1>7<0><1><ias><ip><addr><ess><0><0><0><3>x<139><211>n"
Message-Authenticator = <snip>
Jun 13 13:54:01 radiator-proxy Radiator[25649]: AuthBy RADIUS result:
IGNORE,
Jun 13 13:54:16 radiator-proxy Radiator[25649]: Timed out, retransmitting
Jun 13 13:54:16 radiator-proxy Radiator[25649]: Packet dump: *** Sending
to ias.ip.org.fi port 1812 .... Code: Access-Request Identifier: 7
Authentic: <snip>
Attributes: User-Name = "host/somelaptop.intra.org.fi"
NAS-IP-Address = wlan.ap.org.fi Framed-MTU = 1496
Called-Station-Id = "00-a0-c5-c8-04-91" \
Calling-Station-Id =
"00-0c-f1-05-da-d8" NAS-Port-Type = Wireless-IEEE-802-11
EAP-Message =
<2><2><0>P<25><128><0><0><0>F<22><3><1><0>A<1><0><0>=<3><1>B<173>e<202><147><127>f<224><230>V<146>H<194><173><171><144>[<193><220>+><182><146>;M<11><229><144><193><151><\
145><216><0><0><22><0><4><0><5><0><10><0><9><0>d<0>b<0><3><0><6><0><19><0><18><0>c<1><0>
State =
"#!<4>}<0><0><1>7<0><1><ias><ip><addr><ess><0><0><0><3>x<139><211>n"
Message-Authenticator = <snip>
Jun 13 13:54:31 radiator-proxy Radiator[25649]: Timed out, retransmitting
Jun 13 13:54:31 radiator-proxy Radiator[25649]: Packet dump: *** Sending
to ias.ip.org.fi port 1812 .... Code: Access-Request Identifier: 7
Authentic: <snip>
Attributes: User-Name = "host/somelaptop.intra.org.fi"
NAS-IP-Address = wlan.ap.org.fi Framed-MTU = 1496
Called-Station-Id = "00-a0-c5-c8-04-91" \
Calling-Station-Id =
"00-0c-f1-05-da-d8" NAS-Port-Type = Wireless-IEEE-802-11
EAP-Message =
<2><2><0>P<25><128><0><0><0>F<22><3><1><0>A<1><0><0>=<3><1>B<173>e<202><147><127>f<224><230>V<146>H<194><173><171><144>[<193><220>+><182><146>;M<11><229><144><193><151><\
145><216><0><0><22><0><4><0><5><0><10><0><9><0>d<0>b<0><3><0><6><0><19><0><18><0>c<1><0>
State =
"#!<4>}<0><0><1>7<0><1><ias><ip><addr><ess><0><0><0><3>x<139><211>n"
Message-Authenticator = <snip>
Jun 13 13:54:46 radiator-proxy Radiator[25649]: Timed out, retransmitting
Jun 13 13:54:46 radiator-proxy Radiator[25649]: Packet dump: *** Sending
to ias.ip.org.fi port 1812 .... Code: Access-Request Identifier: 7
Authentic: <snip>
Attributes: User-Name = "host/somelaptop.intra.org.fi"
NAS-IP-Address = wlan.ap.org.fi Framed-MTU = 1496
Called-Station-Id = "00-a0-c5-c8-04-91" \
Calling-Station-Id =
"00-0c-f1-05-da-d8" NAS-Port-Type = Wireless-IEEE-802-11
EAP-Message =
<2><2><0>P<25><128><0><0><0>F<22><3><1><0>A<1><0><0>=<3><1>B<173>e<202><147><127>f<224><230>V<146>H<194><173><171><144>[<193><220>+><182><146>;M<11><229><144><193><151><\
145><216><0><0><22><0><4><0><5><0><10><0><9><0>d<0>b<0><3><0><6><0><19><0><18><0>c<1><0>
State =
"#!<4>}<0><0><1>7<0><1><ias><ip><addr><ess><0><0><0><3>x<139><211>n"
Message-Authenticator = <snip>
Jun 13 13:55:01 radiator-proxy Radiator[25649]: AuthRADIUS: No reply
after 3 retransmissions to ias.ip.org.fi:1812 for
host/somelaptop.intra.org.fi (121)
Jun 13 13:55:01 radiator-proxy Radiator[25649]: AuthRADIUS could not
find a working host to forward to. Ignoring
> On 13 Jun 2005, at 17:57, Chris Hills wrote:
>
>> Hi
>>
>> My configuration is as follows:-
>>
>> <Handler Realm=ad-test.its.ne-worcs.ac.uk>
>>
>> <AuthBy RADIUS>
>>
>> Identifier CheckAD1
>>
>> Host my.ias.server
>> Secret mysecret
>>
>> AuthPort 1812
>> AcctPort 1813
>>
>> </AuthBy>
>>
>> AcctLogFileName %L/detail.myserver
>>
>> </Handler>
>>
>> When a client attempts to authenticate, it proxies the request, but
>> IAS has the following log message:-
>>
>> Access request for user user at my.ias.server was discarded.
>> Fully-Qualified-User-Name = <undetermined>
>> NAS-IP-Address = 172.18.100.14
>> NAS-Identifier = <not present>
>> Called-Station-Identifier = <not present>
>> Calling-Station-Identifier = 00-06-5B-E4-0E-0B
>> Client-Friendly-Name = RADIATOR
>> Client-IP-Address = ra.di.at.or
>> NAS-Port-Type = Ethernet
>> NAS-Port = 238
>> Proxy-Policy-Name = *@my.realm
>> Authentication-Provider = Windows
>> Authentication-Server = <undetermined>
>> Reason-Code = 3
>> Reason = The Remote Authentication Dial-In User Service (RADIUS)
>> request was not properly formatted.
>>
>> For more information, see Help and Support Center at http://
>> go.microsoft.com/fwlink/events.asp.
>>
>> For reference, Radiator said:-
>>
>> Mon Jun 13 08:28:22 2005: INFO: AuthRADIUS: No reply after 3
>> retransmissions to my.ias.server:1812 for chills at ad-test.its.ne-
>> worcs.ac.uk (24)
>> Mon Jun 13 08:28:22 2005: INFO: AuthRADIUS could not find a working
>> host to forward to. Ignoring
>>
>>
>> Is there something wrong with my configuration? I know I had this
>> working before!
>>
>> --
>> Chris Hills
>> IT Services
>> North East Worcestershire College
>>
>> --
>> Archive at http://www.open.com.au/archives/radiator/
>> Announcements on radiator-announce at open.com.au
>> To unsubscribe, email 'majordomo at open.com.au' with
>> 'unsubscribe radiator' in the body of the message.
>>
>
>
> NB:
>
> Have you read the reference manual ("doc/ref.html")?
> Have you searched the mailing list archive (www.open.com.au/archives/
> radiator)?
> Have you had a quick look on Google (www.google.com)?
> Have you included a copy of your configuration file (no secrets),
> together with a trace 4 debug showing what is happening?
>
--
Heikki Vatiainen, Arch Red Oy
+358 44 087 6547
--
Archive at http://www.open.com.au/archives/radiator/
Announcements on radiator-announce at open.com.au
To unsubscribe, email 'majordomo at open.com.au' with
'unsubscribe radiator' in the body of the message.
More information about the radiator
mailing list