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