3.1 and LDAP
Tynan Young
tynany at gmail.com
Wed Dec 2 00:21:03 CET 2015
On Wed, Dec 2, 2015 at 8:58 AM, Arran Cudbard-Bell
<a.cudbardb at freeradius.org> wrote:
>
>> On 1 Dec 2015, at 03:34, Tynan Young <tynany at gmail.com> wrote:
>>
>> Hi,
>>
>> I've got freeradius 3.1 up and running (taken from the git repo on the
>> 25th Nov) on Ubuntu 14.04 and am having weird issues with LDAP. Hoping
>> someone may be able to shed some light.
>>
>> I'm using freeradius for dot1x authentication, both wireless
>> (peap/mschapv2) and wired via NTLM auth. The freeradius LDAP module is
>> used to look up Active Directory group membership and based on
>> membership returns the relevant Tunnel-Private-Group-Id.
>>
>> The issue I'm having is that the LDAP lookup will work most of the
>> time, but will frequently stop working for 5-25 minutes. It will start
>> working again without any changes being made. To isolate LDAP
>> user/server issues I've tried using different user accounts and 2012
>> AD servers.
>
> CN=ldapradiusauth,CN=users,DC=in,DC=testdomain to
> ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389 failed:
> Timed out while waiting for server to respond
> Unable to chase referral
> "ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain"
> (-5: Timed out)
>
> Interesting.
>
> So it looks like it follows the complete referral chain, but then the search operation times out. It may be that timeouts that were not being enforced correctly in v3.0.x are now enforced in v3.1.x, I did fix a fair few of those.
Interesting - this may explain some of the issues I've been
experiencing with 3.0.X also.
> To know for sure, it'd be good to get the debug output with timestampsand maybe a pcap showing what's actually going on.
See below. Let me know if you would like more information.
-Timestamps when LDAP search is not working:
Wed Dec 2 09:25:16 2015 : Debug: (7) files: Performing search in
"dc=in,dc=testdomain" with filter "(sAMAccountName=testuser)", scope
"sub"
Wed Dec 2 09:25:16 2015 : Debug: (7) files: Waiting for search result...
Wed Dec 2 09:27:23 2015 : Debug: rlm_ldap (ldap): Rebinding to URL
ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain
Wed Dec 2 09:27:23 2015 : Debug: rlm_ldap (ldap): Waiting for bind result...
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Rebinding to URL
ldap://ForestDnsZones.in.testdomain/DC=ForestDnsZones,DC=in,DC=testdomain
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Waiting for bind result...
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Rebinding to URL
ldap://in.testdomain/CN=Configuration,DC=in,DC=testdomain
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Waiting for bind result...
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Bind successful
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Bind successful
Wed Dec 2 09:29:31 2015 : Error: rlm_ldap (ldap): Bind with
CN=ldapradiusauth,CN=users,DC=in,DC=testdomain to
ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389 failed:
Timed out while waiting for server to respond
Unable to chase referral
"ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain"
(-5: Timed out)
Wed Dec 2 09:29:31 2015 : Info: rlm_ldap (ldap): Deleting inviable
connection (0)
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap: Closing libldap handle 0x2365990
Wed Dec 2 09:29:31 2015 : Info: rlm_ldap (ldap): Need 6 more
connections to reach 10 spares
Wed Dec 2 09:29:31 2015 : Info: rlm_ldap (ldap): Opening additional
connection (5), 1 of 28 pending slots used
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Connecting to
ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): New libldap handle 0x2365990
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Waiting for bind result...
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Bind successful
Wed Dec 2 09:29:31 2015 : Info: rlm_ldap (ldap): Closing connection
(4): Hit idle_timeout, was idle for 284 seconds
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap: Closing libldap handle 0x23a41f0
Wed Dec 2 09:29:31 2015 : Info: rlm_ldap (ldap): Closing connection
(3): Hit idle_timeout, was idle for 284 seconds
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap: Closing libldap handle 0x23a39a0
Wed Dec 2 09:29:31 2015 : Info: rlm_ldap (ldap): Closing connection
(2): Hit idle_timeout, was idle for 284 seconds
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): You probably need
to lower "min"
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap: Closing libldap handle 0x23922a0
Wed Dec 2 09:29:31 2015 : Info: rlm_ldap (ldap): Closing connection
(1): Hit idle_timeout, was idle for 284 seconds
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): You probably need
to lower "min"
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap: Closing libldap handle 0x23917a0
Wed Dec 2 09:29:31 2015 : Debug: rlm_ldap (ldap): Reserved connection (5)
Wed Dec 2 09:29:31 2015 : WARNING: (7) files: Search failed: Timed
out while waiting for server to respond. Got new socket, retrying...
Wed Dec 2 09:29:31 2015 : Debug: (7) files: Waiting for search result...
-High level packet capture when LDAP search is not working:
No. Time Source Destination
Protocol Length Info
21 2.815005 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
22 2.817726 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
27 2.822321 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
28 2.825065 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
33 2.829556 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
34 2.832579 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
39 2.837051 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
40 2.839793 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
45 2.844133 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
46 2.846510 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
53 31.857220 radius.in.testdomain dc1.in.testdomain
LDAP 139 searchRequest(2) "dc=in,dc=testdomain" wholeSubtree
54 31.860144 dc1.in.testdomain radius.in.testdomain
LDAP 1852 searchResEntry(2)
"CN=testuser,OU=users,DC=in,DC=testdomain" | searchResRef(2) |
searchResRef(2) | searchResRef(2) | searchResDone(2) success [1
result]
115 287.249001 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(11)
122 287.253363 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
123 287.256485 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
125 287.256691 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(2)
127 287.256864 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(2)
129 287.257010 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(2)
131 287.257127 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(2)
133 287.257266 radius.in.testdomain dc1.in.testdomain
LDAP 139 searchRequest(2) "dc=in,dc=testdomain" wholeSubtree
142 287.259174 dc1.in.testdomain radius.in.testdomain
LDAP 1852 searchResEntry(2)
"CN=testuser,OU=users,DC=in,DC=testdomain" | searchResRef(2) |
searchResRef(2) | searchResRef(2) | searchResDone(2) success [1
result]
-High level packet capture when LDAP search is working:
No. Time Source Destination
Protocol Length Info
4 0.001709 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
5 0.004474 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
10 0.008402 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
11 0.011494 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
16 0.015274 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
17 0.017818 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
22 0.022174 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
23 0.024050 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
28 0.028135 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
29 0.030606 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
31 7.718161 radius.in.testdomain dc1.in.testdomain
LDAP 139 searchRequest(2) "dc=in,dc=testdomain" wholeSubtree
32 7.720647 dc1.in.testdomain radius.in.testdomain
LDAP 1852 searchResEntry(2)
"CN=testuser,OU=users,DC=in,DC=testdomain" | searchResRef(2) |
searchResRef(2) | searchResRef(2) | searchResDone(2) success [1
result]
37 7.725337 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(4) "ldapradiusauth" simple
38 7.727794 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(4) success
43 7.945255 radius.in.testdomain dc2.in.testdomain
LDAP 106 bindRequest(8) "ldapradiusauth" simple
44 7.948543 dc2.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(8) success
46 7.948856 radius.in.testdomain dc2.in.testdomain
LDAP 156 searchRequest(7)
"CN=Configuration,dc=in,dc=testdomain" wholeSubtree
47 7.949716 dc2.in.testdomain radius.in.testdomain
LDAP 170 searchResRef(7) | searchResDone(7) success [0
results]
48 7.949817 radius.in.testdomain dc2.in.testdomain
LDAP 166 searchRequest(9)
"CN=Schema,CN=Configuration,dc=in,dc=testdomain" wholeSubtree
49 7.950501 dc2.in.testdomain radius.in.testdomain
LDAP 88 searchResDone(9) success [0 results]
50 7.950590 radius.in.testdomain dc2.in.testdomain
LDAP 73 unbindRequest(10)
54 8.151267 radius.in.testdomain dc1.in.testdomain
LDAP 157 searchRequest(3)
"DC=DomainDnsZones,dc=in,dc=testdomain" wholeSubtree
55 8.152470 dc1.in.testdomain radius.in.testdomain
LDAP 88 searchResDone(3) success [0 results]
57 8.152626 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(11)
61 8.364198 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(13) "ldapradiusauth" simple
62 8.367117 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(13) success
64 8.367626 radius.in.testdomain dc1.in.testdomain
LDAP 272 searchRequest(14)
"CN=test,OU=VLAN-Access,DC=in,DC=testdomain" wholeSubtree
65 8.369174 dc1.in.testdomain radius.in.testdomain
LDAP 1038 searchResEntry(14)
"CN=test,OU=VLAN-Access,DC=in,DC=testdomain" | searchResDone(14)
success [1 result]
66 8.369731 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(15)
73 8.375227 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
74 8.377783 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
76 8.386249 radius.in.testdomain dc1.in.testdomain
LDAP 225 searchRequest(2) "dc=in,dc=testdomain" wholeSubtree
77 8.388571 dc1.in.testdomain radius.in.testdomain
LDAP 425 searchResEntry(2)
"CN=testuser,OU=users,DC=in,DC=testdomain" | searchResRef(2) |
searchResRef(2) | searchResRef(2) | searchResDone(2) success [1
result]
82 8.393105 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(4) "ldapradiusauth" simple
83 8.396002 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(4) success
88 8.612681 radius.in.testdomain dc2.in.testdomain
LDAP 106 bindRequest(8) "ldapradiusauth" simple
89 8.615446 dc2.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(8) success
91 8.615772 radius.in.testdomain dc2.in.testdomain
LDAP 242 searchRequest(7)
"CN=Configuration,dc=in,dc=testdomain" wholeSubtree
92 8.616556 dc2.in.testdomain radius.in.testdomain
LDAP 170 searchResRef(7) | searchResDone(7) success [0
results]
93 8.616637 radius.in.testdomain dc2.in.testdomain
LDAP 252 searchRequest(9)
"CN=Schema,CN=Configuration,dc=in,dc=testdomain" wholeSubtree
94 8.617563 dc2.in.testdomain radius.in.testdomain
LDAP 88 searchResDone(9) success [0 results]
95 8.617650 radius.in.testdomain dc2.in.testdomain
LDAP 73 unbindRequest(10)
99 8.819244 radius.in.testdomain dc1.in.testdomain
LDAP 243 searchRequest(3)
"DC=DomainDnsZones,dc=in,dc=testdomain" wholeSubtree
100 8.820485 dc1.in.testdomain radius.in.testdomain
LDAP 88 searchResDone(3) success [0 results]
102 8.820635 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(11)
106 9.032638 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(13)
113 9.038806 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
114 9.041627 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
119 9.101453 radius.in.testdomain dc1.in.testdomain
LDAP 139 searchRequest(2) "dc=in,dc=testdomain" wholeSubtree
120 9.103941 dc1.in.testdomain radius.in.testdomain
LDAP 1852 searchResEntry(2)
"CN=testuser,OU=users,DC=in,DC=testdomain" | searchResRef(2) |
searchResRef(2) | searchResRef(2) | searchResDone(2) success [1
result]
125 9.108084 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(4) "ldapradiusauth" simple
126 9.110923 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(4) success
131 9.329203 radius.in.testdomain dc2.in.testdomain
LDAP 106 bindRequest(8) "ldapradiusauth" simple
132 9.332170 dc2.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(8) success
134 9.332361 radius.in.testdomain dc2.in.testdomain
LDAP 156 searchRequest(7)
"CN=Configuration,dc=in,dc=testdomain" wholeSubtree
135 9.333151 dc2.in.testdomain radius.in.testdomain
LDAP 170 searchResRef(7) | searchResDone(7) success [0
results]
136 9.333294 radius.in.testdomain dc2.in.testdomain
LDAP 166 searchRequest(9)
"CN=Schema,CN=Configuration,dc=in,dc=testdomain" wholeSubtree
137 9.334050 dc2.in.testdomain radius.in.testdomain
LDAP 88 searchResDone(9) success [0 results]
138 9.334179 radius.in.testdomain dc2.in.testdomain
LDAP 73 unbindRequest(10)
142 9.534048 radius.in.testdomain dc1.in.testdomain
LDAP 157 searchRequest(3)
"DC=DomainDnsZones,dc=in,dc=testdomain" wholeSubtree
143 9.535179 dc1.in.testdomain radius.in.testdomain
LDAP 88 searchResDone(3) success [0 results]
145 9.535365 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(11)
149 9.746469 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(13) "ldapradiusauth" simple
150 9.749525 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(13) success
152 9.750101 radius.in.testdomain dc1.in.testdomain
LDAP 272 searchRequest(14)
"CN=test,OU=VLAN-Access,DC=in,DC=testdomain" wholeSubtree
153 9.751542 dc1.in.testdomain radius.in.testdomain
LDAP 1038 searchResEntry(14)
"CN=test,OU=VLAN-Access,DC=in,DC=testdomain" | searchResDone(14)
success [1 result]
154 9.752103 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(15)
161 9.757750 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
162 9.760814 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
164 9.765768 radius.in.testdomain dc1.in.testdomain
LDAP 225 searchRequest(2) "dc=in,dc=testdomain" wholeSubtree
165 9.767654 dc1.in.testdomain radius.in.testdomain
LDAP 425 searchResEntry(2)
"CN=testuser,OU=users,DC=in,DC=testdomain" | searchResRef(2) |
searchResRef(2) | searchResRef(2) | searchResDone(2) success [1
result]
170 9.772173 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(4) "ldapradiusauth" simple
171 9.774400 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(4) success
176 9.991406 radius.in.testdomain dc2.in.testdomain
LDAP 106 bindRequest(8) "ldapradiusauth" simple
177 9.993905 dc2.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(8) success
179 9.994235 radius.in.testdomain dc2.in.testdomain
LDAP 242 searchRequest(7)
"CN=Configuration,dc=in,dc=testdomain" wholeSubtree
180 9.995032 dc2.in.testdomain radius.in.testdomain
LDAP 170 searchResRef(7) | searchResDone(7) success [0
results]
181 9.995132 radius.in.testdomain dc2.in.testdomain
LDAP 252 searchRequest(9)
"CN=Schema,CN=Configuration,dc=in,dc=testdomain" wholeSubtree
182 9.995820 dc2.in.testdomain radius.in.testdomain
LDAP 88 searchResDone(9) success [0 results]
183 9.995894 radius.in.testdomain dc2.in.testdomain
LDAP 73 unbindRequest(10)
187 10.198411 radius.in.testdomain dc1.in.testdomain
LDAP 243 searchRequest(3)
"DC=DomainDnsZones,dc=in,dc=testdomain" wholeSubtree
188 10.199514 dc1.in.testdomain radius.in.testdomain
LDAP 88 searchResDone(3) success [0 results]
190 10.199652 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(11)
194 10.410664 radius.in.testdomain dc1.in.testdomain
LDAP 73 unbindRequest(13)
201 10.416576 radius.in.testdomain dc1.in.testdomain
LDAP 106 bindRequest(1) "ldapradiusauth" simple
202 10.419202 dc1.in.testdomain radius.in.testdomain
LDAP 88 bindResponse(1) success
> It really just seems like the LDAP server isn't responding quickly enough.
Okay, I'll start doing some debugging on the active directory LDAP
side of things.
> -Arran
>
> Arran Cudbard-Bell <a.cudbardb at freeradius.org>
> FreeRADIUS development team
>
> FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
More information about the Freeradius-Users
mailing list