[SSSD] IPA client randomly lose memory of users

Qing Chang qchang at sri.utoronto.ca
Wed Dec 5 17:03:10 UTC 2012


On 05/12/2012 11:31 AM, Qing Chang wrote:
>
> 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
>
> _______________________________________________
> sssd-devel mailing list
> sssd-devel at lists.fedorahosted.org
> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
One more piece of info, it lost the memory again. Now I am pretty sure that if it
does not get the memory back by itself somehow, nothing will trigger it to do so.

I did a few of this: date; getent passwd shassan, I also asked the user to
open her Thunderbird, both actions just trigger this:
(Wed Dec  5 11:43:52 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 11:43:52 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 11:43:52 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 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got request 
for [4097][1][name=shassan]
(Wed Dec  5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Request 
processed. Returned 1,11,Fast reply - offline
(Wed Dec  5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got request 
for [4097][1][name=shassan]
(Wed Dec  5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Request 
processed. Returned 1,11,Fast reply - offline
(Wed Dec  5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got request 
for [4097][1][name=shassan]
(Wed Dec  5 11:43:52 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Request 
processed. Returned 1,11,Fast reply - offline

NOTHING else...

Sure enough, just before I hit send, it decided to get back the memory:
[root at dovecot2 sssd]# date; getent passwd shassan
Wed Dec  5 11:53:30 EST 2012
shassan:*:54184:541:Shazia Hassan:/home4/shassan:/bin/tcsh
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got request 
for [3][1][name=shassan]
(Wed Dec  5 11:53:33 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 11:53:33 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 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [objectClass]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [uid]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [userPassword]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [uidNumber]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [gidNumber]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [gecos]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [homeDirectory]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [loginShell]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [krbPrincipalName]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [cn]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [memberOf]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [nsUniqueId]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [modifyTimestamp]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [entryUSN]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [shadowLastChange]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [shadowMin]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [shadowMax]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [shadowWarning]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [shadowInactive]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [shadowExpire]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [shadowFlag]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [krbLastPwdChange]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [krbPasswordExpiration]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [pwdAttribute]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [authorizedService]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [accountExpires]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [userAccountControl]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [nsAccountLock]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [host]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [loginDisabled]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [loginExpirationTime]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [loginAllowedTimeMap]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [ipaSshPubKey]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x2000): 
ldap_search_ext called, msgid = 267
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[0x3c98c70], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[0x3c98c70], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done] (0x0400): Search 
result: Success(0), no errmsg set
(Wed Dec  5 11:53:33 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 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding original 
memberOf attributes to [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding 
original mod-Timestamp [20121205164344Z] to attributes of [shassan].
(Wed Dec  5 11:53:33 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 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding 
shadowLastChange [11472] to attributes of [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
shadowMin is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding 
shadowMax [99999] to attributes of [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding 
shadowWarning [7] to attributes of [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
shadowInactive is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
shadowExpire is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
shadowFlag is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding 
krbLastPwdChange [20121029140040Z] to attributes of [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding 
krbPasswordExpiration [20150417140040Z] to attributes of [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
pwdAttribute is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
authorizedService is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
adAccountExpires is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
adUserAccountControl is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
nsAccountLock is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
authorizedHost is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
ndsLoginDisabled is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
ndsLoginExpirationTime is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
ndsLoginAllowedTimeMap is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): 
sshPublicKey is not available for [shassan].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x0400): Storing info for 
user shassan
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [userPassword] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [shadowMin] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [shadowInactive] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [shadowExpire] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [shadowFlag] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [pwdAttribute] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [authorizedService] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [adAccountExpires] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [adUserAccountControl] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [nsAccountLock] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [authorizedHost] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [ndsLoginDisabled] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [ndsLoginExpirationTime] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [ndsLoginAllowedTimeMap] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_remove_attrs] (0x2000): Removing 
attribute [sshPublicKey] from [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_has_deref_support] (0x0400): The server 
supports deref method OpenLDAP
(Wed Dec  5 11:53:33 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 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [objectClass]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [cn]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [userPassword]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [gidNumber]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [member]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [nsUniqueId]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [modifyTimestamp]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [entryUSN]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x2000): 
ldap_search_ext called, msgid = 268
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[0x3c2c400], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
ldap_result found nothing!
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[0x3c2c400], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done] (0x0400): Search 
result: Success(0), no errmsg set
(Wed Dec  5 11:53:33 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 11:53:33 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 11:53:33 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 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_get_direct_parents] (0x1000): shassan 
is a member of 0 sysdb groups
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_initgr_store_user_memberships] 
(0x2000): Updating memberships for shassan
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [acctinfo_callback] (0x0100): Request 
processed. Returned 0,0,Success
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[(nil)], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
ldap_result found nothing!
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got request with 
the following data
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command: 
PAM_AUTHENTICATE
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain: 
sri.utoronto.ca
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user: shassan
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service: dovecot
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty: dovecot
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser: 
shassan at sri.utoronto.ca
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost: 142.76.25.62
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok type: 1
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok size: 9
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): newauthtok type: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): newauthtok size: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid: 18178
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [krb5_auth_send] (0x0100): No ccache file for 
user [shassan] found.
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [fo_resolve_service_send] (0x0100): Trying to 
resolve service 'IPA'
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000): Status of 
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec  5 11:53:33 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 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [fo_resolve_service_activate_timeout] 
(0x2000): Resolve timeout set to 10 seconds
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [get_server_status] (0x1000): Status of 
server 'ipa1.sri.utoronto.ca' is 'working'
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x1000): Saving the 
first resolved server
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_resolve_server_done] (0x0200): Found 
address for server ipa1.sri.utoronto.ca:  TTL 10800
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_resolve_callback] (0x0400): Constructed 
uri 'ldap://ipa1.sri.utoronto.ca'
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000): Setting up 
signal handler up for pid [18421]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_handler_setup] (0x2000): Signal 
handler set up for pid [18421]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [write_pipe_handler] (0x0400): All data has 
been sent!
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [read_pipe_handler] (0x0400): EOF received, 
client finished
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [krb5_child_done] (0x1000): TGT times are 
[1354726413][1354726413][1354812813][0].
(Wed Dec  5 11:53:33 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 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [set_server_common_status] (0x0100): Marking 
server 'ipa1.sri.utoronto.ca' as 'working'
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100): Backend 
returned: (0, 0, <NULL>) [Success]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100): Sending 
result [0][sri.utoronto.ca]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100): Sent 
result [0][sri.utoronto.ca]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x1000): Waiting for 
child [18421].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x0100): child [18421] 
finished successfully.
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x1000): Waiting for 
child [16176].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [child_sig_handler] (0x0020): waitpid failed 
[10][No child processes].
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sss_child_handler] (0x2000): waitpid failed 
[10]: No child processes
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got request with 
the following data
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain: 
sri.utoronto.ca
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user: shassan
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service: dovecot
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty: dovecot
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser: 
shassan at sri.utoronto.ca
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost: 142.76.25.62
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok type: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok size: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): newauthtok type: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): newauthtok size: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid: 18178
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_access_send] (0x0400): Performing 
access check for user [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_account_expired_rhds] (0x0400): 
Performing RHDS access check for user [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_retry] (0x0400): Performing cached HBAC 
evaluation
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_attrs_to_rule] (0x1000): Processing 
rule [allow_all]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_user_attrs_to_rule] (0x1000): 
Processing users for rule [allow_all]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200): Category is set 
to 'all'.
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_service_attrs_to_rule] (0x1000): 
Processing PAM services for rule [allow_all]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200): Category is set 
to 'all'.
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_thost_attrs_to_rule] (0x1000): 
Processing target hosts for rule [allow_all]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_get_category] (0x0200): Category is set 
to 'all'.
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_shost_attrs_to_rule] (0x0400): 
Processing source hosts for rule [allow_all]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_shost_attrs_to_rule] (0x2000): Source 
hosts disabled, setting ALL
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_eval_user_element] (0x1000): [1] groups 
for [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [hbac_eval_user_element] (0x1000): Added 
group [ipausers] for user [shassan]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_hbac_evaluate_rules] (0x0080): Access 
granted by HBAC rule [allow_all]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100): Backend 
returned: (0, 0, <NULL>) [Success]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100): Sending 
result [0][sri.utoronto.ca]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100): Sent 
result [0][sri.utoronto.ca]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got request with 
the following data
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command: 
PAM_OPEN_SESSION
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain: 
sri.utoronto.ca
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user: shassan
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service: dovecot
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty: dovecot
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser: 
shassan at sri.utoronto.ca
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost: 142.76.25.62
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok type: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok size: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): newauthtok type: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): newauthtok size: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid: 18178
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_get_selinux_send] (0x0400): Retrieving 
SELinux user mapping
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_get_selinux_send] (0x2000): Connection 
status is [online].
(Wed Dec  5 11:53:33 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 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [objectClass]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [memberOf]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x2000): 
ldap_search_ext called, msgid = 269
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[0x3f65030], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[0x3f65030], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done] (0x0400): Search 
result: Success(0), no errmsg set
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done] (0x1000): Total 
count [0]
(Wed Dec  5 11:53:33 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 11:53:33 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 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [objectClass]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [cn]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [memberUser]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [memberHost]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [seeAlso]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [ipaSELinuxUser]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [ipaEnabledFlag]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [userCategory]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [hostCategory]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): 
Requesting attrs: [ipaUniqueID]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x2000): 
ldap_search_ext called, msgid = 270
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[0x3e05cd0], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
ldap_result found nothing!
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[0x3e05cd0], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done] (0x0400): Search 
result: Success(0), no errmsg set
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done] (0x1000): Total 
count [0]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [ipa_selinux_get_maps_done] (0x0400): No 
SELinux user maps found!
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100): Backend 
returned: (0, 0, Success) [Success]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100): Sending 
result [4][sri.utoronto.ca]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler_callback] (0x0100): Sent 
result [4][sri.utoronto.ca]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
sh[0x3ccd810], connected[1], ops[(nil)], ldap[0x3f95840]
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: 
ldap_result found nothing!
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Got request with 
the following data
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): command: 
PAM_CLOSE_SESSION
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): domain: 
sri.utoronto.ca
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): user: shassan
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): service: dovecot
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): tty: dovecot
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): ruser: 
shassan at sri.utoronto.ca
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): rhost: 142.76.25.62
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok type: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): authtok size: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): newauthtok type: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): newauthtok size: 0
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): priv: 1
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [pam_print_data] (0x0100): cli_pid: 18178
(Wed Dec  5 11:53:33 2012) [sssd[be[sri.utoronto.ca]]] [be_pam_handler] (0x0100): Sending result 
[0][sri.utoronto.ca]


Thanks,
Qing



More information about the sssd-devel mailing list