Subject: Re: groupcmp fails during tunneled request
From: Matthieu Lazaro <[email-masked]>
To: [email-masked]
Date: Tue, 30 Jun 2009 10:11:03 +0200

Ivan Kalik a écrit :
>> Ivan Kalik a écrit :
>>     
>>>> I am having an issue with the groups again.....
>>>>
>>>> WIFI            NAS-Identifier == "accessPoint-Manager"
>>>>                 Ldap-Group  == wireless,
>>>>                 Ldap-Group  == wireless2,
>>>>
>>>> When I have the attribute wireless it works without a flaw, if I have
>>>> both, it's ok, if I have *ONLY* wireless2 it says "no huntgroup " and
>>>> I'm
>>>> rejected.
>>>>
>>>>         
>>> User is not in wireless2 group in ldap?
>>>
>>> Ivan Kalik
>>> Kalik Informatika ISP
>>>
>>>
>>>       
>> The user *IS* in the wireless2 group in LDAP... That's why I don't
>> understand why it says no huntgroup because wireless works.
>> I was thinking about the syntaxe maybe ( "," "==") ....
>>
>>     
>
> Is that user entry or huntgroup entry? In user entry Ldap-Group should be
> on the check line. Post the debug.
>
>
> Ivan Kalik
> Kalik Informatika ISP
>   
Hello and thanks for the prompt response.

This is a huntgroup entry:

WIFI            NAS-Identifier == "accessPoint-Manager"
                Ldap-Group  == wireless,
                Ldap-Group  == wireless2,

I really wanted to post the debug of a non working configuration with those groups, but it seems to work now since I have put it in debug mode.... And I haven't changed anything on the configuration since it didn't work. SO something is really weird. I'll give you the debug since I think some stuff in it is really strange anyway.

Best Regards,

Matthew

rad_recv: Access-Request packet from host {nas-IP-@} port 1645, id=142, length=156
 User-Name = "ldap-test-user"
 Framed-MTU = 1400
 Called-Station-Id = "00-1E-13-6E-E7-F0"
 Calling-Station-Id = "00-21-E9-AD-65-C9"
 Service-Type = Login-User
 Message-Authenticator = xxxxxxxxx
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 NAS-Port-Type = Wireless-802.11
 NAS-Port = 74057
 NAS-Port-Id = "74057"
 NAS-IP-Address = {nas-IP-@}
 NAS-Identifier = "test-access-point"
+- entering group authorize {...}
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[preprocess]    expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: attempting LDAP reconnection
rlm_ldap: (re)connect to radiusserver.companyname.fr:389, authentication 0
rlm_ldap: starting TLS
rlm_ldap: bind as uid=radtest,ou=accounts,dc=companyname,dc=com/xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx to radiusserver.companyname.fr:389
rlm_ldap: waiting for bind result ...
rlm_ldap: Bind was successful
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group wireless not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless2)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::ldap_groupcmp: User found in group wireless2
rlm_ldap: ldap_release_conn: Release Id: 0
++[preprocess] returns ok
[auth_log]      expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log]      expand: %t -> Tue Jun 30 09:39:31 2009
++[auth_log] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 1 length 12
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[files] users: Matched entry DEFAULT at line 219
++[files] returns ok
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[daily] returns noop
++[expiration] returns noop
++[logintime] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type tls
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 142 to {nas-IP-@} port 1645
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xe6d67e67e6d467ae4afc59448c6cb911
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host {nas-IP-@} port 1645, id=143, length=252
 User-Name = "ldap-test-user"
 Framed-MTU = 1400
 Called-Station-Id = "00-1E-13-6E-E7-F0"
 Calling-Station-Id = "00-21-E9-AD-65-C9"
 Service-Type = Login-User
 Message-Authenticator = xxxxxxxxx
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 NAS-Port-Type = Wireless-802.11
 NAS-Port = 74057
 NAS-Port-Id = "74057"
 State = 0xe6d67e67e6d467ae4afc59448c6cb911
 NAS-IP-Address = {nas-IP-@}
 NAS-Identifier = "test-access-point"
+- entering group authorize {...}
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[preprocess]    expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group wireless not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless2)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::ldap_groupcmp: User found in group wireless2
rlm_ldap: ldap_release_conn: Release Id: 0
++[preprocess] returns ok
[auth_log]      expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log]      expand: %t -> Tue Jun 30 09:39:32 2009
++[auth_log] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 2 length 90
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 80
[peap] Length Included
[peap] eaptls_verify returned 11
[peap]     (other): before/accept initialization
[peap]     TLS_accept: before/accept initialization
[peap] <<< TLS 1.0 Handshake [length 004b], ClientHello
[peap]     TLS_accept: SSLv3 read client hello A
[peap] >>> TLS 1.0 Handshake [length 002a], ServerHello
[peap]     TLS_accept: SSLv3 write server hello A
[peap] >>> TLS 1.0 Handshake [length 0789], Certificate
[peap]     TLS_accept: SSLv3 write certificate A
[peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
[peap]     TLS_accept: SSLv3 write server done A
[peap]     TLS_accept: SSLv3 flush data
[peap]     TLS_accept: Need to read more data: SSLv3 read client certificate A
In SSL Handshake Phase
In SSL Accept mode
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 143 to {nas-IP-@} port 1645
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xe6d67e67e7d567ae4afc59448c6cb911
Finished request 1.
Going to the next request
Waking up in 4.3 seconds.
rad_recv: Access-Request packet from host {nas-IP-@} port 1645, id=144, length=168
 User-Name = "ldap-test-user"
 Framed-MTU = 1400
 Called-Station-Id = "00-1E-13-6E-E7-F0"
 Calling-Station-Id = "00-21-E9-AD-65-C9"
 Service-Type = Login-User
 Message-Authenticator = xxxxxxxxx
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 NAS-Port-Type = Wireless-802.11
 NAS-Port = 74057
 NAS-Port-Id = "74057"
 State = 0xe6d67e67e7d567ae4afc59448c6cb911
 NAS-IP-Address = {nas-IP-@}
 NAS-Identifier = "test-access-point"
+- entering group authorize {...}
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[preprocess]    expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group wireless not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless2)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::ldap_groupcmp: User found in group wireless2
rlm_ldap: ldap_release_conn: Release Id: 0
++[preprocess] returns ok
[auth_log]      expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log]      expand: %t -> Tue Jun 30 09:39:32 2009
++[auth_log] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 3 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 144 to {nas-IP-@} port 1645
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xe6d67e67e4d267ae4afc59448c6cb911
Finished request 2.
Going to the next request
Waking up in 3.8 seconds.
rad_recv: Access-Request packet from host {nas-IP-@} port 1645, id=145, length=500
 User-Name = "ldap-test-user"
 Framed-MTU = 1400
 Called-Station-Id = "00-1E-13-6E-E7-F0"
 Calling-Station-Id = "00-21-E9-AD-65-C9"
 Service-Type = Login-User
 Message-Authenticator = xxxxxxxxx
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 NAS-Port-Type = Wireless-802.11
 NAS-Port = 74057
 NAS-Port-Id = "74057"
 State = 0xe6d67e67e4d267ae4afc59448c6cb911
 NAS-IP-Address = {nas-IP-@}
 NAS-Identifier = "test-access-point"
+- entering group authorize {...}
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[preprocess]    expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group wireless not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless2)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::ldap_groupcmp: User found in group wireless2
rlm_ldap: ldap_release_conn: Release Id: 0
++[preprocess] returns ok
[auth_log]      expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log]      expand: %t -> Tue Jun 30 09:39:33 2009
++[auth_log] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 4 length 253
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 326
[peap] Length Included
[peap] eaptls_verify returned 11
[peap] <<< TLS 1.0 Handshake [length 0106], ClientKeyExchange
[peap]     TLS_accept: SSLv3 read client key exchange A
[peap] <<< TLS 1.0 ChangeCipherSpec [length 0001]
[peap] <<< TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 read finished A
[peap] >>> TLS 1.0 ChangeCipherSpec [length 0001]
[peap]     TLS_accept: SSLv3 write change cipher spec A
[peap] >>> TLS 1.0 Handshake [length 0010], Finished
[peap]     TLS_accept: SSLv3 write finished A
[peap]     TLS_accept: SSLv3 flush data
[peap]     (other): SSL negotiation finished successfully
SSL Connection Established
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 145 to {nas-IP-@} port 1645
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xe6d67e67e5d367ae4afc59448c6cb911
Finished request 3.
Going to the next request
Waking up in 3.3 seconds.
rad_recv: Access-Request packet from host {nas-IP-@} port 1645, id=146, length=168
 User-Name = "ldap-test-user"
 Framed-MTU = 1400
 Called-Station-Id = "00-1E-13-6E-E7-F0"
 Calling-Station-Id = "00-21-E9-AD-65-C9"
 Service-Type = Login-User
 Message-Authenticator = xxxxxxxxx
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 NAS-Port-Type = Wireless-802.11
 NAS-Port = 74057
 NAS-Port-Id = "74057"
 State = 0xe6d67e67e5d367ae4afc59448c6cb911
 NAS-IP-Address = {nas-IP-@}
 NAS-Identifier = "test-access-point"
+- entering group authorize {...}
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[preprocess]    expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group wireless not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless2)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::ldap_groupcmp: User found in group wireless2
rlm_ldap: ldap_release_conn: Release Id: 0
++[preprocess] returns ok
[auth_log]      expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log]      expand: %t -> Tue Jun 30 09:39:33 2009
++[auth_log] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 5 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake is finished
[peap] eaptls_verify returned 3
[peap] eaptls_process returned 3
[peap] EAPTLS_SUCCESS
++[eap] returns handled
Sending Access-Challenge of id 146 to {nas-IP-@} port 1645
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xe6d67e67e2d067ae4afc59448c6cb911
Finished request 4.
Going to the next request
Waking up in 2.8 seconds.
rad_recv: Access-Request packet from host {nas-IP-@} port 1645, id=147, length=205
 User-Name = "ldap-test-user"
 Framed-MTU = 1400
 Called-Station-Id = "00-1E-13-6E-E7-F0"
 Calling-Station-Id = "00-21-E9-AD-65-C9"
 Service-Type = Login-User
 Message-Authenticator = xxxxxxxxx
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 NAS-Port-Type = Wireless-802.11
 NAS-Port = 74057
 NAS-Port-Id = "74057"
 State = 0xe6d67e67e2d067ae4afc59448c6cb911
 NAS-IP-Address = {nas-IP-@}
 NAS-Identifier = "test-access-point"
+- entering group authorize {...}
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[preprocess]    expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group wireless not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless2)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::ldap_groupcmp: User found in group wireless2
rlm_ldap: ldap_release_conn: Release Id: 0
++[preprocess] returns ok
[auth_log]      expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log]      expand: %t -> Tue Jun 30 09:39:34 2009
++[auth_log] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 6 length 43
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] Identity - ldap-test-user
[peap] Got tunneled request
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
server  {
  PEAP: Got tunneled identity of ldap-test-user
  PEAP: Setting default EAP type for tunneled EAP session.
  PEAP: Setting User-Name to ldap-test-user
Sending tunneled request
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 FreeRADIUS-Proxied-To = 127.0.0.1
 User-Name = "ldap-test-user"
server inner-tunnel {
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 6 length 12
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
rlm_ldap: Entering ldap_groupcmp()
[files]  expand: dc=companyname,dc=com -> dc=companyname,dc=com
[files] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[files]  expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[files]  expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=disabled)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group disabled not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
++[files] returns noop
[ldap] performing user authorization for ldap-test-user
[ldap] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[ldap]  expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
[ldap]  expand: dc=companyname,dc=com -> dc=companyname,dc=com
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
[ldap] Added User-Password = {MD5}                 in check items
[ldap] No default NMAS login sequence
[ldap] looking for check items in directory...
rlm_ldap: sambaNtPassword -> NT-Password == 
rlm_ldap: sambaLmPassword -> LM-Password == 
rlm_ldap: ntPassword -> NT-Password == 
rlm_ldap: lmPassword -> LM-Password == 
[ldap] looking for reply items in directory...
[ldap] user ldap-test-user authorized to use remote access
rlm_ldap: ldap_release_conn: Release Id: 0
++[ldap] returns ok
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[daily] returns noop
++[expiration] returns noop
++[logintime] returns noop
Found Auth-Type = EAP
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!    Replacing User-Password in config items with Cleartext-Password.     !!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!! Please update your configuration so that the "known good"               !!!
!!! clear text password is in Cleartext-Password, and not in User-Password. !!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type mschapv2
rlm_eap_mschapv2: Issuing Challenge
++[eap] returns handled
} # server inner-tunnel
[peap] Got tunneled reply code 11
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xb8dbfd7ab8dce75165c444f5e5cf1d13
[peap] Got tunneled reply RADIUS code 11
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xb8dbfd7ab8dce75165c444f5e5cf1d13
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 147 to {nas-IP-@} port 1645
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xe6d67e67e3d167ae4afc59448c6cb911
Finished request 5.
Going to the next request
Waking up in 1.6 seconds.
rad_recv: Access-Request packet from host {nas-IP-@} port 1645, id=148, length=269
 User-Name = "ldap-test-user"
 Framed-MTU = 1400
 Called-Station-Id = "00-1E-13-6E-E7-F0"
 Calling-Station-Id = "00-21-E9-AD-65-C9"
 Service-Type = Login-User
 Message-Authenticator = xxxxxxxxx
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 NAS-Port-Type = Wireless-802.11
 NAS-Port = 74057
 NAS-Port-Id = "74057"
 State = 0xe6d67e67e3d167ae4afc59448c6cb911
 NAS-IP-Address = {nas-IP-@}
 NAS-Identifier = "test-access-point"
+- entering group authorize {...}
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[preprocess]    expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group wireless not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless2)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::ldap_groupcmp: User found in group wireless2
rlm_ldap: ldap_release_conn: Release Id: 0
++[preprocess] returns ok
[auth_log]      expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log]      expand: %t -> Tue Jun 30 09:39:35 2009
++[auth_log] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 7 length 107
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] EAP type mschapv2
[peap] Got tunneled request
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
server  {
  PEAP: Setting User-Name to ldap-test-user
Sending tunneled request
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 FreeRADIUS-Proxied-To = 127.0.0.1
 User-Name = "ldap-test-user"
 State = 0xb8dbfd7ab8dce75165c444f5e5cf1d13
server inner-tunnel {
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 7 length 66
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
rlm_ldap: Entering ldap_groupcmp()
[files]  expand: dc=companyname,dc=com -> dc=companyname,dc=com
[files] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[files]  expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[files]  expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=disabled)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group disabled not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
++[files] returns noop
[ldap] performing user authorization for ldap-test-user
[ldap] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[ldap]  expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
[ldap]  expand: dc=companyname,dc=com -> dc=companyname,dc=com
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
[ldap] Added User-Password =                        in check items
[ldap] No default NMAS login sequence
[ldap] looking for check items in directory...
rlm_ldap: sambaNtPassword -> NT-Password ==  
rlm_ldap: sambaLmPassword -> LM-Password == 
rlm_ldap: ntPassword -> NT-Password ==  
rlm_ldap: lmPassword -> LM-Password == 
[ldap] looking for reply items in directory...
[ldap] user ldap-test-user authorized to use remote access
rlm_ldap: ldap_release_conn: Release Id: 0
++[ldap] returns ok
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[daily] returns noop
++[expiration] returns noop
++[logintime] returns noop
Found Auth-Type = EAP
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!    Replacing User-Password in config items with Cleartext-Password.     !!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!! Please update your configuration so that the "known good"               !!!
!!! clear text password is in Cleartext-Password, and not in User-Password. !!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[mschapv2] +- entering group MS-CHAP {...}
[mschap] Found LM-Password
[mschap] Found NT-Password
[mschap] Told to do MS-CHAPv2 for ldap-test-user with NT-Password
[mschap] adding MS-CHAPv2 MPPE keys
++[mschap] returns ok
MSCHAP Success
++[eap] returns handled
} # server inner-tunnel
[peap] Got tunneled reply code 11
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xb8dbfd7ab9d3e75165c444f5e5cf1d13
[peap] Got tunneled reply RADIUS code 11
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xb8dbfd7ab9d3e75165c444f5e5cf1d13
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 148 to {nas-IP-@} port 1645
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xe6d67e67e0de67ae4afc59448c6cb911
Finished request 6.
Going to the next request
Waking up in 0.4 seconds.
rad_recv: Access-Request packet from host {nas-IP-@} port 1645, id=149, length=205
 User-Name = "ldap-test-user"
 Framed-MTU = 1400
 Called-Station-Id = "00-1E-13-6E-E7-F0"
 Calling-Station-Id = "00-21-E9-AD-65-C9"
 Service-Type = Login-User
 Message-Authenticator = xxxxxxxxx
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 NAS-Port-Type = Wireless-802.11
 NAS-Port = 74057
 NAS-Port-Id = "74057"
 State = 0xe6d67e67e0de67ae4afc59448c6cb911
 NAS-IP-Address = {nas-IP-@}
 NAS-Identifier = "test-access-point"
+- entering group authorize {...}
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[preprocess]    expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group wireless not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless2)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::ldap_groupcmp: User found in group wireless2
rlm_ldap: ldap_release_conn: Release Id: 0
++[preprocess] returns ok
[auth_log]      expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log]      expand: %t -> Tue Jun 30 09:39:36 2009
++[auth_log] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 8 length 43
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] EAP type mschapv2
[peap] Got tunneled request
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
server  {
  PEAP: Setting User-Name to ldap-test-user
Sending tunneled request
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 FreeRADIUS-Proxied-To = 127.0.0.1
 User-Name = "ldap-test-user"
 State = 0xb8dbfd7ab9d3e75165c444f5e5cf1d13
server inner-tunnel {
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[control] returns noop
[eap] EAP packet type response id 8 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
rlm_ldap: Entering ldap_groupcmp()
[files]  expand: dc=companyname,dc=com -> dc=companyname,dc=com
[files] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[files]  expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[files]  expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=disabled)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group disabled not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
++[files] returns noop
[ldap] performing user authorization for ldap-test-user
[ldap] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[ldap]  expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
[ldap]  expand: dc=companyname,dc=com -> dc=companyname,dc=com
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
[ldap] Added User-Password = {MD5}                       in check items
[ldap] No default NMAS login sequence
[ldap] looking for check items in directory...
rlm_ldap: sambaNtPassword -> NT-Password == 
rlm_ldap: sambaLmPassword -> LM-Password == 
rlm_ldap: ntPassword -> NT-Password == 
rlm_ldap: lmPassword -> LM-Password == 
[ldap] looking for reply items in directory...
[ldap] user ldap-test-user authorized to use remote access
rlm_ldap: ldap_release_conn: Release Id: 0
++[ldap] returns ok
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
++[daily] returns noop
++[expiration] returns noop
++[logintime] returns noop
Found Auth-Type = EAP
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!    Replacing User-Password in config items with Cleartext-Password.     !!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!! Please update your configuration so that the "known good"               !!!
!!! clear text password is in Cleartext-Password, and not in User-Password. !!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[eap] Freeing handler
++[eap] returns ok
+- entering group post-auth {...}
[reply_log]     expand: /var/log/freeradius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/reply-detail-20090630
[reply_log] /var/log/freeradius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/reply-detail-20090630
[reply_log]     expand: %t -> Tue Jun 30 09:39:36 2009
++[reply_log] returns ok
} # server inner-tunnel
[peap] Got tunneled reply code 2
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 User-Name = "ldap-test-user"
[peap] Got tunneled reply RADIUS code 2
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 User-Name = "ldap-test-user"
[peap] Tunneled authentication was successful.
[peap] SUCCESS
[peap] Saving tunneled attributes for later
++[eap] returns handled
Sending Access-Challenge of id 149 to {nas-IP-@} port 1645
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
 State = 0xe6d67e67e1df67ae4afc59448c6cb911
Finished request 7.
Going to the next request
Cleaning up request 0 ID 142 with timestamp +23
Cleaning up request 1 ID 143 with timestamp +24
Waking up in 0.3 seconds.
rad_recv: Access-Request packet from host {nas-IP-@} port 1645, id=150, length=205
 User-Name = "ldap-test-user"
 Framed-MTU = 1400
 Called-Station-Id = "00-1E-13-6E-E7-F0"
 Calling-Station-Id = "00-21-E9-AD-65-C9"
 Service-Type = Login-User
 Message-Authenticator = xxxxxxxxx
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 NAS-Port-Type = Wireless-802.11
 NAS-Port = 74057
 NAS-Port-Id = "74057"
 State = 0xe6d67e67e1df67ae4afc59448c6cb911
 NAS-IP-Address = {nas-IP-@}
 NAS-Identifier = "test-access-point"
+- entering group authorize {...}
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
[preprocess]    expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=ldap-test-user)
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (uid=ldap-test-user)
rlm_ldap: ldap_release_conn: Release Id: 0
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::groupcmp: Group wireless not found or user not a member
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: Entering ldap_groupcmp()
[preprocess]    expand: dc=companyname,dc=com -> dc=companyname,dc=com
[preprocess]    expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in dc=companyname,dc=com, with filter (&(radiusGroupName=wireless2)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))
rlm_ldap: object not found
rlm_ldap: ldap_release_conn: Release Id: 0
rlm_ldap: ldap_get_conn: Checking Id: 0
rlm_ldap: ldap_get_conn: Got Id: 0
rlm_ldap: performing search in uid=ldap-test-user,ou=people,dc=companyname,dc=com, with filter (objectclass=*)
rlm_ldap::ldap_groupcmp: User found in group wireless2
rlm_ldap: ldap_release_conn: Release Id: 0
++[preprocess] returns ok
[auth_log]      expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/auth-detail-20090630
[auth_log]      expand: %t -> Tue Jun 30 09:39:37 2009
++[auth_log] returns ok
++[mschap] returns noop
[suffix] No '@' in User-Name = "ldap-test-user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] EAP packet type response id 9 length 43
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established.  Decoding tunneled attributes.
[peap] Received EAP-TLV response.
[peap] Success
[peap] Using saved attributes from the original Access-Accept
[eap] Freeing handler
++[eap] returns ok
+- entering group post-auth {...}
[reply_log]     expand: /var/log/freeradius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d -> /var/log/freeradius/radacct/{nas-IP-@}/reply-detail-20090630
[reply_log] /var/log/freeradius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d expands to /var/log/freeradius/radacct/{nas-IP-@}/reply-detail-20090630
[reply_log]     expand: %t -> Tue Jun 30 09:39:37 2009
++[reply_log] returns ok
++[exec] returns noop
Sending Access-Accept of id 150 to {nas-IP-@} port 1645
 User-Name = "ldap-test-user"
 MS-MPPE-Recv-Key = ooooooooooooooooooooooooooooooooooooooooooooooooooooooooo 
 MS-MPPE-Send-Key = ooooooooooooooooooooooooooooooooooooooooooooooooooooooooo
 EAP-Message = yyyyyyyyyyyyyyyyyyyyyyyy
 Message-Authenticator = xxxxxxxxx
Finished request 8.
Going to the next request
Cleaning up request 2 ID 144 with timestamp +24
Waking up in 0.4 seconds.
Cleaning up request 3 ID 145 with timestamp +25
Waking up in 0.4 seconds.
Cleaning up request 4 ID 146 with timestamp +25
Waking up in 1.2 seconds.
Cleaning up request 5 ID 147 with timestamp +26
Waking up in 1.1 seconds.
Cleaning up request 6 ID 148 with timestamp +27
Waking up in 1.1 seconds.
Cleaning up request 7 ID 149 with timestamp +28
Waking up in 0.4 seconds.
Cleaning up request 8 ID 150 with timestamp +29
Ready to process requests.