[SSSD] sssd/ssh authentication problem

Wes Modes wmodes at ucsc.edu
Fri Mar 29 19:11:09 UTC 2013


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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.fedorahosted.org/pipermail/sssd-devel/attachments/20130329/4f96cad1/attachment.html>


More information about the sssd-devel mailing list