[SSSD] sssd/ssh authentication problem

Wes Modes wmodes at ucsc.edu
Mon Apr 1 18:06:44 UTC 2013


Any thoughts?  Reply at bottom...

On 3/29/2013 12:11 PM, Wes Modes wrote:
> On 3/29/2013 1:18 AM, Jakub Hrozek wrote:
>> On Thu, Mar 28, 2013 at 04:34:47PM -0700, Wes Modes wrote:
>>> Hi, I've read a few of the posts to this list that have helped folks
>>> diagnose their auth problems with sssd.  However, I couldn't quite
>>> figure out how to diagnose mine.  Perhaps your expertise can help.
>>>
>>> I am running CentOS 6.3 with sssd-1.9.2.  I set up my ldap authorization
>>> like so:
>>>
>>> authconfig --enableldap --enableldapauth --enablemkhomedir --ldapserver=ldap.mydomain.edu --ldapbasedn="dc=mydomain,dc=com" --update
>>>
>>> After that, most everything worked like magic:
>>>
>> Hi Wes,
>>
>>> [root at myhost ~]# getent passwd rjohnson
>>> rjohnson:*:30644:30075:Robert Johnson,,831-459-5208,,:/data/home/rjohnson:/bin/nologin
>>>
>>> However, I was unable to make ssh for these ldap users work.  It does
>>> work for local users, however.
>>>
>>> Now, honestly, I don't want ldap users to ever be able to login via ssh,
>> that's why you set the shell to nologin, right?
>>
>>> however, I suspect getting that to work is the key to getting sftp
>>> working through the ssh system.  Here's what happens when I try to ssh
>>> into myhost.  It is a known/tested user and password combo.
>>>
>>> [root at myotherhost]$ ssh jhurt at myhost
>>> jhurt at myhost's password: 
>>> Permission denied, please try again.
>>>
>>> And over on myhost with sshd debugging mode:
>>>
>>> [root at myhost log]# /usr/sbin/sshd -d -d -d
>>> [snip]
>>> debug1: userauth-request for user jhurt service ssh-connection method password
>>> debug1: attempt 3 failures 0
>>> debug2: input_userauth_request: try method password
>>> debug3: mm_auth_password entering
>>> debug3: mm_request_send entering: type 11
>>> debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD
>>> debug3: mm_request_receive_expect entering: type 12
>>> debug3: mm_request_receive entering
>>> debug3: monitor_read: checking request 11
>>> debug3: PAM: sshpam_passwd_conv called with 1 messages
>>> debug1: PAM: password authentication failed for jhurt: Authentication failure
>>> debug3: mm_answer_authpassword: sending result 0
>>> debug3: mm_request_send entering: type 12
>>> Failed password for jhurt from 192.168.1.2 port 44180 ssh2
>>> debug3: mm_auth_password: user not authenticated
>>> debug3: Wrote 80 bytes for a total of 2045
>>> debug3: mm_request_receive entering
>>>
>>> And here's what sssd says in the logs at debug level 9.
>>>
>>> (Thu Mar 28 15:47:26 2013) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 1F843B0
>>> (Thu Mar 28 15:47:26 2013) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
>>> (Thu Mar 28 15:47:26 2013) [sssd[pam]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x1f85980][19]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering pam_cmd_authenticate
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'jhurt' matched without domain, user is jhurt
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): using default domain [(null)]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): user: jhurt
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): rhost: myotherhost.mydomain.com
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): authtok size: 5
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): newauthtok size: 0
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 6294
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/default/jhurt]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x41b300:3:jhurt at default]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [default][3][1][name=jhurt]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x1f87da0
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x41b300:3:jhurt at default]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x1f87da0
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 1F87950
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 1 errno: 11 error message: Offline
>> I think here is the problem. While retrieving identity information works
>> just fine even when the SSSD cannot connect to the remote server,
>> authentication is only possible online by default (unless
>> cache_credentials is set to True and there was at least one successfull
>> authentication to establish the cached credentials).
>>
>> So I would recommend to also raise the debug_level in the [domain]
>> section and check why the SSSD cannot connect.
>>
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_check_user_dp_callback] (0x0040): Unable to get information from Data Provider
>>> Error: 1, 11, Offline
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [jhurt at default]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1f90e60
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1f90f80
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x1f90f80 "ltdb_timeout"
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x1f90e60 "ltdb_callback"
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [jhurt at default]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [jhurt] added to PAM initgroup cache
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): domain: default
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): user: jhurt
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): rhost: myotherhost.mydomain.com
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): authtok size: 5
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): newauthtok size: 0
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 6294
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x1f816c0
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x41b300:3:jhurt at default]
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x1f816c0
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 1F87950
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_dp_process_reply] (0x0100): received: [9][default]
>> PAM error code 9 means PAM_AUTHINFO_UNAVAIL - Underlying authentication
>> service can not retrieve authentication information. Again, I think this
>> is because the SSSD can't connect to the server for one reason or
>> another.
>>
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [9].
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [pam_reply] (0x0100): blen: 24
>>> (Thu Mar 28 15:47:27 2013) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x1f85980][19]
>>> (Thu Mar 28 15:47:32 2013) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [jhurt] removed from PAM initgroup cache
>>> (Thu Mar 28 15:47:36 2013) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 1F843B0
>>> (Thu Mar 28 15:47:36 2013) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
>>> (Thu Mar 28 15:47:36 2013) [sssd[pam]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>>>
>>> And here an successful strace of logging into the local machine.
>>>
>>> [root at myhost ~]# strace -e open su - jhurt
>> su from root won't even consult pam_sss for authentication because typically
>> the pam stack contains pam_rootok.so which always succeeds if the caller
>> is root. You could verify that by taking a look at /var/log/secure.
>> _______________________________________________
>> sssd-devel mailing list
>> sssd-devel at lists.fedorahosted.org
>> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
>
> In a failed attempt during debugging to turn off caching I had set
> "cache_credentials = False" since "entry_cache_timeout = 1" in the
> domain section did not seem to take effect.  I set it back to
> "cache_credentials = True" here.  I set "debug_level = 31" in the
> domain and pam sections as you suggested (doesn't seem to make any
> different above nine, however).  Here we go:
>
>     [root at myhost sssd]# tail -f -n 0 *.log
>     ==> ldap_child.log <==
>
>     ==> sssd_default.log <==
>
>     ==> sssd.log <==
>
>     ==> sssd_nss.log <==
>
>     ==> sssd_pam.log <==
>     (Fri Mar 29 12:03:25 2013) [sssd[pam]] [idle_handler] (0x2000): Terminating idle client [0xf33500][19]
>     (Fri Mar 29 12:03:25 2013) [sssd[pam]] [client_destructor] (0x2000): Terminated client [0xf33500][19]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[12749].
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0xf32cf0][19]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe!
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0xf32cf0][19]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0xf32cf0][19]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0xf32cf0][19]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering pam_cmd_authenticate
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'jhurt' matched without domain, user is jhurt
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): using default domain [(null)]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): user: jhurt
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): rhost: myotherhost.mydomain.com
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): authtok size: 5
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): newauthtok size: 0
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 12749
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/default/jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x41b300:3:jhurt at default]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [default][3][1][name=jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sbus_add_timeout] (0x2000): 0xf2efe0
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x41b300:3:jhurt at default]
>
>     ==> sssd_default.log <==
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 1649AE0
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_get_account_info] (0x0100): Got request for [3][1][name=jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x165c930
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x165ab20
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x165ab20 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x165c930 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x16521a0
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x165d9c0
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x16a7a90
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1651430
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x165d9c0 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x16521a0 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1653600
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1668370
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1651430 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x16a7a90 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1654990
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x165a610
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1668370 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1653600 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x165d9c0
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1653600
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x165a610 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1654990 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1653600 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x165d9c0 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): beginning to connect
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap.mydomain.com' is 'working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 389 for server 'ldap.mydomain.com' is 'not working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_port_status] (0x0100): Reseting the status of port 389 for server 'ldap.mydomain.com'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap.mydomain.com' is 'working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_resolve_server_process] (0x0200): Found address for server ldap.mydomain.com: [192.168.1.81] TTL 43200
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x4000): Using file descriptor [20] for LDAP connection.
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://ldap.mydomain.com:389/??base] with fd [20].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x165ac80], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedFeatures]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x165ac80], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_rootdse_done] (0x2000): Got rootdse
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_server_opts_from_rootdse] (0x0200): No known USN scheme is supported by this server!
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1364584706
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_cli_auth_step] (0x1000): No authentication requested or SASL auth forced off
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'ldap.mydomain.com' as 'working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [set_server_common_status] (0x0100): Marking server 'ldap.mydomain.com' as 'working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_id_op_connect_done] (0x2000): Old USN: 0, New USN: 0
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=mydomain,dc=com]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=jhurt)(objectclass=posixAccount))][dc=mydomain,dc=com].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 2
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_run_online_cb] (0x4000): Online call back list is empty, nothing to do.
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x165c820], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x165c820], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [uid=jhurt,ou=people,dc=mydomain,dc=com].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [uid]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [uidNumber]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [homeDirectory]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [gecos]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [shadowExpire]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [shadowLastChange]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [shadowMax]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [loginShell]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x165c820], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Storing the user
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_save_user] (0x4000): Save user
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_save_user] (0x2000): Adding originalDN [uid=jhurt,ou=people,dc=mydomain,dc=com] to attributes of [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original memberOf is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20130328213652Z] to attributes of [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): Original USN value is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_save_user] (0x1000): User principal is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowLastChange [15792] to attributes of [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowMax [900] to attributes of [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowExpire [18262] to attributes of [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): adUserAccountControl is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [jhurt].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_save_user] (0x0400): Storing info for user jhurt
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1656040
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1656040 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657e30
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1657f50 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657e30 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 2)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPrincipalName] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x16f3050
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x16f3050 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowMin] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowWarning] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x16f3050
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x16f3050 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowInactive] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [shadowFlag] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x16f3050
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x16f3050 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbLastPwdChange] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [krbPasswordExpiration] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x16f3050
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x16f3050 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [pwdAttribute] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedService] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x16f3050
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x16f3050 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adAccountExpires] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [adUserAccountControl] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x16f3050
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x16f3050 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [nsAccountLock] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [authorizedHost] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x16f3050
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x16f3050 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginDisabled] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginExpirationTime] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x16f3050
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x16f3050 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sysdb_remove_attrs] (0x2000): Removing attribute [ndsLoginAllowedTimeMap] from [jhurt]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1657f50
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1656160
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1656160 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1657f50 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 2)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Commit change
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x1655e00
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x1655f20
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x1655f20 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x1655e00 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_initgr_user] (0x4000): Process user's groups
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_initgr_rfc2307_next_base] (0x0400): Searching for groups with base [dc=mydomain,dc=com]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(memberuid=jhurt)(objectclass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=mydomain,dc=com].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 3
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x1656ff0], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x1656ff0], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=cns,ou=group,dc=mydomain,dc=com].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x1656ff0], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=devel-read,ou=group,dc=mydomain,dc=com].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x1656ff0], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=webcontrib,ou=group,dc=mydomain,dc=com].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x1656ff0], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x1656ff0], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=staff,ou=group,dc=mydomain,dc=com].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[0x1656ff0], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_generic_ext_done] (0x1000): Total count [0]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x165a380
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x165a430
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Destroying timer event 0x165a430 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): Ending timer event 0x165a380 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_initgr_common_store] (0x2000): Updating memberships for jhurt
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): start ldb transaction (nesting: 1)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 1)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_get_initgr_done] (0x4000): Initgroups done
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_id_op_destroy] (0x4000): releasing operation connection
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_id_op_done] (0x4000): releasing operation connection
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_add_timeout] (0x2000): 0x16a87a0
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16dae20], connected[1], ops[(nil)], ldap[0x1654d50]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_remove_timeout] (0x2000): 0x16a87a0
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 164EE00
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>
>     ==> sssd_pam.log <==
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0xf2efe0
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: F30C50
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [jhurt at default]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0xf3a530
>
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0xf3a650
>
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0xf3a650 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): Ending timer event 0xf3a530 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [jhurt at default]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [jhurt] added to PAM initgroup cache
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): domain: default
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): user: jhurt
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): service: sshd
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): rhost: myotherhost.mydomain.com
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): authtok size: 5
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): newauthtok size: 0
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 12749
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sbus_add_timeout] (0x2000): 0xf30500
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x41b300:3:jhurt at default]
>
>     ==> sssd_default.log <==
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 1649AE0
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_pam_handler] (0x0100): Got request with the following data
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): domain: default
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): user: jhurt
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): service: sshd
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): tty: ssh
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): ruser: 
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): rhost: myotherhost.mydomain.com
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok type: 1
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): authtok size: 5
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok type: 0
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): newauthtok size: 0
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): priv: 1
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [pam_print_data] (0x0100): cli_pid: 12749
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap.mydomain.com' is 'working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 389 for server 'ldap.mydomain.com' is 'working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap.mydomain.com' is 'working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_resolve_server_process] (0x1000): Saving the first resolved server
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_resolve_server_process] (0x0200): Found address for server ldap.mydomain.com: [192.168.1.81] TTL 43200
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldap://ldap.mydomain.com/'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x4000): Using file descriptor [21] for LDAP connection.
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://ldap.mydomain.com:389/??base] with fd [21].
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_sys_connect_done] (0x0100): Executing START TLS
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_result] (0x2000): Trace: sh[0x16527c0], connected[1], ops[0x1657410], ldap[0x1659e90]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_EXTENDED]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_connect_done] (0x0080): START TLS result: Success(0), (null)
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_connect_done] (0x0080): ldap_install_tls failed: [Connect error] [TLS error -8172:Peer's certificate issuer has been marked as not trusted by the user.]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_handle_release] (0x2000): Trace: sh[0x16527c0], connected[1], ops[(nil)], ldap[0x1659e90], destructor_lock[0], release_memory[0]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'ldap.mydomain.com' as 'not working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap.mydomain.com' is 'working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 389 for server 'ldap.mydomain.com' is 'not working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_server_status] (0x1000): Status of server 'ldap.mydomain.com' is 'working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [get_port_status] (0x1000): Port status of port 389 for server 'ldap.mydomain.com' is 'not working'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [fo_resolve_service_send] (0x0020): No available servers for service 'LDAP'
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_resolve_server_done] (0x1000): Server resolution failed: 5
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_mark_offline] (0x2000): Going offline!
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_run_offline_cb] (0x0080): Going offline. Running callbacks.
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Backend returned: (1, 9, <NULL>) [Provider is Offline (Authentication service cannot retrieve authentication info)]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sending result [9][default]
>
>     ==> sssd_pam.log <==
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0xf30500
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: F30C50
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_dp_process_reply] (0x0100): received: [9][default]
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [9].
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): start ldb transaction (nesting: 0)
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0xf32610
>
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0xf326c0
>
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0xf326c0 "ltdb_timeout"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): Ending timer event 0xf32610 "ltdb_callback"
>
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sysdb_cache_auth] (0x4000): Offline credentials expiration is [0] days.
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [check_failed_login_attempts] (0x4000): Failed login attempts [0], allowed failed login attempts [0], failed login delay [5].
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [sysdb_cache_auth] (0x0100): Cached credentials not available.
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [ldb] (0x4000): cancel ldb transaction (nesting: 0)
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_handle_cached_login] (0x1000): cached login returned: 9
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [9].
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [pam_reply] (0x0100): blen: 24
>     (Fri Mar 29 12:03:26 2013) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0xf32cf0][19]
>
>     ==> sssd_default.log <==
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [be_pam_handler_callback] (0x0100): Sent result [9][default]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [sdap_handle_release] (0x2000): Trace: sh[0x16dae20], connected[1], ops[(nil)], ldap[0x1654d50], destructor_lock[0], release_memory[0]
>     (Fri Mar 29 12:03:26 2013) [sssd[be[default]]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
>     (Fri Mar 29 12:03:30 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus conn: 163DDD0
>     (Fri Mar 29 12:03:30 2013) [sssd[be[default]]] [sbus_dispatch] (0x4000): Dispatching.
>     (Fri Mar 29 12:03:30 2013) [sssd[be[default]]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>
>     ==> sssd_pam.log <==
>     (Fri Mar 29 12:03:31 2013) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: F2D3B0
>     (Fri Mar 29 12:03:31 2013) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
>     (Fri Mar 29 12:03:31 2013) [sssd[pam]] [sbus_message_handler] (0x4000): Received SBUS method [ping]
>     (Fri Mar 29 12:03:31 2013) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [jhurt] removed from PAM initgroup cache
>
> Sorry that is so long.  Does this log output provide enough clues as
> to why it is not working? 
>
> I see some things that look suspicious like the "Port status of port
> 389 for server 'ldap.mydomain.com' is 'not working'" message, but I
> suspect that is a Red Herring, since myhost can connect to the ldap
> server in other ways, such as ldapsearch and getent passwd.
>
> What are your thoughts about why it is not allowing a successful login
> via ssh/sssd/pam?
>
> Again, thanks for the help.
>
> Wes
>

-- 
Wes Modes
Systems Designer, Developer, and Administrator
University Library ITS
University of California, Santa Cruz

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-devel/attachments/20130401/1bc36d6f/attachment.html>


More information about the sssd-devel mailing list