Re: 3.1 and LDAP

1 Dec 2015


      On Wed, Dec 2, 2015 at 8:58 AM, Arran Cudbard-Bell
<a.cudbardb@freeradius.org> wrote:
...
...
On 1 Dec 2015, at 03:34, Tynan Young <tynany@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@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