On 04/12/2012 3:11 PM, Jakub Hrozek wrote:
On Tue, Dec 04, 2012 at 08:50:23PM +0100, Jakub Hrozek wrote:
> On Tue, Dec 04, 2012 at 02:38:34PM -0500, Simo Sorce wrote:
>> On Tue, 2012-12-04 at 14:31 -0500, Qing Chang wrote:
>>> On 04/12/2012 2:19 PM, Simo Sorce wrote:
>>>> On Tue, 2012-12-04 at 13:11 -0500, Dmitri Pal wrote:
>>>>>> A "service sssd restart" "fix" the
problem...
>>>>>>
>>>>>> I am thinking of running a cron job of above every 10 minutes to
>>>>> work
>>>>>> around
>>>>>> the problem while it is being troubleshoot. Is it a bad idea?
>>>> Well every 10 min. seem a bit too much, but I guess it depends how long
>>>> your user is willing to wait when it breaks :-/
>>>>> This thread reminded me of the following thread
>>>>>
https://lists.fedorahosted.org/pipermail/sssd-devel/2011-September/007058...
>>>> Yes Dmitri, this is very similar.
>>>>
>>>> Qing,
>>>> do you happen to have the provider logs as well ?
>>>>
>>>> It seemed confined to the nss responder, but it may be an actual
>>>> provider issue after all, seem like the provider is deleting the user
>>>> from the cache from time to time, and it shouldn't.
>>>>
> The provider has no means of deleting a user from cache, in the current
> model, the responders are pure "readers" and only the back ends are
> "writers".
I'm sorry, I swapped the terms responder and provider myself..
Simo was completely right, because the provider is the writer (at least
I got that part right) and for some reason the provider removed the
cached entry, then the nss responder could not read it from
cache while offline and return it.
Bottom line is, the domain logs Simo asked for would be welcome.
Sorry for the confusion.
_______________________________________________
sssd-devel mailing list
sssd-devel(a)lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-devel This is getting real
frustrating, sssd seems to play hide and seek with me, it
would forget and remeber at will:
=====
First failed "getent passwd shassan" triggers:
(Wed Dec 5 10:45:05 2012) [sssd[nss]] [nss_cmd_getpwnam_dp_callback] (0x0040): Unable to
get
information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Wed Dec 5 10:45:05 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got
request
for [4097][1][name=shassan]
(Wed Dec 5 10:45:05 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Request
processed. Returned 1,11,Fast reply - offline
=====
Although not 100% sure, (should have run "date;...",) second failed "getent
passwd shassan" triggers:
(Wed Dec 5 10:45:47 2012) [sssd[nss]] [nss_cmd_getpwnam_dp_callback] (0x0040): Unable to
get
information from Data Provider
Error: 1, 11, Fast reply - offline
Will try to return what we have in cache
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got
request
for [4097][1][name=shassan]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100):
Request
processed. Returned 1,11,Fast reply - offline
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [fo_resolve_service_send] (0x0100):
Trying to
resolve service 'IPA'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_port_status] (0x1000): Port
status of
port 0 for server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]]
[fo_resolve_service_activate_timeout]
(0x2000): Resolve timeout set to 10 seconds
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x1000):
Saving the
first resolved server
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x0200):
Found
address for server ipa1.sri.utoronto.ca: TTL 10800
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sss_ldap_init_send] (0x0400):
Setting 6
seconds timeout for connecting
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_ldap_connect_callback_add]
(0x1000):
New LDAP connection to [ldap://ipa1.sri.utoronto.ca:389/??base] with fd
[46].
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(objectclass=*)][].
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [*]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [altServer]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [namingContexts]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedControl]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedExtension]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedFeatures]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedLDAPVersion]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [supportedSASLMechanisms]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [defaultNamingContext]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [lastUSN]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [highestCommittedUSN]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 1
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3e02c80], ldap[0x3fdb450]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3e02c80], ldap[0x3fdb450]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_kinit_send] (0x0400):
Attempting kinit
(default, host/dovecot2.sri.utoronto.ca, SRI.UTORONTO.CA, 86400)
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_kinit_next_kdc] (0x1000):
Resolving
next KDC for service IPA
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [fo_resolve_service_send] (0x0100):
Trying to
resolve service 'IPA'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_port_status] (0x1000): Port
status of
port 0 for server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]]
[fo_resolve_service_activate_timeout]
(0x2000): Resolve timeout set to 10 seconds
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x1000):
Saving the
first resolved server
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x0200):
Found
address for server ipa1.sri.utoronto.ca: TTL 10800
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_kinit_kdc_resolved] (0x1000):
KDC
resolved, attempting to get TGT...
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [create_tgt_req_send_buffer]
(0x1000): buffer
size: 60
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Setting up
signal handler up for pid [14590]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Signal
handler set up for pid [14590]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [set_tgt_child_timeout] (0x0400):
Setting 6
seconds timeout for tgt child
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [write_pipe_handler] (0x0400): All
data has
been sent!
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [read_pipe_handler] (0x0400): EOF
received,
client finished
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_tgt_recv] (0x0400): Child
responded: 0 [FILE:/var/lib/sss/db/ccache_SRI.UTORONTO.CA], expired on [135480
8747]
(Wed Dec 5 10:45:47 2012) [sssd[be[sri.utoronto.ca]]] [sasl_bind_send] (0x0100):
Executing sasl
bind mech: GSSAPI, user: host/dovecot2.sri.utoronto.ca
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x1000):
Waiting for
child [14590].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x0100): child
[14590]
finished successfully.
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sss_child_handler] (0x2000):
waitpid failed
[10]: No child processes
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [fo_set_port_status] (0x0100):
Marking port 0
of server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [set_server_common_status]
(0x0100): Marking
server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_id_op_connect_done] (0x2000):
Old USN:
358742, New USN: 364519
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_users_next_base]
(0x0400):
Searching for users with base [cn=accounts,dc=sri,dc=utoronto,dc=ca]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(&(uid=shassan)(objectclass=posixAccount))][cn
=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uid]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userPassword]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uidNumber]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gidNumber]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gecos]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [homeDirectory]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginShell]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPrincipalName]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberOf]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsUniqueId]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [modifyTimestamp]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [entryUSN]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowLastChange]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMin]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMax]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowWarning]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowInactive]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowExpire]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowFlag]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbLastPwdChange]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPasswordExpiration]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [pwdAttribute]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [authorizedService]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [accountExpires]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userAccountControl]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsAccountLock]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [host]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginDisabled]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginExpirationTime]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginAllowedTimeMap]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaSshPubKey]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 5
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [be_run_online_cb] (0x0080): Going
online.
Running callbacks.
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f8af00], ldap[0x3fdb450]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f8af00], ldap[0x3fdb450]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_users_process] (0x0400):
Search for
users, returned 1 results.
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original DN [uid=shassan,cn=users,cn=accounts,dc=sri,dc=utoronto,dc=ca
] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
original
memberOf attributes to [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original mod-Timestamp [20121205133521Z] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
user
principal [shassan(a)SRI.UTORONTO.CA] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowLastChange [11472] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowMin is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowMax [99999] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowWarning [7] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowInactive is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowExpire is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowFlag is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbLastPwdChange [20121029140040Z] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbPasswordExpiration [20150417140040Z] to attributes of [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
pwdAttribute is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedService is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adAccountExpires is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adUserAccountControl is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
nsAccountLock is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedHost is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginDisabled is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginExpirationTime is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginAllowedTimeMap is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
sshPublicKey is not available for [shassan].
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x0400): Storing
info for
user shassan
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_search_user_by_name]
(0x0400): No such
entry
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_add_user] (0x0400): Error:
17 (File
exists)
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_store_user] (0x0080): A user
with the
same UID [54184] was removed from the cache
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_search_user_by_uid]
(0x0400): No such
entry
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450]
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]]
[delayed_online_authentication_callback]
(0x0200): Backend is online, starting delayed online authentication.
======
At no later than Wed Dec 5 10:46:10 EST 2012, it recalled the memory:
[root@dovecot2 sssd]# getent passwd shassan
shassan:*:54184:541:Shazia Hassan:/home4/shassan:/bin/tcsh
[root@dovecot2 sssd]# date
Wed Dec 5 10:46:10 EST 2012
Then a successful Thunderbird login triggers:
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got
request
for [3][1][name=shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_initgr_next_base]
(0x0400):
Searching for users with base [cn=accounts,dc=sri,dc=utoronto,dc=ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(&(uid=shassan)(objectclass=posixAccount))][cn
=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uid]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userPassword]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [uidNumber]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gidNumber]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gecos]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [homeDirectory]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginShell]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPrincipalName]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberOf]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsUniqueId]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [modifyTimestamp]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [entryUSN]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowLastChange]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMin]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowMax]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowWarning]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowInactive]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowExpire]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [shadowFlag]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbLastPwdChange]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [krbPasswordExpiration]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [pwdAttribute]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [authorizedService]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [accountExpires]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userAccountControl]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsAccountLock]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [host]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginDisabled]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginExpirationTime]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [loginAllowedTimeMap]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaSshPubKey]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 154
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f23520], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f23520], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original DN [uid=shassan,cn=users,cn=accounts,dc=sri,dc=utoronto,dc=ca
] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
original
memberOf attributes to [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
original mod-Timestamp [20121205154656Z] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding
user
principal [shassan(a)SRI.UTORONTO.CA] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowLastChange [11472] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowMin is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowMax [99999] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
shadowWarning [7] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowInactive is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowExpire is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
shadowFlag is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbLastPwdChange [20121029140040Z] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding
krbPasswordExpiration [20150417140040Z] to attributes of [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
pwdAttribute is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedService is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adAccountExpires is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
adUserAccountControl is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
nsAccountLock is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
authorizedHost is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginDisabled is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginExpirationTime is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
ndsLoginAllowedTimeMap is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr]
(0x2000):
sshPublicKey is not available for [shassan].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x0400): Storing
info for
user shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [userPassword] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowMin] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowInactive] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowExpire] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [shadowFlag] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [pwdAttribute] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [authorizedService] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [adAccountExpires] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [adUserAccountControl] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [nsAccountLock] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [authorizedHost] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [ndsLoginDisabled] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [ndsLoginExpirationTime] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [ndsLoginAllowedTimeMap] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000):
Removing
attribute [sshPublicKey] from [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_has_deref_support] (0x0400):
The server
supports deref method OpenLDAP
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(&(objectclass=posixGroup)(cn=*))][cn=ipausers
,cn=groups,cn=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userPassword]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [gidNumber]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [member]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [nsUniqueId]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [modifyTimestamp]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [entryUSN]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 155
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3efbd90], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3efbd90], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_initgr_nested_search]
(0x0040): Search
for group cn=ipausers,cn=groups,cn=accounts,dc=sri,dc=utoronto,dc=ca,
returned 0 results. Skipping
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]]
[sdap_initgr_store_user_memberships]
(0x1000): The user shassan is a direct member of 0 LDAP groups
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_get_direct_parents]
(0x2000):
searching sysdb with filter [(&(objectClass=group)(member=name=shassan,cn=use
rs,cn=sri.utoronto.ca,cn=sysdb))]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_get_direct_parents]
(0x1000): shassan
is a member of 0 sysdb groups
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]]
[sdap_initgr_store_user_memberships]
(0x2000): Updating memberships for shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [acctinfo_callback] (0x0100):
Request
processed. Returned 0,0,Success
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command:
PAM_AUTHENTICATE
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 9
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid:
13707
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [check_for_valid_tgt] (0x1000): TGT
end time
[1354808817].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [check_for_valid_tgt] (0x0080): TGT
is valid.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [fo_resolve_service_send] (0x0100):
Trying to
resolve service 'IPA'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [get_port_status] (0x1000): Port
status of
port 0 for server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]]
[fo_resolve_service_activate_timeout]
(0x2000): Resolve timeout set to 10 seconds
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000):
Status of
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x1000):
Saving the
first resolved server
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x0200):
Found
address for server ipa1.sri.utoronto.ca: [142.76.29.27] TTL 10800
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_resolve_callback] (0x0400):
Constructed
uri 'ldap://ipa1.sri.utoronto.ca'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Setting up
signal handler up for pid [14717]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000):
Signal
handler set up for pid [14717]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [write_pipe_handler] (0x0400): All
data has
been sent!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [read_pipe_handler] (0x0400): EOF
received,
client finished
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [krb5_child_done] (0x1000): TGT
times are
[1354722435][1354722435][1354808835][0].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [fo_set_port_status] (0x0100):
Marking port 0
of server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [set_server_common_status]
(0x0100): Marking
server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [safe_remove_old_ccache_file]
(0x1000): New
and old ccache file are the same, no one will be deleted.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Backend
returned: (0, 0, <NULL>) [Success]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sending
result [0][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sent
result [0][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x1000):
Waiting for
child [14717].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x0100): child
[14717]
finished successfully.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sss_child_handler] (0x2000):
waitpid failed
[10]: No child processes
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command:
PAM_ACCT_MGMT
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid:
13707
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_access_send] (0x0400):
Performing
access check for user [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_account_expired_rhds]
(0x0400):
Performing RHDS access check for user [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_retry] (0x0400): Performing
cached HBAC
evaluation
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_attrs_to_rule] (0x1000):
Processing
rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_user_attrs_to_rule] (0x1000):
Processing users for rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200):
Category is set
to 'all'.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_service_attrs_to_rule]
(0x1000):
Processing PAM services for rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200):
Category is set
to 'all'.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_thost_attrs_to_rule]
(0x1000):
Processing target hosts for rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200):
Category is set
to 'all'.
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_shost_attrs_to_rule]
(0x0400):
Processing source hosts for rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_shost_attrs_to_rule]
(0x2000): Source
hosts disabled, setting ALL
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_eval_user_element] (0x1000):
[1] groups
for [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [hbac_eval_user_element] (0x1000):
Added
group [ipausers] for user [shassan]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_hbac_evaluate_rules] (0x0080):
Access
granted by HBAC rule [allow_all]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Backend
returned: (0, 0, <NULL>) [Success]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sending
result [0][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sent
result [0][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command:
PAM_OPEN_SESSION
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid:
13707
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_get_selinux_send] (0x0400):
Retrieving
SELinux user mapping
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_get_selinux_send] (0x2000):
Connection
status is [online].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(&(objectClass=ipaHost)(fqdn=dovecot2.sri.utor
onto.ca))][cn=accounts,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberOf]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 156
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f62e80], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f62e80], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x1000): Total
count [0]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_selinux_get_maps_next]
(0x0400): Trying
to fetch SELinux maps with following parameters: [2][(null)][cn=selin
ux,dc=sri,dc=utoronto,dc=ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x0400): calling
ldap_search_ext with [(&(objectclass=ipaselinuxusermap)(ipaEnabledFl
ag=TRUE))][cn=selinux,dc=sri,dc=utoronto,dc=ca].
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [objectClass]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [cn]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberUser]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [memberHost]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [seeAlso]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaSELinuxUser]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaEnabledFlag]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [userCategory]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [hostCategory]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x1000):
Requesting attrs: [ipaUniqueID]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step]
(0x2000):
ldap_search_ext called, msgid = 157
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f8b800], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[0x3f8b800], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x0400): Search
result: Success(0), no errmsg set
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done]
(0x1000): Total
count [0]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [ipa_selinux_get_maps_done]
(0x0400): No
SELinux user maps found!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Backend
returned: (0, 0, Success) [Success]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sending
result [4][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100):
Sent
result [4][sri.utoronto.ca]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450]
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000):
Trace:
ldap_result found nothing!
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got
request with
the following data
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command:
PAM_CLOSE_SESSION
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain:
sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user:
shassan
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty:
dovecot
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser:
shassan(a)sri.utoronto.ca
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost:
142.76.25.62
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok
size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid:
13707
(Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Sending
result
[0][sri.utoronto.ca]
I hope this is enough info for you. I am going to put in the cron job now...
Thanks,
Qing