my dovecot IMAP server would randomly lose memory of users, as an example:
Samba/NFS server knows this user: [root@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
It gets it: [root@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
On Fri, 2012-11-30 at 17:21 -0500, Qing Chang wrote:
my dovecot IMAP server would randomly lose memory of users, as an example:
Samba/NFS server knows this user: [root@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
Is it necessary to remove the ldb file, or does a simple restart 'fix' things ?
It gets it: [root@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.
Is it possible for you to raise the log level, or would that slow down your production environment too much ?
In that case do you have any hints on how we could reproduce this issue ? Have you notice if it happens periodically, or after specific events ?
Thanks, Simo.
On 30/11/2012 5:39 PM, Simo Sorce wrote:
On Fri, 2012-11-30 at 17:21 -0500, Qing Chang wrote:
my dovecot IMAP server would randomly lose memory of users, as an example:
Samba/NFS server knows this user: [root@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
Is it necessary to remove the ldb file, or does a simple restart 'fix' things ?
I could try that next time around when a user calls me, thought to clear the cache to be sure...
It gets it: [root@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.
Is it possible for you to raise the log level, or would that slow down your production environment too much ?
In that case do you have any hints on how we could reproduce this issue ? Have you notice if it happens periodically, or after specific events ?
I have asked the users, who had this problem recurring, to call me, I'll turn on debug log at that time.
BTW, to troubleshoot an unrelated problem, I set the debug level to 0xFFF0, is this overkill? ===== [nss] debug_level = 0xFFF0
[pam] debug_level = 0xFFF0 =====
Thanks, Simo.
On Sat, Dec 01, 2012 at 09:59:44PM -0500, Qing Chang wrote:
On 30/11/2012 5:39 PM, Simo Sorce wrote:
On Fri, 2012-11-30 at 17:21 -0500, Qing Chang wrote:
my dovecot IMAP server would randomly lose memory of users, as an example:
Samba/NFS server knows this user: [root@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
Is it necessary to remove the ldb file, or does a simple restart 'fix' things ?
I could try that next time around when a user calls me, thought to clear the cache to be sure...
It gets it: [root@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.
Is it possible for you to raise the log level, or would that slow down your production environment too much ?
In that case do you have any hints on how we could reproduce this issue ? Have you notice if it happens periodically, or after specific events ?
I have asked the users, who had this problem recurring, to call me, I'll turn on debug log at that time.
BTW, to troubleshoot an unrelated problem, I set the debug level to 0xFFF0, is this overkill? ===== [nss] debug_level = 0xFFF0
[pam] debug_level = 0xFFF0
I wouldn't say overkill, it may produce more info than necessary and then it might be harder to analyze the logs simply because of the size. I usually use debug_level 8, 9 is to verbose for my taste. But it really depends on the particular problem. In general, it is better to have more information than less :-)
What is the nature of this second problem? Maybe it would be nice to also include the debug_level directive in the domain section to see what the back end is doing..
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@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
It gets it: [root@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?
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@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
It gets it: [root@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.
Thanks, Qing
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@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
It gets it: [root@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?
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@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
It gets it: [root@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.
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
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@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
It gets it: [root@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.
Thanks, Qing
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
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@smb2 shassan]# getent passwd bqiang bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh
But dovecot server does not: [root@dovecot2 ~]# getent passwd bqiang
Only when I apply this: [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb [root@dovecot2 ~]# service sssd restart
It gets it: [root@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.
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@smb2 shassan]# getent passwd bqiang > bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh > > But dovecot server does not: > [root@dovecot2 ~]# getent passwd bqiang > > Only when I apply this: > [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb > [root@dovecot2 ~]# service sssd restart > > It gets it: > [root@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@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [shassan@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x4267b0:1:shassan@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@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:3:shassan@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@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@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0400): Initgroups for [shassan@sri.utoronto.ca] completed (Tue Dec 4 09:19:02 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x4267b0:3:shassan@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@sri.utoronto.ca] (Tue Dec 4 10:50:49 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:34:31 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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
On 12/04/2012 12:45 PM, Qing Chang wrote:
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@smb2 shassan]# getent passwd bqiang >> bqiang:*:47105:471:Beiping Qiang:/home2/bqiang:/bin/tcsh >> >> But dovecot server does not: >> [root@dovecot2 ~]# getent passwd bqiang >> >> Only when I apply this: >> [root@dovecot2 ~]# \rm /var/lib/sss/db/cache_sri.utoronto.ca.ldb >> [root@dovecot2 ~]# service sssd restart >> >> It gets it: >> [root@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@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [shassan@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x4267b0:1:shassan@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@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:3:shassan@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@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@sri.utoronto.ca] (Tue Dec 4 09:19:02 2012) [sssd[nss]] [nss_cmd_initgroups_search] (0x0400): Initgroups for [shassan@sri.utoronto.ca] completed (Tue Dec 4 09:19:02 2012) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x4267b0:3:shassan@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@sri.utoronto.ca] (Tue Dec 4 10:50:49 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:34:31 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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@sri.utoronto.ca] (Tue Dec 4 11:38:06 2012) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x4267b0:1:shassan@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@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@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?
This thread reminded me of the following thread https://lists.fedorahosted.org/pipermail/sssd-devel/2011-September/007058.ht...
Thanks, Qing _______________________________________________ sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
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.ht...
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.
Simo.
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.ht...
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.
Simo.
I am sorry, but what is the provider log?
Qing
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.ht...
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.
Simo.
I am sorry, but what is the provider log?
Oh sorry, I should have been more specific, the provider log is the log file named after your domain sssd_my.domain.name.log which contains logs about the connection to the server and might explain what error the provider got when it decided to go oflline (which may have also caused the incorrect deletion of the user from the cache).
Simo.
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.ht...
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".
Simo.
I am sorry, but what is the provider log?
Oh sorry, I should have been more specific, the provider log is the log file named after your domain sssd_my.domain.name.log which contains logs about the connection to the server and might explain what error the provider got when it decided to go oflline (which may have also caused the incorrect deletion of the user from the cache).
I agree the issue seems to be on the provider side, though. For some reason, the provider is going offline and it shouldn't.
What puzzles me is that Qing described the failing case as "open Thunderbird". I don't quite understand how that could fail except for a timeout? We should still return data from cache..
On 04/12/2012 2:50 PM, 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.ht...
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".
Simo.
I am sorry, but what is the provider log?
Oh sorry, I should have been more specific, the provider log is the log file named after your domain sssd_my.domain.name.log which contains logs about the connection to the server and might explain what error the provider got when it decided to go oflline (which may have also caused the incorrect deletion of the user from the cache).
I agree the issue seems to be on the provider side, though. For some reason, the provider is going offline and it shouldn't.
What puzzles me is that Qing described the failing case as "open Thunderbird". I don't quite understand how that could fail except for a timeout? We should still return data from cache..
sorry for the confusion, Jakub. I was just being specific that I asked her to close thunderbird and reopen it to trigger authentication attempt. At that point dovecot2 already lost her.
I have turned debug logging including provider log. Hopefully it happens before /var is fill up...
Thanks, Qing
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On Tue, 2012-12-04 at 14:59 -0500, Qing Chang wrote:
On 04/12/2012 2:50 PM, 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.ht...
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".
Simo.
I am sorry, but what is the provider log?
Oh sorry, I should have been more specific, the provider log is the log file named after your domain sssd_my.domain.name.log which contains logs about the connection to the server and might explain what error the provider got when it decided to go oflline (which may have also caused the incorrect deletion of the user from the cache).
I agree the issue seems to be on the provider side, though. For some reason, the provider is going offline and it shouldn't.
What puzzles me is that Qing described the failing case as "open Thunderbird". I don't quite understand how that could fail except for a timeout? We should still return data from cache..
sorry for the confusion, Jakub. I was just being specific that I asked her to close thunderbird and reopen it to trigger authentication attempt. At that point dovecot2 already lost her.
I have turned debug logging including provider log. Hopefully it happens before /var is fill up...
Feel free to turn down the NSS log if you want, or maybe set it to 0x0040 so you can more easily correlate the exact time when you get back this error: (Tue Dec 4 10:50:49 2012) [sssd[nss]] [nss_cmd_getpwnam_dp_callback] (0x0040): Unable to get information from Data Provider
Simo.
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.ht...
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.
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.ht...
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@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@SRI.UTORONTO.CA] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowLastChange [11472] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowMax [99999] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowWarning [7] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding krbLastPwdChange [20121029140040Z] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding krbPasswordExpiration [20150417140040Z] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): adUserAccountControl is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x0400): Storing info for user shassan (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_search_user_by_name] (0x0400): No such entry (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_add_user] (0x0400): Error: 17 (File exists) (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_store_user] (0x0080): A user with the same UID [54184] was removed from the cache (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_search_user_by_uid] (0x0400): No such entry (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450] (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [delayed_online_authentication_callback] (0x0200): Backend is online, starting delayed online authentication.
====== At no later than Wed Dec 5 10:46:10 EST 2012, it recalled the memory: [root@dovecot2 sssd]# getent passwd shassan shassan:*:54184:541:Shazia Hassan:/home4/shassan:/bin/tcsh [root@dovecot2 sssd]# date Wed Dec 5 10:46:10 EST 2012
Then a successful Thunderbird login triggers: (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got request for [3][1][name=shassan] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=sri,dc=utoronto,dc=ca] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=shassan)(objectclass=posixAccount))][cn =accounts,dc=sri,dc=utoronto,dc=ca]. (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 154 (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: sh[0x3ddec30], connected[1], ops[0x3f23520], ldap[0x3fdb450] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: sh[0x3ddec30], connected[1], ops[0x3f23520], ldap[0x3fdb450] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [uid=shassan,cn=users,cn=accounts,dc=sri,dc=utoronto,dc=ca ] to attributes of [shassan]. (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding original memberOf attributes to [shassan]. (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20121205154656Z] to attributes of [shassan]. (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding user principal [shassan@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@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@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@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@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
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.ht... 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@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@SRI.UTORONTO.CA] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowLastChange [11472] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowMax [99999] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding shadowWarning [7] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding krbLastPwdChange [20121029140040Z] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding krbPasswordExpiration [20150417140040Z] to attributes of [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): adUserAccountControl is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [shassan]. (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x0400): Storing info for user shassan (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_search_user_by_name] (0x0400): No such entry (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_add_user] (0x0400): Error: 17 (File exists) (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_store_user] (0x0080): A user with the same UID [54184] was removed from the cache (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sysdb_search_user_by_uid] (0x0400): No such entry (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: sh[0x3ddec30], connected[1], ops[(nil)], ldap[0x3fdb450] (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! (Wed Dec 5 10:45:48 2012) [sssd[be[sri.utoronto.ca]]] [delayed_online_authentication_callback] (0x0200): Backend is online, starting delayed online authentication.
====== At no later than Wed Dec 5 10:46:10 EST 2012, it recalled the memory: [root@dovecot2 sssd]# getent passwd shassan shassan:*:54184:541:Shazia Hassan:/home4/shassan:/bin/tcsh [root@dovecot2 sssd]# date Wed Dec 5 10:46:10 EST 2012
Then a successful Thunderbird login triggers: (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [be_get_account_info] (0x0100): Got request for [3][1][name=shassan] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=sri,dc=utoronto,dc=ca] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=shassan)(objectclass=posixAccount))][cn =accounts,dc=sri,dc=utoronto,dc=ca]. (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 154 (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: sh[0x3ddec30], connected[1], ops[0x3f23520], ldap[0x3fdb450] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_process_result] (0x2000): Trace: sh[0x3ddec30], connected[1], ops[0x3f23520], ldap[0x3fdb450] (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [uid=shassan,cn=users,cn=accounts,dc=sri,dc=utoronto,dc=ca ] to attributes of [shassan]. (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding original memberOf attributes to [shassan]. (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20121205154656Z] to attributes of [shassan]. (Wed Dec 5 10:47:15 2012) [sssd[be[sri.utoronto.ca]]] [sdap_save_user] (0x1000): Adding user principal [shassan@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@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@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@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@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@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@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@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@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@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@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@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
On Wed, 2012-12-05 at 11:31 -0500, Qing Chang wrote:
I see this:
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
but later on you report only logs after 10:45:05.
It would be useful to see what happened in the provider immediately before the error was returned. In particular I would like to see what error caused the provider to go offline and if it mentions removing the user in any way.
(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
This is interesting, do you have duplicated UIDs in your directory by chance ?
Simo.
On 05/12/2012 12:59 PM, Simo Sorce wrote:
On Wed, 2012-12-05 at 11:31 -0500, Qing Chang wrote:
I see this:
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
but later on you report only logs after 10:45:05.
It would be useful to see what happened in the provider immediately before the error was returned. In particular I would like to see what error caused the provider to go offline and if it mentions removing the user in any way.
the problem is we don't know when the loss of memory happened and it appears to me that nothing is logged about it. If you don't mind, I can send in more logs.
(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
This is interesting, do you have duplicated UIDs in your directory by chance ?
That was also what I was wondering about, but that's her id, it is unique.
Simo.
Thanks, Qing
On 12/05/2012 02:00 PM, Qing Chang wrote:
On 05/12/2012 12:59 PM, Simo Sorce wrote:
On Wed, 2012-12-05 at 11:31 -0500, Qing Chang wrote:
I see this:
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
but later on you report only logs after 10:45:05.
It would be useful to see what happened in the provider immediately before the error was returned. In particular I would like to see what error caused the provider to go offline and if it mentions removing the user in any way.
the problem is we don't know when the loss of memory happened and it appears to me that nothing is logged about it. If you don't mind, I can send in more logs.
(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
This is interesting, do you have duplicated UIDs in your directory by chance ?
That was also what I was wondering about, but that's her id, it is unique.
Can you compare the LDAP entry of this user to couple other users that are OK, use SSSD regularly and do not have an issue? May be there is something else in the user entry that would shed the light.
Also comparing this machine's sssd.conf to other machine's sssd.conf might give some hints.
Most likely we are hitting a specific configuration that during implementation was considered as impossible. Please send the logs to Simo and Jakub.
Simo.
Thanks, Qing _______________________________________________ sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On 05/12/2012 2:58 PM, Dmitri Pal wrote:
On 12/05/2012 02:00 PM, Qing Chang wrote:
On 05/12/2012 12:59 PM, Simo Sorce wrote:
On Wed, 2012-12-05 at 11:31 -0500, Qing Chang wrote:
I see this:
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
but later on you report only logs after 10:45:05.
It would be useful to see what happened in the provider immediately before the error was returned. In particular I would like to see what error caused the provider to go offline and if it mentions removing the user in any way.
the problem is we don't know when the loss of memory happened and it appears to me that nothing is logged about it. If you don't mind, I can send in more logs.
(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
This is interesting, do you have duplicated UIDs in your directory by chance ?
That was also what I was wondering about, but that's her id, it is unique.
Can you compare the LDAP entry of this user to couple other users that are OK, use SSSD regularly and do not have an issue? May be there is something else in the user entry that would shed the light.
there is nothing different after comparing with a few accounts. The cmd line I used is this: ldapsearch -LL -x -D 'cn=Directory Manager' -W -b 'dc=sri,dc=utoronto,dc=ca' '(uid=shassan)'
Could there be still something not showing by this cmd?
Also comparing this machine's sssd.conf to other machine's sssd.conf might give some hints.
all sssd.conf file are generated by ipa-client-install, they are all the same.
Most likely we are hitting a specific configuration that during implementation was considered as impossible. Please send the logs to Simo and Jakub.
will do.
Simo.
Thanks, Qing _______________________________________________ sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On Thu, Dec 06, 2012 at 11:37:41AM -0500, Qing Chang wrote:
On 05/12/2012 2:58 PM, Dmitri Pal wrote:
On 12/05/2012 02:00 PM, Qing Chang wrote:
On 05/12/2012 12:59 PM, Simo Sorce wrote:
On Wed, 2012-12-05 at 11:31 -0500, Qing Chang wrote:
I see this:
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
but later on you report only logs after 10:45:05.
It would be useful to see what happened in the provider immediately before the error was returned. In particular I would like to see what error caused the provider to go offline and if it mentions removing the user in any way.
the problem is we don't know when the loss of memory happened and it appears to me that nothing is logged about it. If you don't mind, I can send in more logs.
(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
This is interesting, do you have duplicated UIDs in your directory by chance ?
That was also what I was wondering about, but that's her id, it is unique.
Can you compare the LDAP entry of this user to couple other users that are OK, use SSSD regularly and do not have an issue? May be there is something else in the user entry that would shed the light.
there is nothing different after comparing with a few accounts. The cmd line I used is this: ldapsearch -LL -x -D 'cn=Directory Manager' -W -b 'dc=sri,dc=utoronto,dc=ca' '(uid=shassan)'
Could there be still something not showing by this cmd?
The term "uid" is kind of overloaded here. We're looking for non-unique UID numbers, not the uid LDAP attributes, which store the name.
Something like this might show the offender: ldapsearch -LL -x -D 'cn=Directory Manager' -W -b 'dc=sri,dc=utoronto,dc=ca' '(uidNumber=54184)'
On 06/12/2012 12:12 PM, Jakub Hrozek wrote:
On Thu, Dec 06, 2012 at 11:37:41AM -0500, Qing Chang wrote:
On 05/12/2012 2:58 PM, Dmitri Pal wrote:
On 12/05/2012 02:00 PM, Qing Chang wrote:
On 05/12/2012 12:59 PM, Simo Sorce wrote:
On Wed, 2012-12-05 at 11:31 -0500, Qing Chang wrote:
I see this:
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
but later on you report only logs after 10:45:05.
It would be useful to see what happened in the provider immediately before the error was returned. In particular I would like to see what error caused the provider to go offline and if it mentions removing the user in any way.
the problem is we don't know when the loss of memory happened and it appears to me that nothing is logged about it. If you don't mind, I can send in more logs.
(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
This is interesting, do you have duplicated UIDs in your directory by chance ?
That was also what I was wondering about, but that's her id, it is unique.
Can you compare the LDAP entry of this user to couple other users that are OK, use SSSD regularly and do not have an issue? May be there is something else in the user entry that would shed the light.
there is nothing different after comparing with a few accounts. The cmd line I used is this: ldapsearch -LL -x -D 'cn=Directory Manager' -W -b 'dc=sri,dc=utoronto,dc=ca' '(uid=shassan)'
Could there be still something not showing by this cmd?
The term "uid" is kind of overloaded here. We're looking for non-unique UID numbers, not the uid LDAP attributes, which store the name.
Something like this might show the offender: ldapsearch -LL -x -D 'cn=Directory Manager' -W -b 'dc=sri,dc=utoronto,dc=ca' '(uidNumber=54184)'
Thanks Jakub, there is a conflict uidNumber indeed.
What I tried was "getent passwd 54184", it gave me just one entry which got me to believe that it is unique...
Thank you all for your time and wisdom.
Qing
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On Thu, Dec 06, 2012 at 01:49:14PM -0500, Qing Chang wrote:
On 06/12/2012 12:12 PM, Jakub Hrozek wrote:
On Thu, Dec 06, 2012 at 11:37:41AM -0500, Qing Chang wrote:
On 05/12/2012 2:58 PM, Dmitri Pal wrote:
On 12/05/2012 02:00 PM, Qing Chang wrote:
On 05/12/2012 12:59 PM, Simo Sorce wrote:
On Wed, 2012-12-05 at 11:31 -0500, Qing Chang wrote:
I see this:
>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 but later on you report only logs after 10:45:05.
It would be useful to see what happened in the provider immediately before the error was returned. In particular I would like to see what error caused the provider to go offline and if it mentions removing the user in any way.
the problem is we don't know when the loss of memory happened and it appears to me that nothing is logged about it. If you don't mind, I can send in more logs.
>(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 This is interesting, do you have duplicated UIDs in your directory by chance ?
That was also what I was wondering about, but that's her id, it is unique.
Can you compare the LDAP entry of this user to couple other users that are OK, use SSSD regularly and do not have an issue? May be there is something else in the user entry that would shed the light.
there is nothing different after comparing with a few accounts. The cmd line I used is this: ldapsearch -LL -x -D 'cn=Directory Manager' -W -b 'dc=sri,dc=utoronto,dc=ca' '(uid=shassan)'
Could there be still something not showing by this cmd?
The term "uid" is kind of overloaded here. We're looking for non-unique UID numbers, not the uid LDAP attributes, which store the name.
Something like this might show the offender: ldapsearch -LL -x -D 'cn=Directory Manager' -W -b 'dc=sri,dc=utoronto,dc=ca' '(uidNumber=54184)'
Thanks Jakub, there is a conflict uidNumber indeed.
What I tried was "getent passwd 54184", it gave me just one entry which got me to believe that it is unique...
Right, the getent functions stop at first match.
Does your setup work fine after removing the duplicate UID?
On 2012/12/6 13:54, Jakub Hrozek wrote:
On Thu, Dec 06, 2012 at 01:49:14PM -0500, Qing Chang wrote:
On 06/12/2012 12:12 PM, Jakub Hrozek wrote:
On Thu, Dec 06, 2012 at 11:37:41AM -0500, Qing Chang wrote:
On 05/12/2012 2:58 PM, Dmitri Pal wrote:
On 12/05/2012 02:00 PM, Qing Chang wrote:
On 05/12/2012 12:59 PM, Simo Sorce wrote: > On Wed, 2012-12-05 at 11:31 -0500, Qing Chang wrote: > > I see this: > >> 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 > but later on you report only logs after 10:45:05. > > It would be useful to see what happened in the provider immediately > before the error was returned. In particular I would like to see what > error caused the provider to go offline and if it mentions removing the > user in any way. the problem is we don't know when the loss of memory happened and it appears to me that nothing is logged about it. If you don't mind, I can send in more logs. >> (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 > This is interesting, do you have duplicated UIDs in your directory by > chance ? That was also what I was wondering about, but that's her id, it is unique.
Can you compare the LDAP entry of this user to couple other users that are OK, use SSSD regularly and do not have an issue? May be there is something else in the user entry that would shed the light.
there is nothing different after comparing with a few accounts. The cmd line I used is this: ldapsearch -LL -x -D 'cn=Directory Manager' -W -b 'dc=sri,dc=utoronto,dc=ca' '(uid=shassan)'
Could there be still something not showing by this cmd?
The term "uid" is kind of overloaded here. We're looking for non-unique UID numbers, not the uid LDAP attributes, which store the name.
Something like this might show the offender: ldapsearch -LL -x -D 'cn=Directory Manager' -W -b 'dc=sri,dc=utoronto,dc=ca' '(uidNumber=54184)'
Thanks Jakub, there is a conflict uidNumber indeed.
What I tried was "getent passwd 54184", it gave me just one entry which got me to believe that it is unique...
Right, the getent functions stop at first match.
Does your setup work fine after removing the duplicate UID?
yes. I have removed the cron job.
Many thanks,
Qing
sssd-devel@lists.fedorahosted.org