Wed Jul 11 15:51:03 2007 : Debug:   Processing the authorize section of radiusd.conf
Wed Jul 11 15:51:03 2007 : Debug: modcall: entering group authorize for request 1
Wed Jul 11 15:51:03 2007 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1
Wed Jul 11 15:51:03 2007 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1
Wed Jul 11 15:51:03 2007 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 1
Wed Jul 11 15:51:03 2007 : Debug:   modsingle[authorize]: calling ldap (rlm_ldap) for request 1
Wed Jul 11 15:51:03 2007 : Debug: rlm_ldap: - authorize
Wed Jul 11 15:51:03 2007 : Debug: rlm_ldap: performing user authorization for jhenkel
Wed Jul 11 15:51:03 2007 : Debug: radius_xlat:  '(uid=jhenkel)'
Wed Jul 11 15:51:03 2007 : Debug: radius_xlat:  'ou=staff,dc=sterlingcrane,dc=ca'
Wed Jul 11 15:51:03 2007 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0
Wed Jul 11 15:51:03 2007 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0
Wed Jul 11 15:51:03 2007 : Debug: rlm_ldap: performing search in ou=staff,dc=sterlingcrane,dc=ca, with filter (uid=jhenkel)
ldap_search
put_filter: "(uid=jhenkel)"
put_filter: simple
put_simple_filter: "uid=jhenkel"
ldap_send_initial_request
ldap_send_server_request
ldap_result msgid 4
ldap_chkResponseList for msgid=4, all=1
ldap_chkResponseList returns NULL
wait4msg (timeout 4 sec, 0 usec), msgid 4
wait4msg continue, msgid 4, all 1
** Connections:
* host: ldap.sterlingcrane.ca  port: 389  (default)
  refcnt: 2  status: Connected
  last used: Wed Jul 11 15:51:03 2007

** Outstanding Requests:
 * msgid 4,  origid 4, status InProgress
   outstanding referrals 0, parent count 0
** Response Queue:
   Empty
ldap_chkResponseList for msgid=4, all=1
ldap_chkResponseList returns NULL
ldap_int_select
read1msg: msgid 4, all 1
ldap_read: message type search-result msgid 4, original id 4
ldap_chase_referrals
read1msg:  V2 referral chased, mark request completed, id = 4
new result:  res_errno: 32, res_error: <>, res_matched: <dc=sterlingcrane,dc=ca>
read1msg:  0 new referrals
read1msg:  mark request completed, id = 4
request 4 done
res_errno: 32, res_error: <>, res_matched: <dc=sterlingcrane,dc=ca>
ldap_free_request (origid 4, msgid 4)
ldap_free_connection
ldap_free_connection: refcnt 1
ldap_parse_result
Wed Jul 11 15:51:03 2007 : Debug: rlm_ldap: object not found or got ambiguous search result
ldap_msgfree
Wed Jul 11 15:51:03 2007 : Debug: rlm_ldap: search failed
Wed Jul 11 15:51:03 2007 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0
Wed Jul 11 15:51:03 2007 : Debug:   modsingle[authorize]: returned from ldap (rlm_ldap) for request 1
Wed Jul 11 15:51:03 2007 : Debug:   modcall[authorize]: module "ldap" returns notfound for request 1
Wed Jul 11 15:51:03 2007 : Debug: modcall: leaving group authorize (returns ok) for request 1
Wed Jul 11 15:51:03 2007 : Debug: auth: No authenticate method (Auth-Type) configuration found for the request: Rejecting the user
Wed Jul 11 15:51:03 2007 : Debug: auth: Failed to validate the user.
Wed Jul 11 15:51:03 2007 : Debug: Delaying request 1 for 1 seconds
Wed Jul 11 15:51:03 2007 : Debug: Finished request 1
Wed Jul 11 15:51:03 2007 : Debug: Going to the next request
Wed Jul 11 15:51:03 2007 : Debug: --- Walking the entire request list ---
Wed Jul 11 15:51:03 2007 : Debug: Waking up in 1 seconds...
Wed Jul 11 15:51:04 2007 : Debug: --- Walking the entire request list ---
Wed Jul 11 15:51:04 2007 : Debug: Waking up in 1 seconds...
Wed Jul 11 15:51:05 2007 : Debug: --- Walking the entire request list ---
Sending Access-Reject of id 91 to 127.0.0.1 port 37542
Wed Jul 11 15:51:05 2007 : Debug: Waking up in 4 seconds...
Wed Jul 11 15:51:09 2007 : Debug: --- Walking the entire request list ---
Wed Jul 11 15:51:09 2007 : Debug: Cleaning up request 1 ID 91 with timestamp 469550c7
Wed Jul 11 15:51:09 2007 : Debug: Nothing to do.  Sleeping until we see a request.