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@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@myotherhost]$ ssh jhurt@myhost
jhurt@myhost's password: 
Permission denied, please try again.

And over on myhost with sshd debugging mode:

[root@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@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@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@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@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@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@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@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@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@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@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@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@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@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