sssd/ssh authentication problem

[Wes Modes]

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:

[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,
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 128.114.163.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
(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]
(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
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib64/libpam.so.0", O_RDONLY)    = 3
open("/lib64/libpam_misc.so.0", O_RDONLY) = 3
open("/lib64/libc.so.6", O_RDONLY)      = 3
open("/lib64/libaudit.so.1", O_RDONLY)  = 3
open("/lib64/libdl.so.2", O_RDONLY)     = 3
open("/lib64/libcrypt.so.1", O_RDONLY)  = 3
open("/lib64/libfreebl3.so", O_RDONLY)  = 3
open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
open("/etc/nsswitch.conf", O_RDONLY)    = 3
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib64/libnss_files.so.2", O_RDONLY) = 3
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib64/libnss_sss.so.2", O_RDONLY) = 3
open("/lib64/libpthread.so.0", O_RDONLY) = 3
open("/var/lib/sss/mc/passwd", O_RDONLY|O_CLOEXEC) = 3
open("/etc/pam.d/su-l", O_RDONLY)       = 4
open("/etc/pam.d/su", O_RDONLY)         = 5
open("/lib64/security/pam_rootok.so", O_RDONLY) = 6
open("/etc/ld.so.cache", O_RDONLY)      = 6
open("/lib64/libselinux.so.1", O_RDONLY) = 6
open("/etc/pam.d/system-auth", O_RDONLY) = 6
open("/lib64/security/pam_env.so", O_RDONLY) = 7
open("/lib64/security/pam_fprintd.so", O_RDONLY) = 7
open("/etc/ld.so.cache", O_RDONLY)      = 7
open("/usr/lib64/libdbus-glib-1.so.2", O_RDONLY) = 7
open("/lib64/libdbus-1.so.3", O_RDONLY) = 7
open("/lib64/librt.so.1", O_RDONLY)     = 7
open("/lib64/libgobject-2.0.so.0", O_RDONLY) = 7
open("/lib64/libglib-2.0.so.0", O_RDONLY) = 7
open("/lib64/security/pam_unix.so", O_RDONLY) = 7
open("/etc/ld.so.cache", O_RDONLY)      = 7
open("/lib64/libnsl.so.1", O_RDONLY)    = 7
open("/lib64/security/pam_succeed_if.so", O_RDONLY) = 7
open("/lib64/security/pam_sss.so", O_RDONLY) = 7
open("/lib64/security/pam_deny.so", O_RDONLY) = 7
open("/etc/pam.d/su", O_RDONLY)         = 5
open("/etc/pam.d/system-auth", O_RDONLY) = 6
open("/lib64/security/pam_localuser.so", O_RDONLY) = 7
open("/lib64/security/pam_permit.so", O_RDONLY) = 7
open("/etc/pam.d/su", O_RDONLY)         = 5
open("/etc/pam.d/system-auth", O_RDONLY) = 6
open("/lib64/security/pam_cracklib.so", O_RDONLY) = 7
open("/etc/ld.so.cache", O_RDONLY)      = 7
open("/usr/lib64/libcrack.so.2", O_RDONLY) = 7
open("/lib64/security/pam_keyinit.so", O_RDONLY) = 5
open("/etc/pam.d/su", O_RDONLY)         = 5
open("/etc/pam.d/system-auth", O_RDONLY) = 6
open("/lib64/security/pam_limits.so", O_RDONLY) = 7
open("/lib64/security/pam_oddjob_mkhomedir.so", O_RDONLY) = 7
open("/lib64/security/pam_xauth.so", O_RDONLY) = 6
open("/etc/pam.d/other", O_RDONLY)      = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/proc/self/task/6324/attr/current", O_RDONLY) = 4
open("/proc/self/task/6324/attr/current", O_RDONLY) = 4
open("/proc/self/task/6324/attr/prev", O_RDONLY) = 4
open("/selinux/class/passwd/index", O_RDONLY) = 4
open("/selinux/class/passwd/perms", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) =
4
open("/selinux/class/passwd/perms/crontab", O_RDONLY) = 5
open("/selinux/class/passwd/perms/rootok", O_RDONLY) = 5
open("/selinux/class/passwd/perms/chsh", O_RDONLY) = 5
open("/selinux/class/passwd/perms/chfn", O_RDONLY) = 5
open("/selinux/class/passwd/perms/passwd", O_RDONLY) = 5
open("/selinux/access", O_RDWR)         = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/security/limits.conf", O_RDONLY) = 4
open("/etc/security/limits.d", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4
open("/usr/lib64/gconv/gconv-modules.cache", O_RDONLY) = 5
open("/etc/security/limits.d/90-nproc.conf", O_RDONLY) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/var/run/utmp", O_RDONLY|O_CLOEXEC) = 4
open("/etc/localtime", O_RDONLY)        = 4
-sh-4.1$ 

And selinux is permissive. 

What is happening here that I can su to this user but cannot ssh in?

Wes


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

[Jakub Hrozek]

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 128.114.163.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.

[Wes Modes]

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(a)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

[Wes Modes]

Any thoughts?  Reply at bottom...

On 3/29/2013 12:11 PM, Wes Modes wrote:
>  On 3/29/2013 1:18 AM, Jakub Hrozek wrote:
> > On Thu, Mar 28, 2013 at 04:34:47PM -0700, Wes Modes wrote:
> >> Hi, I've read a few of the posts to this list that have helped folks
> >> diagnose their auth problems with sssd.  However, I couldn't quite
> >> figure out how to diagnose mine.  Perhaps your expertise can help.
> >>
> >> I am running CentOS 6.3 with sssd-1.9.2.  I set up my ldap authorization
> >> like so:
> >>
> >> authconfig --enableldap --enableldapauth --enablemkhomedir
> --ldapserver=ldap.mydomain.edu --ldapbasedn="dc=mydomain,dc=com" --update
> >>
> >> After that, most everything worked like magic:
> >>
> > Hi Wes,
> >
> >> [root@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(a)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
>  
-- 
Wes Modes
Systems Designer, Developer, and Administrator
University Library ITS
University of California, Santa Cruz

[Jakub Hrozek]

On Fri, Mar 29, 2013 at 12:11:09PM -0700, Wes Modes wrote:
>     (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.] 
Here is your problem. While SSSD allows the use of anonymous bind for
retrieving identity information, authentication must be performed over
secure channel. The default (unless the URI starts with ldaps://) is
TLS.

See options ldap_tls_cacert, ldap_tls_cacertdir etc in man sssd-ldap.

>     (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]

[Wes Modes]

On 4/2/2013 2:42 AM, Jakub Hrozek wrote:
>  On Fri, Mar 29, 2013 at 12:11:09PM -0700, Wes Modes wrote:
> >    (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.]
>  Here is your problem. While SSSD allows the use of anonymous bind for
>  retrieving identity information, authentication must be performed over
>  secure channel. The default (unless the URI starts with ldaps://) is
>  TLS.
>
>  See options ldap_tls_cacert, ldap_tls_cacertdir etc in man sssd-ldap. 
Oh no, that's bad news for me, as I never could get TLS working on my
OpenLDAP server!

> >    (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-devel mailing list
>  sssd-devel(a)lists.fedorahosted.org
>  https://lists.fedorahosted.org/mailman/listinfo/sssd-devel 
-- 
Wes Modes
Systems Designer, Developer, and Administrator
University Library ITS
University of California, Santa Cruz

[Stephen Gallagher]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Tue 02 Apr 2013 02:40:45 PM EDT, Wes Modes wrote:
> > See options ldap_tls_cacert, ldap_tls_cacertdir etc in man
> > sssd-ldap.
>  
>  Oh no, that's bad news for me, as I never could get TLS working on
>  my OpenLDAP server!
>   
Based on the error you're seeing there, it sounds like TLS *is*
working, but you don't have a proper trust relationship. Most likely,
this means the server certificate is self-signed. There are two ways
to solve this: the correct way and the easy way.

The correct way:
Get a copy of the public key for the self-signed server certificate
and drop it on the client machine(s) then point the ldap_cacert at the
file.

The easy way:
Set the option 'ldap_tls_reqcert = allow' in the domain section of
sssd.conf. This will tell SSSD to blindly accept the certificate and
use it for encryption. This will provide you with encryption
protecting your authentications, but unlike the correct way it will
leave you open to a man-in-the-middle attack (if someone managed to
get you to connect to a different LDAP server, the client would
blindly trust it and send the password along.


The reason we do not allow non-TLS/SSL connections for authentication
is because the LDAP protocol requires that the passwords are sent in
plaintext within the protocol message, making it absolutely trivial to
steal passwords with a simple network sniffer like tcpdump or
wireshark/ethereal.

I'd suggest trying out the easy way above first so you can finish
testing out SSSD, then go back and implement the correct way once
you're comfortable with the rest of the system.
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.13 (GNU/Linux)
> Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
>
> iEYEARECAAYFAlFbMEQACgkQeiVVYja6o6MotACfcnqBg59IIj9JqKXyJPwH6qnz
> 6sUAniOW+Sin2RjdY9BB5rcy984CVhhx
> =7c2U
> -----END PGP SIGNATURE-----

[Wes Modes]

On 4/2/2013 12:23 PM, Stephen Gallagher wrote:
>  On Tue 02 Apr 2013 02:40:45 PM EDT, Wes Modes wrote:
>  >> See options ldap_tls_cacert, ldap_tls_cacertdir etc in man
>  >> sssd-ldap.
>
>  > Oh no, that's bad news for me, as I never could get TLS working on
>  > my OpenLDAP server!
>
>
>  Based on the error you're seeing there, it sounds like TLS *is*
>  working, but you don't have a proper trust relationship. Most likely,
>  this means the server certificate is self-signed. There are two ways
>  to solve this: the correct way and the easy way. 
I've wanted my ldap server to use TLS since I set it up, but struggled
with getting it to work (and maybe also understanding just how it did work).

First I tried the easy way and was excited to find that I was able to
connect to ssh with an LDAP user.  Woot.
>  The correct way:
>  Get a copy of the public key for the self-signed server certificate
>  and drop it on the client machine(s) then point the ldap_cacert at the
>  file. 
Next I tried the correct way.  I'm interpretting that to mean:  Get a
copy of the public key for the self-signed cert /on the LDAP server/ and
put it on the server running sssd, then point ldap_cacert in sssd.conf
to that cert, right?

Previously I was using an IPSCA-signed cert for *.mydomain.com.  But
just to simplify things and since I don't completely understand how
ssl/tls uses certs, I went back to the cert that was installed with
OpenLDAP (/etc/ssl/openldap2.4/ldap.pem) and copied it over to the sssd
server restarting both services.  After that I was able to connect.

Great. Now I can use ssh to disallow login and restrict LDAP users to sftp.

Thank you for the help.

>  The easy way:
>  Set the option 'ldap_tls_reqcert = allow' in the domain section of
>  sssd.conf. This will tell SSSD to blindly accept the certificate and
>  use it for encryption. This will provide you with encryption
>  protecting your authentications, but unlike the correct way it will
>  leave you open to a man-in-the-middle attack (if someone managed to
>  get you to connect to a different LDAP server, the client would
>  blindly trust it and send the password along.
>
>
>  The reason we do not allow non-TLS/SSL connections for authentication
>  is because the LDAP protocol requires that the passwords are sent in
>  plaintext within the protocol message, making it absolutely trivial to
>  steal passwords with a simple network sniffer like tcpdump or
>  wireshark/ethereal.
>
>  I'd suggest trying out the easy way above first so you can finish
>  testing out SSSD, then go back and implement the correct way once
>  you're comfortable with the rest of the system. 
-- 
Wes Modes
Systems Designer, Developer, and Administrator
University Library ITS
University of California, Santa Cruz