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