[SSSD] IPA client randomly lose memory of users

Qing Chang qchang at sri.utoronto.ca
Wed Dec 5 16:31:04 UTC 2012


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.html
>>>>> 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 at 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 at 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 at dovecot2 sssd]# getent passwd shassan
shassan:*:54184:541:Shazia Hassan:/home4/shassan:/bin/tcsh
[root at 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 at 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 at 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 at 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 at 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 at 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




More information about the sssd-devel mailing list