Ok, I now have timestamping, and see where I believe the delay to be.
The entire request and group lookups occur within two seconds time,
the tail of of 09:53:38 and throughout 09:53:39.
It verifies the username/password, does group lookups, and then after
it determines the group, it appears (to my eyes at least) to then
attempt to verify the username/password again. This second attempt
takes around two seconds all by itself.
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: waiting for bind result ...
Mon May 13 09:53:41 2002 : Debug: rlm_ldap: user username authenticated
succesf
ully
Here is my configs (colorful comments removed for a cleaner appearance):
-------- config --------------
authorize {
ldap
files
}
authenticate {
ldap {
notfound = RETURN
}
}
preacct {
suffix
files
preprocess
}
accounting {
detail
radutmp
}
session {
radutmp
}
---------- end config -----------
Below is the full logs for context.
----------- logs -----------------
Mon May 13 09:53:38 2002 : Debug: Nothing to do. Sleeping until we see a
reques
t.
rad_recv: Access-Request packet from host 127.0.0.1:4774, id=106, length=58
User-Name = "username"
User-Password = "\266\261\024u5\n\320\245\365?\242\303\230\247\253:"
NAS-IP-Address = 255.255.255.255
NAS-Port-Id = "0"
Mon May 13 09:53:38 2002 : Debug: rad_lowerpair: User-Name now 'username'
Mon May 13 09:53:38 2002 : Debug: rad_rmspace_pair: User-Name now
'username'
Mon May 13 09:53:38 2002 : Debug: rad_rmspace_pair: User-Password now
'secret
'
Mon May 13 09:53:38 2002 : Debug: modcall: entering group authorize
Mon May 13 09:53:38 2002 : Debug: rlm_ldap: - authorize
Mon May 13 09:53:38 2002 : Debug: rlm_ldap: performing user authorization for
te
stjth02
Mon May 13 09:53:38 2002 : Debug: radius_xlat: '(uid=username)'
Mon May 13 09:53:38 2002 : Debug: radius_xlat: 'dc=pennswoods,dc=net'
Mon May 13 09:53:38 2002 : Debug: ldap_get_conn: Got Id: 0
Mon May 13 09:53:38 2002 : Debug: rlm_ldap: performing search in
dc=pennswoods,d
c=net, with filter (uid=username)
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: Added password
{crypt}$1$47.97645$11
g49TqDNOYEoJp0sx5FO/ in check items
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: looking for check items in
directory
...
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: looking for reply items in directory
...
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: user username authorized to use
rem
ote access
Mon May 13 09:53:39 2002 : Debug: ldap_release_conn: Release Id: 0
Mon May 13 09:53:39 2002 : Debug: modcall[authorize]: module "ldap" returns
ok
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: Entering ldap_groupcmp()
Mon May 13 09:53:39 2002 : Debug: radius_xlat: 'dc=pennswoods,dc=net'
Mon May 13 09:53:39 2002 : Debug: ldap_get_conn: Got Id: 0
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: performing search in
dc=pennswoods,d
c=net, with filter (cn=domainemail)
[Continues onwards for a while looking up groups...]
Mon May 13 09:53:39 2002 : Debug: rlm_ldap::ldap_groupcmp: User found in
group c
n=multilink,ou=Group,dc=pennswoods,dc=net
Mon May 13 09:53:39 2002 : Debug: ldap_release_conn: Release Id: 0
Mon May 13 09:53:39 2002 : Debug: users: Matched DEFAULT at 203
Mon May 13 09:53:39 2002 : Debug: modcall[authorize]: module "files" returns o
k
Mon May 13 09:53:39 2002 : Debug: modcall: group authorize returns ok
Mon May 13 09:53:39 2002 : Debug: rad_check_password: Found Auth-Type
LDAP
Mon May 13 09:53:39 2002 : Debug: auth: type "Ldap"
Mon May 13 09:53:39 2002 : Debug: modcall: entering group authenticate
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: - authenticate
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: login attempt by "username" with
pa
ssword "secret"
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: user DN:
uid=username,ou=people,dc=
pennswoods,dc=net
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: (re)connect to localhost
205.247.236
.150 65.215.120.5:389, authentication 1
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: bind as
uid=username,ou=people,dc=p
ennswoods,dc=net/secret
Mon May 13 09:53:39 2002 : Debug: rlm_ldap: waiting for bind result ...
Mon May 13 09:53:41 2002 : Debug: rlm_ldap: user username authenticated
succesf
ully
Mon May 13 09:53:41 2002 : Debug: modcall[authenticate]: module "ldap"
returns
ok
Mon May 13 09:53:41 2002 : Debug: modcall: group authenticate returns ok
Mon May 13 09:53:41 2002 : Debug: modcall: entering group session
Mon May 13 09:53:41 2002 : Debug: radius_xlat: 'username'
Mon May 13 09:53:41 2002 : Debug: modcall[session]: module "radutmp"
returns o
k
Mon May 13 09:53:41 2002 : Debug: modcall: group session returns ok
Mon May 13 09:53:41 2002 : Auth: Login OK: [username] (from client 127.0.0.1
po
rt 0)
Sending Access-Accept of id 106 to 127.0.0.1:4774
Port-Limit = 2
Idle-Timeout = 1800
Mon May 13 09:53:41 2002 : Debug: Finished request 2
Mon May 13 09:53:41 2002 : Debug: Going to the next request
Mon May 13 09:53:41 2002 : Debug: --- Walking the entire request list ---
Mon May 13 09:53:41 2002 : Debug: Waking up in 3 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:4774, id=106, length=58
Mon May 13 09:53:41 2002 : Info: Sending duplicate authentication reply to clien
t 127.0.0.1:4774 - ID: 106
Sending Access-Accept of id 106 to 127.0.0.1
Mon May 13 09:53:41 2002 : Debug: rl_next: returning NULL
Mon May 13 09:53:41 2002 : Debug: Waking up in 3 seconds...
Mon May 13 09:53:44 2002 : Debug: --- Walking the entire request list ---
Mon May 13 09:53:44 2002 : Debug: Cleaning up request 2 ID 106 with
timestamp 3c
dfc562
Mon May 13 09:53:44 2002 : Debug: Nothing to do. Sleeping until we see a
reques
t.
John Hogenmiller, kb3dfz
Systems Administrator, Pennswoods.net
1(877)897-4883 x 592
---
Wouldn't the sentence "I want to put a hyphen between the words Fish
and And and And and Chips in my Fish-And-Chips sign" have been clearer if
quotation marks had been placed before Fish, and between Fish and and, and
and and And, and And and and, and and and And, and And and and, and and
and Chips, as well as after Chips?
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
