Alex, this is not the full output of radiusd -X (or freeradius -X). You've only included the request, not the configuration that -X spits out beforehand. Please include that portion as well. Stefan -----Original Message----- From: freeradius-users-bounces+stefan.paetow=ja.net@lists.freeradius.org [mailto:freeradius-users-bounces+stefan.paetow=ja.net@lists.freeradius.org] On Behalf Of Alex Gregory Sent: 13 August 2014 20:23 To: FreeRadius users mailing list Subject: Re: OpenLDAP Group membership to Filter-ID I did not have that in there. I added it into the ldap module so my config now looks like: ldap { server = "localhost" identity = "cn=admin,dc=team,dc=company,dc=com" password = xxxxx basedn = "ou=Users,dc=team,dc=company,dc=com" scope = "sub" filter = "(uid=%{%{Stripped-User-Name}:-%{User-Name}})" ... } Here is the output from -XXX rad_recv: Access-Request packet from host xxx.xxx.xxx.xxx port 32768, id=101, length=215 User-Name = "joeuser" Chargeable-User-Identity = "" Location-Capable = Civix-Location Calling-Station-Id = "78-31-c1-be-89-a8" Called-Station-Id = "d4-a0-2a-15-7f-00:C2_Test" NAS-Port = 4 Cisco-AVPair = "audit-session-id=0a210082000006c453ebb861" NAS-IP-Address = 10.33.0.130 NAS-Identifier = "inWebo" Airespace-Wlan-Id = 6 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x0201000c016a6f6575736572 Message-Authenticator = 0x882183e2a08a2bce65b1792c44079165 Wed Aug 13 19:11:30 2014 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authorize {...} Wed Aug 13 19:11:30 2014 : Info: ++[preprocess] returns ok Wed Aug 13 19:11:30 2014 : Info: ++[chap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[mschap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[digest] returns noop Wed Aug 13 19:11:30 2014 : Info: [suffix] No '@' in User-Name = "joeuser", looking up realm NULL Wed Aug 13 19:11:30 2014 : Info: [suffix] No such realm "NULL" Wed Aug 13 19:11:30 2014 : Info: ++[suffix] returns noop Wed Aug 13 19:11:30 2014 : Info: [eap] EAP packet type response id 1 length 12 Wed Aug 13 19:11:30 2014 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns updated Wed Aug 13 19:11:30 2014 : Info: ++[files] returns noop Wed Aug 13 19:11:30 2014 : Info: [ldap] performing user authorization for joeuser Wed Aug 13 19:11:30 2014 : Info: [ldap] expand: %{Stripped-User-Name} -> Wed Aug 13 19:11:30 2014 : Info: [ldap] ... expanding second conditional Wed Aug 13 19:11:30 2014 : Info: [ldap] expand: %{User-Name} -> joeuser Wed Aug 13 19:11:30 2014 : Info: [ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=joeuser) Wed Aug 13 19:11:30 2014 : Info: [ldap] expand: ou=Users,dc=team,dc=company,dc=com -> ou=Users,dc=team,dc=company,dc=com Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] attempting LDAP reconnection Wed Aug 13 19:11:30 2014 : Debug: [ldap] (re)connect to localhost:389, authentication 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] bind as cn=admin,dc=team,dc=company,dc=com/653776d05374 to localhost:389 Wed Aug 13 19:11:30 2014 : Debug: [ldap] waiting for bind result ... Wed Aug 13 19:11:30 2014 : Debug: [ldap] Bind was successful Wed Aug 13 19:11:30 2014 : Debug: [ldap] performing search in ou=Users,dc=team,dc=company,dc=com, with filter (uid=joeuser) Wed Aug 13 19:11:30 2014 : Info: [ldap] No default NMAS login sequence Wed Aug 13 19:11:30 2014 : Info: [ldap] looking for check items in directory... Wed Aug 13 19:11:30 2014 : Debug: [ldap] userPassword -> Password-With-Header == "{MD5}X03MO1qnZdYdgyfeuILPmQ==" Wed Aug 13 19:11:30 2014 : Info: [ldap] looking for reply items in directory... Wed Aug 13 19:11:30 2014 : Info: [ldap] user joeuser authorized to use remote access Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Aug 13 19:11:30 2014 : Info: ++[ldap] returns ok Wed Aug 13 19:11:30 2014 : Info: ++[expiration] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[logintime] returns noop Wed Aug 13 19:11:30 2014 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Wed Aug 13 19:11:30 2014 : Info: ++[pap] returns noop Wed Aug 13 19:11:30 2014 : Info: Found Auth-Type = EAP Wed Aug 13 19:11:30 2014 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authenticate {...} Wed Aug 13 19:11:30 2014 : Info: [eap] EAP Identity Wed Aug 13 19:11:30 2014 : Info: [eap] processing type tls Wed Aug 13 19:11:30 2014 : Info: [tls] Initiate Wed Aug 13 19:11:30 2014 : Info: [tls] Start returned 1 Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns handled Sending Access-Challenge of id 101 to xxx.xxx.xxx.xxx port 32768 EAP-Message = 0x010200061520 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xce049ae9ce068f152ab18dd0a9f47460 Wed Aug 13 19:11:30 2014 : Info: Finished request 0. Wed Aug 13 19:11:30 2014 : Debug: Going to the next request Wed Aug 13 19:11:30 2014 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host xxx.xxx.xxx.xxx port 32768, id=102, length=373 User-Name = "joeuser" Chargeable-User-Identity = "" Location-Capable = Civix-Location Calling-Station-Id = "78-31-c1-be-89-a8" Called-Station-Id = "d4-a0-2a-15-7f-00:C2_Test" NAS-Port = 4 Cisco-AVPair = "audit-session-id=0a210082000006c453ebb861" NAS-IP-Address = 10.33.0.130 NAS-Identifier = "inWebo" Airespace-Wlan-Id = 6 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x0202009815800000008e160301008901000085030153ebb86267f54fc71b8caba32338c6ac7b304b74e7b8ea6d3121e26a2ed7c8d800004a00ffc024c023c00ac009c007c008c028c027c014c013c011c012c026c025c02ac029c005c004c002c003c00fc00ec00cc00d003d003c002f000500040035000a0067006b00330039001601000012000a00080006001700180019000b00020100 State = 0xce049ae9ce068f152ab18dd0a9f47460 Message-Authenticator = 0x5bde15e0f296c2eec38dd20a652cce44 Wed Aug 13 19:11:30 2014 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authorize {...} Wed Aug 13 19:11:30 2014 : Info: ++[preprocess] returns ok Wed Aug 13 19:11:30 2014 : Info: ++[chap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[mschap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[digest] returns noop Wed Aug 13 19:11:30 2014 : Info: [suffix] No '@' in User-Name = "joeuser", looking up realm NULL Wed Aug 13 19:11:30 2014 : Info: [suffix] No such realm "NULL" Wed Aug 13 19:11:30 2014 : Info: ++[suffix] returns noop Wed Aug 13 19:11:30 2014 : Info: [eap] EAP packet type response id 2 length 152 Wed Aug 13 19:11:30 2014 : Info: [eap] Continuing tunnel setup. Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns ok Wed Aug 13 19:11:30 2014 : Info: Found Auth-Type = EAP Wed Aug 13 19:11:30 2014 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authenticate {...} Wed Aug 13 19:11:30 2014 : Info: [eap] Request found, released from the list Wed Aug 13 19:11:30 2014 : Info: [eap] EAP/ttls Wed Aug 13 19:11:30 2014 : Info: [eap] processing type ttls Wed Aug 13 19:11:30 2014 : Info: [ttls] Authenticate Wed Aug 13 19:11:30 2014 : Info: [ttls] processing EAP-TLS Wed Aug 13 19:11:30 2014 : Debug: TLS Length 142 Wed Aug 13 19:11:30 2014 : Info: [ttls] Length Included Wed Aug 13 19:11:30 2014 : Info: [ttls] eaptls_verify returned 11 Wed Aug 13 19:11:30 2014 : Info: [ttls] (other): before/accept initialization Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: before/accept initialization Wed Aug 13 19:11:30 2014 : Info: [ttls] <<< TLS 1.0 Handshake [length 0089], ClientHello Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 read client hello A Wed Aug 13 19:11:30 2014 : Info: [ttls] >>> TLS 1.0 Handshake [length 0039], ServerHello Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 write server hello A Wed Aug 13 19:11:30 2014 : Info: [ttls] >>> TLS 1.0 Handshake [length 02c4], Certificate Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 write certificate A Wed Aug 13 19:11:30 2014 : Info: [ttls] >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 write key exchange A Wed Aug 13 19:11:30 2014 : Info: [ttls] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 write server done A Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 flush data Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: Need to read more data: SSLv3 read client certificate A Wed Aug 13 19:11:30 2014 : Debug: In SSL Handshake Phase Wed Aug 13 19:11:30 2014 : Debug: In SSL Accept mode Wed Aug 13 19:11:30 2014 : Info: [ttls] eaptls_process returned 13 Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns handled Sending Access-Challenge of id 102 to xxx.xxx.xxx.xxx port 32768 EAP-Message = 0x0103040015c000000460160301003902000035030153ebb862012b65c4fb6e4f52554f17ee124440bd460ba5b87053e8744206bfc600c01400000dff01000100000b00040300010216030102c40b0002c00002bd0002ba308202b63082019ea003020102020900b507e231935d6b3f300d06092a864886f70d010105050030133111300f060355040313086f70656e6c646170301e170d3134303830373232333035385a170d3234303830343232333035385a30133111300f060355040313086f70656e6c64617030820122300d06092a864886f70d01010105000382010f003082010a0282010100bae7e24798efa862ea1659a17ac74864a297d09a EAP-Message = 0x249d8e467e1a40a3fc4fdcf36e73ac43cc11e5df4978020ae6af6c12d0a98f7c90d0352eae9c5b9c8364cffe115b833c52bfbcb43c292c303ee0f8cca82a3732ed53bcdba3905a9f030c9bf242e7482f28c0a30e5210afbf064e6129cef1358e30942581621b927da448fcea0fcca181c7ea6ac7385946513bd092e7ccf41df13f7a4f498533947d1f0451659c20977cfddeb5ffadef948b8f876a1bbba0f2a574e05daf8fe696a828973f21674abc246ca73279dcd5fe1720f1140b3f351427fc5be4a4158fb31d2b46643e0bbef9297b892cea88babfcb26e53bcc981bec71b84d0fb21760176f5d12adc90203010001a30d300b30090603551d1304 EAP-Message = 0x023000300d06092a864886f70d010105050003820101009a35e4dddb99265dfbe96dbd2dd5efcec97ebbb6111d42b313a0d7b6f29a4a4cc378c154afc028a986a118ddf1e611aa3fda9ed59c9f745663fcfd2655891584047b99042c2f7d3757ff92e86d008a55dac7e1e2a8f7e67711fec590812461e9de753eacf30285e44c3c7ecc31671d4ccbfdc6de65536e8b780cbf05ca5e0442748ccc7356f315baac1cc9bb528198bba1526d18213171b26e3676162be28056600762ed21df47ca64f29fb8b9853b8e84731708c7e7c5b0862c3d61aa07b37b89eb915e0fb7f5867a9eb9346574bfc112aa4ea45ae9bae8fdf44b9cedbd3ba5082046a7de23 EAP-Message = 0xc8fefa2502dad1e8da8bf54443bc2b061a301dd93689ce6867d9160301014b0c000147030017410435796b6c770b407c2ebab35a3d09b54da0cc51fc29e0127a4e712087f927a4ec66a4001d8e03338aca7c1dc10908145a3965b1b289246e63ea9af938293a140201008264e93ba4a0e00fe8a2a603aa05a33cdaf5c24318fc220ad64b624ef88b45fba17d3acc2c10d3e5637b914657ace3c36cab6a5f1c364cb4d73ada622674017ddaecbb02453a2b48ed183114904b75fd62beccbc2e9af4aebffb4914aab0ac1bb3c9e69c5b8556b8bb6d5144fcf81eb91ed845f3280442d546b1b4a5ab6867e9d5f50773d21d4f335f695b5fc386f0d37beefc EAP-Message = 0x56c2aca56a2c087629999c71 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xce049ae9cf078f152ab18dd0a9f47460 Wed Aug 13 19:11:30 2014 : Info: Finished request 1. Wed Aug 13 19:11:30 2014 : Debug: Going to the next request Wed Aug 13 19:11:30 2014 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host xxx.xxx.xxx.xxx port 32768, id=103, length=227 User-Name = "joeuser" Chargeable-User-Identity = "" Location-Capable = Civix-Location Calling-Station-Id = "78-31-c1-be-89-a8" Called-Station-Id = "d4-a0-2a-15-7f-00:C2_Test" NAS-Port = 4 Cisco-AVPair = "audit-session-id=0a210082000006c453ebb861" NAS-IP-Address = 10.33.0.130 NAS-Identifier = "inWebo" Airespace-Wlan-Id = 6 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020300061500 State = 0xce049ae9cf078f152ab18dd0a9f47460 Message-Authenticator = 0xb8e667ae4d70cf7ba99ff183a7a889cb Wed Aug 13 19:11:30 2014 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authorize {...} Wed Aug 13 19:11:30 2014 : Info: ++[preprocess] returns ok Wed Aug 13 19:11:30 2014 : Info: ++[chap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[mschap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[digest] returns noop Wed Aug 13 19:11:30 2014 : Info: [suffix] No '@' in User-Name = "joeuser", looking up realm NULL Wed Aug 13 19:11:30 2014 : Info: [suffix] No such realm "NULL" Wed Aug 13 19:11:30 2014 : Info: ++[suffix] returns noop Wed Aug 13 19:11:30 2014 : Info: [eap] EAP packet type response id 3 length 6 Wed Aug 13 19:11:30 2014 : Info: [eap] Continuing tunnel setup. Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns ok Wed Aug 13 19:11:30 2014 : Info: Found Auth-Type = EAP Wed Aug 13 19:11:30 2014 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authenticate {...} Wed Aug 13 19:11:30 2014 : Info: [eap] Request found, released from the list Wed Aug 13 19:11:30 2014 : Info: [eap] EAP/ttls Wed Aug 13 19:11:30 2014 : Info: [eap] processing type ttls Wed Aug 13 19:11:30 2014 : Info: [ttls] Authenticate Wed Aug 13 19:11:30 2014 : Info: [ttls] processing EAP-TLS Wed Aug 13 19:11:30 2014 : Info: [ttls] Received TLS ACK Wed Aug 13 19:11:30 2014 : Info: [ttls] ACK handshake fragment handler Wed Aug 13 19:11:30 2014 : Info: [ttls] eaptls_verify returned 1 Wed Aug 13 19:11:30 2014 : Info: [ttls] eaptls_process returned 13 Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns handled Sending Access-Challenge of id 103 to xxx.xxx.xxx.xxx port 32768 EAP-Message = 0x01040074158000000460f3411c40ef6cbf1635e4b4c7c71d18b883360ad6c27db542a4ffa0196c0b2ff8daca2101a3b4a35171415bdf6b68817425eb344c2e5e5a6794c0f1002aa59f631cb9c5135d716d9664afa8a76e9f2ee942decefd1b459b2dbb216aa655697391b416030100040e000000 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xce049ae9cc008f152ab18dd0a9f47460 Wed Aug 13 19:11:30 2014 : Info: Finished request 2. Wed Aug 13 19:11:30 2014 : Debug: Going to the next request Wed Aug 13 19:11:30 2014 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host xxx.xxx.xxx.xxx port 32768, id=104, length=365 User-Name = "joeuser" Chargeable-User-Identity = "" Location-Capable = Civix-Location Calling-Station-Id = "78-31-c1-be-89-a8" Called-Station-Id = "d4-a0-2a-15-7f-00:C2_Test" NAS-Port = 4 Cisco-AVPair = "audit-session-id=0a210082000006c453ebb861" NAS-IP-Address = 10.33.0.130 NAS-Identifier = "inWebo" Airespace-Wlan-Id = 6 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x020400901580000000861603010046100000424104004576a5ac3ee43c0112ce47d295aa54d21d71076fd64b293d0d59fff21795217e1ac2b3934427d9740a789cd8731e1bd52c246904d4414a1877b375e67df9f31403010001011603010030da43e9a2a8d1bb853ae1740aaf5964dc58b28263a25f1dbc40149b8d0aa0a62b22a690caf5fa2c9663e53591a55e3100 State = 0xce049ae9cc008f152ab18dd0a9f47460 Message-Authenticator = 0x9582ab96a0b46bdb12bc99449a415f67 Wed Aug 13 19:11:30 2014 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authorize {...} Wed Aug 13 19:11:30 2014 : Info: ++[preprocess] returns ok Wed Aug 13 19:11:30 2014 : Info: ++[chap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[mschap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[digest] returns noop Wed Aug 13 19:11:30 2014 : Info: [suffix] No '@' in User-Name = "joeuser", looking up realm NULL Wed Aug 13 19:11:30 2014 : Info: [suffix] No such realm "NULL" Wed Aug 13 19:11:30 2014 : Info: ++[suffix] returns noop Wed Aug 13 19:11:30 2014 : Info: [eap] EAP packet type response id 4 length 144 Wed Aug 13 19:11:30 2014 : Info: [eap] Continuing tunnel setup. Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns ok Wed Aug 13 19:11:30 2014 : Info: Found Auth-Type = EAP Wed Aug 13 19:11:30 2014 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authenticate {...} Wed Aug 13 19:11:30 2014 : Info: [eap] Request found, released from the list Wed Aug 13 19:11:30 2014 : Info: [eap] EAP/ttls Wed Aug 13 19:11:30 2014 : Info: [eap] processing type ttls Wed Aug 13 19:11:30 2014 : Info: [ttls] Authenticate Wed Aug 13 19:11:30 2014 : Info: [ttls] processing EAP-TLS Wed Aug 13 19:11:30 2014 : Debug: TLS Length 134 Wed Aug 13 19:11:30 2014 : Info: [ttls] Length Included Wed Aug 13 19:11:30 2014 : Info: [ttls] eaptls_verify returned 11 Wed Aug 13 19:11:30 2014 : Info: [ttls] <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 read client key exchange A Wed Aug 13 19:11:30 2014 : Info: [ttls] <<< TLS 1.0 ChangeCipherSpec [length 0001] Wed Aug 13 19:11:30 2014 : Info: [ttls] <<< TLS 1.0 Handshake [length 0010], Finished Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 read finished A Wed Aug 13 19:11:30 2014 : Info: [ttls] >>> TLS 1.0 ChangeCipherSpec [length 0001] Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 write change cipher spec A Wed Aug 13 19:11:30 2014 : Info: [ttls] >>> TLS 1.0 Handshake [length 0010], Finished Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 write finished A Wed Aug 13 19:11:30 2014 : Info: [ttls] TLS_accept: SSLv3 flush data Wed Aug 13 19:11:30 2014 : Info: [ttls] (other): SSL negotiation finished successfully Wed Aug 13 19:11:30 2014 : Debug: SSL Connection Established Wed Aug 13 19:11:30 2014 : Info: [ttls] eaptls_process returned 13 Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns handled Sending Access-Challenge of id 104 to xxx.xxx.xxx.xxx port 32768 EAP-Message = 0x0105004515800000003b1403010001011603010030479426af6e1c12503738a32e262e84a4c666ea99fb6f5a80df674f2146e70be7e6187626844cccb9362ac032ee1b5de3 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xce049ae9cd018f152ab18dd0a9f47460 Wed Aug 13 19:11:30 2014 : Info: Finished request 3. Wed Aug 13 19:11:30 2014 : Debug: Going to the next request Wed Aug 13 19:11:30 2014 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host xxx.xxx.xxx.xxx port 32768, id=105, length=300 User-Name = "joeuser" Chargeable-User-Identity = "" Location-Capable = Civix-Location Calling-Station-Id = "78-31-c1-be-89-a8" Called-Station-Id = "d4-a0-2a-15-7f-00:C2_Test" NAS-Port = 4 Cisco-AVPair = "audit-session-id=0a210082000006c453ebb861" NAS-IP-Address = 10.33.0.130 NAS-Identifier = "inWebo" Airespace-Wlan-Id = 6 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 EAP-Message = 0x0205004f15800000004517030100407bbbae1e3e6f6eee806cadf4038fc633b025b87de4bfe6c62065214c14dc49fba070a2a5ae82ba25538125ce60ed1e16eebeb7ad9c5eaa990c2be82e7b18f38e State = 0xce049ae9cd018f152ab18dd0a9f47460 Message-Authenticator = 0x641909bf4fd27987f4b839410ca1f707 Wed Aug 13 19:11:30 2014 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authorize {...} Wed Aug 13 19:11:30 2014 : Info: ++[preprocess] returns ok Wed Aug 13 19:11:30 2014 : Info: ++[chap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[mschap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[digest] returns noop Wed Aug 13 19:11:30 2014 : Info: [suffix] No '@' in User-Name = "joeuser", looking up realm NULL Wed Aug 13 19:11:30 2014 : Info: [suffix] No such realm "NULL" Wed Aug 13 19:11:30 2014 : Info: ++[suffix] returns noop Wed Aug 13 19:11:30 2014 : Info: [eap] EAP packet type response id 5 length 79 Wed Aug 13 19:11:30 2014 : Info: [eap] Continuing tunnel setup. Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns ok Wed Aug 13 19:11:30 2014 : Info: Found Auth-Type = EAP Wed Aug 13 19:11:30 2014 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group authenticate {...} Wed Aug 13 19:11:30 2014 : Info: [eap] Request found, released from the list Wed Aug 13 19:11:30 2014 : Info: [eap] EAP/ttls Wed Aug 13 19:11:30 2014 : Info: [eap] processing type ttls Wed Aug 13 19:11:30 2014 : Info: [ttls] Authenticate Wed Aug 13 19:11:30 2014 : Info: [ttls] processing EAP-TLS Wed Aug 13 19:11:30 2014 : Debug: TLS Length 69 Wed Aug 13 19:11:30 2014 : Info: [ttls] Length Included Wed Aug 13 19:11:30 2014 : Info: [ttls] eaptls_verify returned 11 Wed Aug 13 19:11:30 2014 : Info: [ttls] eaptls_process returned 7 Wed Aug 13 19:11:30 2014 : Info: [ttls] Session established. Proceeding to decode tunneled attributes. TTLS tunnel data in 0000: 00 00 00 01 00 00 00 0f 6a 6f 65 75 73 65 72 00 TTLS tunnel data in 0010: 00 00 00 02 00 00 00 18 70 61 73 73 77 6f 72 64 TTLS tunnel data in 0020: 00 00 00 00 00 00 00 00 Wed Aug 13 19:11:30 2014 : Info: [ttls] Got tunneled request User-Name = "joeuser" User-Password = "password" FreeRADIUS-Proxied-To = 127.0.0.1 Wed Aug 13 19:11:30 2014 : Info: [ttls] Sending tunneled request User-Name = "joeuser" User-Password = "password" FreeRADIUS-Proxied-To = 127.0.0.1 Chargeable-User-Identity = "" Location-Capable = Civix-Location Calling-Station-Id = "78-31-c1-be-89-a8" Called-Station-Id = "d4-a0-2a-15-7f-00:C2_Test" NAS-Port = 4 Cisco-AVPair = "audit-session-id=0a210082000006c453ebb861" NAS-IP-Address = 10.33.0.130 NAS-Identifier = "inWebo" Airespace-Wlan-Id = 6 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 server inner-tunnel { Wed Aug 13 19:11:30 2014 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-tunnel Wed Aug 13 19:11:30 2014 : Info: +- entering group authorize {...} Wed Aug 13 19:11:30 2014 : Info: ++? if (Ldap-Group =~ /ou=corp,ou=Users,dc=team,dc=company,dc=com/ ) Wed Aug 13 19:11:30 2014 : Debug: [ldap] Entering ldap_groupcmp() Wed Aug 13 19:11:30 2014 : Info: expand: ou=Users,dc=team,dc=company,dc=com -> ou=Users,dc=team,dc=company,dc=com Wed Aug 13 19:11:30 2014 : Info: expand: %{Stripped-User-Name} -> Wed Aug 13 19:11:30 2014 : Info: ... expanding second conditional Wed Aug 13 19:11:30 2014 : Info: expand: %{User-Name} -> joeuser Wed Aug 13 19:11:30 2014 : Info: expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=joeuser) Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] performing search in ou=Users,dc=team,dc=company,dc=com, with filter (uid=joeuser) Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Aug 13 19:11:30 2014 : Info: expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))) Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] performing search in ou=corp,ou=Users,dc=team,dc=company,dc=com, with filter (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))) Wed Aug 13 19:11:30 2014 : Debug: [ldap] object not found Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Aug 13 19:11:30 2014 : Debug: rlm_ldap::ldap_groupcmp: Group ou=corp,ou=Users,dc=team,dc=company,dc=com not found or user is not a member. Wed Aug 13 19:11:30 2014 : Info: ? Evaluating (Ldap-Group =~ /ou=corp,ou=Users,dc=team,dc=company,dc=com/) -> FALSE Wed Aug 13 19:11:30 2014 : Info: ++? if (Ldap-Group =~ /ou=corp,ou=Users,dc=team,dc=company,dc=com/ ) -> FALSE Wed Aug 13 19:11:30 2014 : Info: ++? if (Ldap-Group =~ /ou=dev,ou=Users,dc=team,dc=company,dc=com/ ) Wed Aug 13 19:11:30 2014 : Debug: [ldap] Entering ldap_groupcmp() Wed Aug 13 19:11:30 2014 : Info: expand: ou=Users,dc=team,dc=company,dc=com -> ou=Users,dc=team,dc=company,dc=com Wed Aug 13 19:11:30 2014 : Info: expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))) Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] performing search in ou=dev,ou=Users,dc=team,dc=company,dc=com, with filter (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))) Wed Aug 13 19:11:30 2014 : Debug: [ldap] object not found Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Aug 13 19:11:30 2014 : Debug: rlm_ldap::ldap_groupcmp: Group ou=dev,ou=Users,dc=team,dc=company,dc=com not found or user is not a member. Wed Aug 13 19:11:30 2014 : Info: ? Evaluating (Ldap-Group =~ /ou=dev,ou=Users,dc=team,dc=company,dc=com/) -> FALSE Wed Aug 13 19:11:30 2014 : Info: ++? if (Ldap-Group =~ /ou=dev,ou=Users,dc=team,dc=company,dc=com/ ) -> FALSE Wed Aug 13 19:11:30 2014 : Info: ++[chap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[mschap] returns noop Wed Aug 13 19:11:30 2014 : Info: [suffix] No '@' in User-Name = "joeuser", looking up realm NULL Wed Aug 13 19:11:30 2014 : Info: [suffix] No such realm "NULL" Wed Aug 13 19:11:30 2014 : Info: ++[suffix] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[control] returns noop Wed Aug 13 19:11:30 2014 : Info: [eap] No EAP-Message, not doing EAP Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[files] returns noop Wed Aug 13 19:11:30 2014 : Info: [ldap] performing user authorization for joeuser Wed Aug 13 19:11:30 2014 : Info: [ldap] expand: %{Stripped-User-Name} -> Wed Aug 13 19:11:30 2014 : Info: [ldap] ... expanding second conditional Wed Aug 13 19:11:30 2014 : Info: [ldap] expand: %{User-Name} -> joeuser Wed Aug 13 19:11:30 2014 : Info: [ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=joeuser) Wed Aug 13 19:11:30 2014 : Info: [ldap] expand: ou=Users,dc=team,dc=company,dc=com -> ou=Users,dc=team,dc=company,dc=com Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Checking Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_get_conn: Got Id: 0 Wed Aug 13 19:11:30 2014 : Debug: [ldap] performing search in ou=Users,dc=team,dc=company,dc=com, with filter (uid=joeuser) Wed Aug 13 19:11:30 2014 : Info: [ldap] No default NMAS login sequence Wed Aug 13 19:11:30 2014 : Info: [ldap] looking for check items in directory... Wed Aug 13 19:11:30 2014 : Debug: [ldap] userPassword -> Password-With-Header == "{MD5}X03MO1qnZdYdgyfeuILPmQ==" Wed Aug 13 19:11:30 2014 : Info: [ldap] looking for reply items in directory... Wed Aug 13 19:11:30 2014 : Info: [ldap] user joeuser authorized to use remote access Wed Aug 13 19:11:30 2014 : Debug: [ldap] ldap_release_conn: Release Id: 0 Wed Aug 13 19:11:30 2014 : Info: ++[ldap] returns ok Wed Aug 13 19:11:30 2014 : Info: ++[expiration] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[logintime] returns noop Wed Aug 13 19:11:30 2014 : Info: ++[pap] returns updated Wed Aug 13 19:11:30 2014 : Info: Found Auth-Type = PAP Wed Aug 13 19:11:30 2014 : Info: # Executing group from file /etc/freeradius/sites-enabled/inner-tunnel Wed Aug 13 19:11:30 2014 : Info: +- entering group PAP {...} Wed Aug 13 19:11:30 2014 : Info: [pap] login attempt with password "password" Wed Aug 13 19:11:30 2014 : Info: [pap] Using MD5 encryption. Wed Aug 13 19:11:30 2014 : Info: [pap] Normalizing MD5-Password from base64 encoding Wed Aug 13 19:11:30 2014 : Info: [pap] User authenticated successfully Wed Aug 13 19:11:30 2014 : Info: ++[pap] returns ok Wed Aug 13 19:11:30 2014 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/inner-tunnel Wed Aug 13 19:11:30 2014 : Info: +- entering group post-auth {...} Wed Aug 13 19:11:30 2014 : Info: expand: %{control:Tmp-String-1} -> Wed Aug 13 19:11:30 2014 : Info: ++[reply] returns noop } # server inner-tunnel Wed Aug 13 19:11:30 2014 : Info: [ttls] Got tunneled reply code 2 Filter-Id = "" Wed Aug 13 19:11:30 2014 : Info: [ttls] Got tunneled Access-Accept Wed Aug 13 19:11:30 2014 : Info: [eap] Freeing handler Wed Aug 13 19:11:30 2014 : Info: ++[eap] returns ok Wed Aug 13 19:11:30 2014 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/default Wed Aug 13 19:11:30 2014 : Info: +- entering group post-auth {...} Wed Aug 13 19:11:30 2014 : Info: ++[exec] returns noop Sending Access-Accept of id 105 to xxx.xxx.xxx.xxx port 32768 Filter-Id = "" MS-MPPE-Recv-Key = 0x973c07e31d3c62b129b86e8e3c753157d7d3fa68a4a77314fa71358e280a02a8 MS-MPPE-Send-Key = 0x4a82fcf322b22593fb75a29e51144d16c5698583f60d170a3fe559c800065eec EAP-Message = 0x03050004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "joeuser" Wed Aug 13 19:11:30 2014 : Info: Finished request 4. Wed Aug 13 19:11:30 2014 : Debug: Going to the next request Wed Aug 13 19:11:30 2014 : Debug: Waking up in 4.8 seconds. Wed Aug 13 19:11:35 2014 : Info: Cleaning up request 0 ID 101 with timestamp +40 Wed Aug 13 19:11:35 2014 : Info: Cleaning up request 1 ID 102 with timestamp +40 Wed Aug 13 19:11:35 2014 : Info: Cleaning up request 2 ID 103 with timestamp +40 Wed Aug 13 19:11:35 2014 : Info: Cleaning up request 3 ID 104 with timestamp +40 Wed Aug 13 19:11:35 2014 : Info: Cleaning up request 4 ID 105 with timestamp +40 Wed Aug 13 19:11:35 2014 : Info: Ready to process requests. Janet(UK) is a trading name of Jisc Collections and Janet Limited, a not-for-profit company which is registered in England under No. 2881024 and whose Registered Office is at Lumen House, Library Avenue, Harwell Oxford, Didcot, Oxfordshire. OX11 0SG. VAT No. 614944238