[SSSD] IPA client randomly lose memory of users

Qing Chang qchang at sri.utoronto.ca
Tue Dec 4 17:45:06 UTC 2012


On 03/12/2012 4:24 PM, Simo Sorce wrote:
> On Mon, 2012-12-03 at 15:42 -0500, Qing Chang wrote:
>> On 03/12/2012 10:12 AM, Dmitri Pal wrote:
>>> On 12/02/2012 11:37 AM, Jakub Hrozek wrote:
>>>> On Sat, Dec 01, 2012 at 10:01:55PM -0500, Qing Chang wrote:
>>>>> On 30/11/2012 7:30 PM, Dmitri Pal wrote:
>>>>>> On 11/30/2012 05:21 PM, Qing Chang wrote:
>>>>>>> my dovecot IMAP server would randomly lose memory of users, as an
>>>>>>> example:
>>>>>>>
>>>>>>> Samba/NFS server knows this user:
>>>>>>> [root at smb2 shassan]# getent passwd bqiang
>>>>>>> bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
>>>>>>>
>>>>>>> But dovecot server does not:
>>>>>>> [root at dovecot2 ~]# getent passwd bqiang
>>>>>>>
>>>>>>> Only when I apply this:
>>>>>>> [root at dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb
>>>>>>> [root at dovecot2 ~]# service sssd restart
>>>>>>>
>>>>>>> It gets it:
>>>>>>> [root at dovecot2 ~]# getent passwd bqiang
>>>>>>> bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
>>>>>>>
>>>>>>> So far I have to deal with this for three users. It's quite possible
>>>>>>> that there are more than 3 that are affected, they were just patient
>>>>>>> enough to wait until dovecot "recovers its memory".
>>>>>>>
>>>>>>> =====
>>>>>>> sssd.x86_64                      1.8.0-32.el6
>>>>>>> @rhel-x86_64-server-6
>>>>>>> sssd-client.x86_64               1.8.0-32.el6
>>>>>>> @rhel-x86_64-server-6
>>>>>>> =====
>>>>>>>
>>>>>>> Your help is much appreciated.
>>>>>>>
>>>>>>> Thanks,
>>>>>>> Qing
>>>>>>>
>>>>>> Can it be because hierarchy changes in some way?
>>>>> I assume this is not a question for me? Please explain if it is, I do not have a clue what this is.
>>>> I think that Dmitri was asking if the group membreships may have changed
>>>> on the server between the two lookups. In other words, was the user
>>>> added to or removed from some groups on the server?
>>> Correct but not only this.
>>> Have the nesting of the groups the user is in changed in any way?
>>> For example a group was moved from one parent group to another.
>> I am no using nested groups.
>>
>> It happened to one of the three users today, I was putting in change for increasing
>> log level, by doing "service sssd restart", like Simo suspected, that along brought
>> back the memory:-( But I have to wait for another occurrence to catch the bug in
>> action...
>>
>> Will report back.
> Hi this is already valuable feedback, thanks a lot, focuses the problem
> in the nss responder.
>
> Simo.
>
It happened this morning, following I have  the logs spanning a few hours to
show how the state has changed (there may be a lot noises, it's level 8):

===== when it's working =====
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1].
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1].
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for 
[sri.utoronto.ca][4097][1][name=shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x17f2b40
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x17f2b40
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - 
DP error code: 0 errno: 0 error message: Success
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for 
[0x4267b0:3:shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for 
[sri.utoronto.ca][4099][1][name=shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x107cf60
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request 
[0x4267b0:3:shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x107cf60
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - 
DP error code: 0 errno: 0 error message: Success
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0400): Initgroups for 
[shassan at sri.utoronto.ca] completed
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: 
[0x4267b0:3:shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0400): Initgroups for 
[shassan at sri.utoronto.ca] completed
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [accept_fd_handler] (0x0100): Client connected!
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1].
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1].
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0400): Initgroups for 
[shassan at sri.utoronto.ca] completed
(Tue Dec  4 09:19:08 2012) [sssd[nss]] [accept_fd_handler] (0x0100): Client connected!

===== still working =====
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [accept_fd_handler] (0x0100): Client connected!
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1].
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1].
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_initgroups] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning..
(Tue Dec  4 09:34:50 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0400): Initgroups for 
[shassan at sri.utoronto.ca] completed
(Tue Dec  4 09:34:51 2012) [sssd[nss]] [client_recv] (0x0200): Client disconnected!

===== gone bad =====
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for 
[sri.utoronto.ca][4097][1][name=shassan]
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x15215f0
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x15215f0
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - 
DP error code: 1 errno: 11 error message: Fast reply - offline
(Tue Dec  4 10:50:49 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
(Tue Dec  4 10:50:49 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: 
[0x4267b0:1:shassan at sri.utoronto.ca]

===== second wave =====
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1].
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1].
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for 
[sri.utoronto.ca][4097][1][name=shassan]
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x11bd340
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x11bd340
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - 
DP error code: 1 errno: 11 error message: Fast reply - offline
(Tue Dec  4 11:34:31 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
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:34:31 2012) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
(Tue Dec  4 11:34:32 2012) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
(Tue Dec  4 11:34:32 2012) [sssd[nss]] [client_recv] (0x0200): Client disconnected!

===== user is asked to close and open thunderbird =====
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for 
[sri.utoronto.ca][4097][1][name=shassan]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sbus_add_timeout] (0x2000): 0xf66f90
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0xf66f90
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - 
DP error code: 1 errno: 11 error message: Fast reply - offline
(Tue Dec  4 11:38:06 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
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for 
[sri.utoronto.ca][4097][1][name=shassan]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sbus_add_timeout] (0x2000): 0xe65ed0
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0xe65ed0
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - 
DP error code: 1 errno: 11 error message: Fast reply - offline
(Tue Dec  4 11:38:06 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
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for 
[sri.utoronto.ca][4097][1][name=shassan]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x167ac00
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x167ac00
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - 
DP error code: 1 errno: 11 error message: Fast reply - offline
(Tue Dec  4 11:38:06 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
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [accept_fd_handler] (0x0100): Client connected!
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1].
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1].
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [nss_cmd_getpwnam] (0x0100): Requesting info for [shassan] 
from [<ALL>]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for 
[NCE/USER/sri.utoronto.ca/shassan]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for 
[shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for 
[sri.utoronto.ca][4097][1][name=shassan]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x1b34d70
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request 
[0x4267b0:1:shassan at sri.utoronto.ca]
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x1b34d70
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - 
DP error code: 1 errno: 11 error message: Fast reply - offline
(Tue Dec  4 11:38:06 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
(Tue Dec  4 11:38:06 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: 
[0x4267b0:1:shassan at sri.utoronto.ca]
===== end =====

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?

Thanks,
Qing



More information about the sssd-devel mailing list