(RADIATOR) "not properly formatted" when proxying EAP-TLS to IAS
Mike McCauley
mikem at open.com.au
Mon Jun 13 17:58:25 CDT 2005
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?
--
Mike McCauley mikem at open.com.au
Open System Consultants Pty. Ltd Unix, Perl, Motif, C++, WWW
9 Bulbul Place Currumbin Waters QLD 4223 Australia http://www.open.com.au
Phone +61 7 5598-7474 Fax +61 7 5598-7070
Radiator: the most portable, flexible and configurable RADIUS server
anywhere. SQL, proxy, DBM, files, LDAP, NIS+, password, NT, Emerald,
Platypus, Freeside, TACACS+, PAM, external, Active Directory, EAP, TLS,
TTLS, PEAP etc on Unix, Windows, MacOS etc.
--
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