(RADIATOR) "not properly formatted" when proxying EAP-TLS to IAS
Heikki Vatiainen
hvn at archred.com
Tue Jun 14 06:10:14 CDT 2005
There was DupInterval 0 in the configuration but now it is back to the
default value of 2 (seconds). The problem still persists.
Mike McCauley wrote:
> Hello Heike and Chris,
>
> Thanks for your note and logs.
>
> I think that Heikki's analysis is correct: The AP is sending 2 duplicate
> requests in the same second, and Radiator is configured to proxy these as 2
> distinct non-duplicate requests. And this is confusing the IAS State
> maintenance algorithm.
>
> I suspect that the AP's Client clause has been configured with a non-standard
> DupInterval of 0 (meaning that Radiator will always proxy requests even if
> they are duplicates).
>
> If that is so, I suggest to Heike that DupInterval should be set back to the
> standard 2 seconds.
>
> Chris, you did not include all of your config file in your note, so I cant
> tell if it is the same issue for you too.
>
>
> Cheers.
>
> On Tuesday 14 June 2005 00:29, Heikki Vatiainen wrote:
>
>>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><22
>>
>>9><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><22
>>
>>9><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><22
>>
>>9><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><22
>>
>>9><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><22
>>
>>9><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