one user can't be looked up

[Peter Moody]

(apologies if this gets sent twice, there was apparently an issue with
my subscription to the sssd-users list)

this is admittedly low priority since this is all just a test network
at this point, but we're looking to deploy sssd at work so I'd like to
make sure all the kinks I know about are well understood/fixed

I have an openldap install with the following users (pmoody, peter)
with uidNumbers (1001, 1002) respectively.

sssd works for both users from freebsd 11.2 prelease (sssd-1.11.7_11,
whew, that's old).

sssd works for pmoody from debian stretch (1.15.0-3). it does *not*
work for the user peter.

this is what happens for the user peter.

pmoody@deb:~$ sudo sss_cache -E
pmoody@deb:~$ getent passwd pmoody
pmoody:*:1001:500:Peter Moody:/home/pmoody:/bin/bash
pmoody@deb:~$ getent passwd peter
pmoody:*:1001:500:Peter Moody:/home/pmoody:/bin/bash
pmoody@deb:~$

I've tried version 1.16.1-1, same results.

These are the ldap entries for the aforementioned users:

# peter, people, x.com
dn: uid=peter,ou=people,dc=x,dc=com
cn: peter
givenName: peter
sn: moody
uid: peter
uidNumber: 1002
homeDirectory: /home/peter
objectClass: top
objectClass: posixAccount
objectClass: shadowAccount
objectClass: inetOrgPerson
objectClass: organizationalPerson
gidNumber: 500
loginShell: /usr/local/bin/fish

# pmoody, people, x.com
dn: uid=pmoody,ou=people,dc=x,dc=com
cn: Peter Moody
givenName: Peter
sn: Moody
uid: pmoody
uidNumber: 1001
homeDirectory: /home/pmoody
objectClass: top
objectClass: posixAccount
objectClass: shadowAccount
objectClass: inetOrgPerson
objectClass: organizationalPerson
loginShell: /usr/local/bin/fish
gidNumber: 500

on the debian box that exhibits this error, I see the following in the logs:

(Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
ldb transaction (nesting: 2)
(Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such
object](32)[ldb_wait from ldb_modify with LDB_WAIT_ALL: No such object
(32)]
(Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]]
[sysdb_set_cache_entry_attr] (0x0400): No such entry
(Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_set_entry_attr]
(0x0080): Cannot set attrs for
name=[e-mail],cn=users,cn=x.com,cn=sysdb, 2 [No such file or
directory]
(Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_store_user]
(0x0040): Cache update failed: 2
(Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
ldb transaction (nesting: 1)
(Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_store_user]
(0x0400): Error: 2 (No such file or directory)
(Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sdap_save_user]
(0x0020): Failed to save user [[e-mail]]
(Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sdap_save_users]
(0x0040): Failed to store user 0. Ignoring.

it kind of looks like what was reported here :
https://lists.fedorahosted.org/archives/list/[e-mail].o...

but I don't see a resolution to that report.

any suggestions on what I can do to fix this? logs/configs I can
provide to help isolate the problem?

Cheers,
peter

[Peter Moody]

are there any logs I can provide to help anyone figure out why this is
happening? I've (re-)confirmed that this behavior is present in 1.16.1
On Mon, Jun 18, 2018 at 9:04 PM Peter Moody  wrote:
> (apologies if this gets sent twice, there was apparently an issue with
> my subscription to the sssd-users list)
>
> this is admittedly low priority since this is all just a test network
> at this point, but we're looking to deploy sssd at work so I'd like to
> make sure all the kinks I know about are well understood/fixed
>
> I have an openldap install with the following users (pmoody, peter)
> with uidNumbers (1001, 1002) respectively.
>
> sssd works for both users from freebsd 11.2 prelease (sssd-1.11.7_11,
> whew, that's old).
>
> sssd works for pmoody from debian stretch (1.15.0-3). it does *not*
> work for the user peter.
>
> this is what happens for the user peter.
>
> pmoody@deb:~$ sudo sss_cache -E
> pmoody@deb:~$ getent passwd pmoody
> pmoody:*:1001:500:Peter Moody:/home/pmoody:/bin/bash
> pmoody@deb:~$ getent passwd peter
> pmoody:*:1001:500:Peter Moody:/home/pmoody:/bin/bash
> pmoody@deb:~$
>
> I've tried version 1.16.1-1, same results.
>
> These are the ldap entries for the aforementioned users:
>
> # peter, people, x.com
> dn: uid=peter,ou=people,dc=x,dc=com
> cn: peter
> givenName: peter
> sn: moody
> uid: peter
> uidNumber: 1002
> homeDirectory: /home/peter
> objectClass: top
> objectClass: posixAccount
> objectClass: shadowAccount
> objectClass: inetOrgPerson
> objectClass: organizationalPerson
> gidNumber: 500
> loginShell: /usr/local/bin/fish
>
> # pmoody, people, x.com
> dn: uid=pmoody,ou=people,dc=x,dc=com
> cn: Peter Moody
> givenName: Peter
> sn: Moody
> uid: pmoody
> uidNumber: 1001
> homeDirectory: /home/pmoody
> objectClass: top
> objectClass: posixAccount
> objectClass: shadowAccount
> objectClass: inetOrgPerson
> objectClass: organizationalPerson
> loginShell: /usr/local/bin/fish
> gidNumber: 500
>
> on the debian box that exhibits this error, I see the following in the logs:
>
> (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
> ldb transaction (nesting: 2)
> (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]]
> [sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such
> object](32)[ldb_wait from ldb_modify with LDB_WAIT_ALL: No such object
> (32)]
> (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]]
> [sysdb_set_cache_entry_attr] (0x0400): No such entry
> (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_set_entry_attr]
> (0x0080): Cannot set attrs for
> name=[e-mail],cn=users,cn=x.com,cn=sysdb, 2 [No such file or
> directory]
> (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_store_user]
> (0x0040): Cache update failed: 2
> (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
> ldb transaction (nesting: 1)
> (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_store_user]
> (0x0400): Error: 2 (No such file or directory)
> (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sdap_save_user]
> (0x0020): Failed to save user [[e-mail]]
> (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sdap_save_users]
> (0x0040): Failed to store user 0. Ignoring.
>
> it kind of looks like what was reported here :
> https://lists.fedorahosted.org/archives/list/[e-mail].o...
>
> but I don't see a resolution to that report.
>
> any suggestions on what I can do to fix this? logs/configs I can
> provide to help isolate the problem?
>
> Cheers,
> peter

[Sumit Bose]

On Thu, Jun 28, 2018 at 07:46:29PM -0700, Peter Moody wrote:
> are there any logs I can provide to help anyone figure out why this is
> happening? I've (re-)confirmed that this behavior is present in 1.16.1

Can you send your sssd.conf for a start.

bye,
Sumit
> On Mon, Jun 18, 2018 at 9:04 PM Peter Moody  wrote:
> > (apologies if this gets sent twice, there was apparently an issue with
> > my subscription to the sssd-users list)
> >
> > this is admittedly low priority since this is all just a test network
> > at this point, but we're looking to deploy sssd at work so I'd like to
> > make sure all the kinks I know about are well understood/fixed
> >
> > I have an openldap install with the following users (pmoody, peter)
> > with uidNumbers (1001, 1002) respectively.
> >
> > sssd works for both users from freebsd 11.2 prelease (sssd-1.11.7_11,
> > whew, that's old).
> >
> > sssd works for pmoody from debian stretch (1.15.0-3). it does *not*
> > work for the user peter.
> >
> > this is what happens for the user peter.
> >
> > pmoody@deb:~$ sudo sss_cache -E
> > pmoody@deb:~$ getent passwd pmoody
> > pmoody:*:1001:500:Peter Moody:/home/pmoody:/bin/bash
> > pmoody@deb:~$ getent passwd peter
> > pmoody:*:1001:500:Peter Moody:/home/pmoody:/bin/bash
> > pmoody@deb:~$
> >
> > I've tried version 1.16.1-1, same results.
> >
> > These are the ldap entries for the aforementioned users:
> >
> > # peter, people, x.com
> > dn: uid=peter,ou=people,dc=x,dc=com
> > cn: peter
> > givenName: peter
> > sn: moody
> > uid: peter
> > uidNumber: 1002
> > homeDirectory: /home/peter
> > objectClass: top
> > objectClass: posixAccount
> > objectClass: shadowAccount
> > objectClass: inetOrgPerson
> > objectClass: organizationalPerson
> > gidNumber: 500
> > loginShell: /usr/local/bin/fish
> >
> > # pmoody, people, x.com
> > dn: uid=pmoody,ou=people,dc=x,dc=com
> > cn: Peter Moody
> > givenName: Peter
> > sn: Moody
> > uid: pmoody
> > uidNumber: 1001
> > homeDirectory: /home/pmoody
> > objectClass: top
> > objectClass: posixAccount
> > objectClass: shadowAccount
> > objectClass: inetOrgPerson
> > objectClass: organizationalPerson
> > loginShell: /usr/local/bin/fish
> > gidNumber: 500
> >
> > on the debian box that exhibits this error, I see the following in the logs:
> >
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
> > ldb transaction (nesting: 2)
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]]
> > [sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such
> > object](32)[ldb_wait from ldb_modify with LDB_WAIT_ALL: No such object
> > (32)]
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]]
> > [sysdb_set_cache_entry_attr] (0x0400): No such entry
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_set_entry_attr]
> > (0x0080): Cannot set attrs for
> > name=[e-mail],cn=users,cn=x.com,cn=sysdb, 2 [No such file or
> > directory]
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_store_user]
> > (0x0040): Cache update failed: 2
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
> > ldb transaction (nesting: 1)
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_store_user]
> > (0x0400): Error: 2 (No such file or directory)
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sdap_save_user]
> > (0x0020): Failed to save user [[e-mail]]
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sdap_save_users]
> > (0x0040): Failed to store user 0. Ignoring.
> >
> > it kind of looks like what was reported here :
> > https://lists.fedorahosted.org/archives/list/[e-mail].o...
> >
> > but I don't see a resolution to that report.
> >
> > any suggestions on what I can do to fix this? logs/configs I can
> > provide to help isolate the problem?
> >
> > Cheers,
> > peter
>
> sssd-users mailing list -- [e-mail]
> To unsubscribe send an email to [e-mail]
> Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives: https://lists.fedoraproject.org/archives/list/[e-mail]....

[JOHE (John Hearns)]

Peter,

are you running the name serive cacheing daemon, nscd ?

________________________________
From: Sumit Bose 
Sent: 04 July 2018 08:44:49
To: [e-mail]
Subject: [SSSD-users] Re: one user can't be looked up

On Thu, Jun 28, 2018 at 07:46:29PM -0700, Peter Moody wrote:
> are there any logs I can provide to help anyone figure out why this is
> happening? I've (re-)confirmed that this behavior is present in 1.16.1

Can you send your sssd.conf for a start.

bye,
Sumit
> On Mon, Jun 18, 2018 at 9:04 PM Peter Moody  wrote:
> > (apologies if this gets sent twice, there was apparently an issue with
> > my subscription to the sssd-users list)
> >
> > this is admittedly low priority since this is all just a test network
> > at this point, but we're looking to deploy sssd at work so I'd like to
> > make sure all the kinks I know about are well understood/fixed
> >
> > I have an openldap install with the following users (pmoody, peter)
> > with uidNumbers (1001, 1002) respectively.
> >
> > sssd works for both users from freebsd 11.2 prelease (sssd-1.11.7_11,
> > whew, that's old).
> >
> > sssd works for pmoody from debian stretch (1.15.0-3). it does *not*
> > work for the user peter.
> >
> > this is what happens for the user peter.
> >
> > pmoody@deb:~$ sudo sss_cache -E
> > pmoody@deb:~$ getent passwd pmoody
> > pmoody:*:1001:500:Peter Moody:/home/pmoody:/bin/bash
> > pmoody@deb:~$ getent passwd peter
> > pmoody:*:1001:500:Peter Moody:/home/pmoody:/bin/bash
> > pmoody@deb:~$
> >
> > I've tried version 1.16.1-1, same results.
> >
> > These are the ldap entries for the aforementioned users:
> >
> > # peter, people, x.com
> > dn: uid=peter,ou=people,dc=x,dc=com
> > cn: peter
> > givenName: peter
> > sn: moody
> > uid: peter
> > uidNumber: 1002
> > homeDirectory: /home/peter
> > objectClass: top
> > objectClass: posixAccount
> > objectClass: shadowAccount
> > objectClass: inetOrgPerson
> > objectClass: organizationalPerson
> > gidNumber: 500
> > loginShell: /usr/local/bin/fish
> >
> > # pmoody, people, x.com
> > dn: uid=pmoody,ou=people,dc=x,dc=com
> > cn: Peter Moody
> > givenName: Peter
> > sn: Moody
> > uid: pmoody
> > uidNumber: 1001
> > homeDirectory: /home/pmoody
> > objectClass: top
> > objectClass: posixAccount
> > objectClass: shadowAccount
> > objectClass: inetOrgPerson
> > objectClass: organizationalPerson
> > loginShell: /usr/local/bin/fish
> > gidNumber: 500
> >
> > on the debian box that exhibits this error, I see the following in the logs:
> >
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
> > ldb transaction (nesting: 2)
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]]
> > [sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such
> > object](32)[ldb_wait from ldb_modify with LDB_WAIT_ALL: No such object
> > (32)]
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]]
> > [sysdb_set_cache_entry_attr] (0x0400): No such entry
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_set_entry_attr]
> > (0x0080): Cannot set attrs for
> > name=[e-mail],cn=users,cn=x.com,cn=sysdb, 2 [No such file or
> > directory]
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_store_user]
> > (0x0040): Cache update failed: 2
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
> > ldb transaction (nesting: 1)
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sysdb_store_user]
> > (0x0400): Error: 2 (No such file or directory)
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sdap_save_user]
> > (0x0020): Failed to save user [[e-mail]]
> > (Mon Jun 18 20:39:44 2018) [sssd[be[x.com]]] [sdap_save_users]
> > (0x0040): Failed to store user 0. Ignoring.
> >
> > it kind of looks like what was reported here :
> > https://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.fed...
> >
> > but I don't see a resolution to that report.
> >
> > any suggestions on what I can do to fix this? logs/configs I can
> > provide to help isolate the problem?
> >
> > Cheers,
> > peter
>
> sssd-users mailing list -- [e-mail]
> To unsubscribe send an email to [e-mail]
> Fedora Code of Conduct: https://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgetfedora...
> List Guidelines: https://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Ffedorapro...
> List Archives: https://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.fed...

_______________________________________________
sssd-users mailing list -- [e-mail]
To unsubscribe send an email to [e-mail]
Fedora Code of Conduct: https://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgetfedora...
List Guidelines: https://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Ffedorapro...
List Archives: https://emea01.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.fed...

[Peter Moody]

On Tue, Jul 3, 2018 at 11:45 PM Sumit Bose  wrote:
> On Thu, Jun 28, 2018 at 07:46:29PM -0700, Peter Moody wrote:
> > are there any logs I can provide to help anyone figure out why this is
> > happening? I've (re-)confirmed that this behavior is present in 1.16.1
>
> Can you send your sssd.conf for a start.

Thanks!

pjm@deb:~$ sudo cat /etc/sssd/sssd.conf
[nss]
debug_level = 0x06f0
filter_groups = root
filter_users  = root

reconnection_retries = 3
use_fully_qualified_names = true

[pam]
debug_level = 0x46f0
reconnection_retries = 3

[sssd]
debug_level = 0x06f0
config_file_version  = 2
reconnection_retries = 3
services = nss, pam
domains = X.COM

[domain/x.com]
debug_level    = 0x46f0
override_shell = /bin/bash
ignore_group_members = true
ldap_referrals = false
enumerate      = false
cache_credentials = true

id_provider     = ldap
access_provider = ldap
auth_provider   = ldap

ldap_uri         = ldaps://ldap.x.com
ldap_search_base = dc=x,dc=com
ldap_tls_cacert  = /etc/ldap/ca.pem

ldap_tls_reqcert      = demand
ldap_id_use_start_tls = true

dns_discovery_domain   = x.com

ldap_schema = rfc2307
ldap_access_order = expire
ldap_account_expire_policy = ad
ldap_force_upper_case_realm = true

ldap_user_search_base    = ou=people,dc=x,dc=com
ldap_group_search_base   = ou=groups,dc=x,dc=com
ldap_user_object_class   = inetOrgPerson
ldap_user_home_directory = homeDirectory
ldap_group_object_class  = posixGroup
# ldap_group_name = cn

#Bind credentials
ldap_default_bind_dn = <...>
ldap_default_authtok = <...>

pjm@deb:~$

[Jakub Hrozek]

On Fri, Jul 06, 2018 at 09:02:25AM -0700, Peter Moody wrote:
> On Tue, Jul 3, 2018 at 11:45 PM Sumit Bose  wrote:
> > On Thu, Jun 28, 2018 at 07:46:29PM -0700, Peter Moody wrote:
> > > are there any logs I can provide to help anyone figure out why this is
> > > happening? I've (re-)confirmed that this behavior is present in 1.16.1
> >
> > Can you send your sssd.conf for a start.
>
> Thanks!
>
> pjm@deb:~$ sudo cat /etc/sssd/sssd.conf
> [nss]
> debug_level = 0x06f0
> filter_groups = root
> filter_users  = root
>
> reconnection_retries = 3
> use_fully_qualified_names = true
>
> [pam]
> debug_level = 0x46f0
> reconnection_retries = 3
>
> [sssd]
> debug_level = 0x06f0
> config_file_version  = 2
> reconnection_retries = 3
> services = nss, pam
> domains = X.COM
>
> [domain/x.com]
> debug_level    = 0x46f0
> override_shell = /bin/bash
> ignore_group_members = true
> ldap_referrals = false
> enumerate      = false
> cache_credentials = true
>
> id_provider     = ldap
> access_provider = ldap
> auth_provider   = ldap
>
> ldap_uri         = ldaps://ldap.x.com
> ldap_search_base = dc=x,dc=com
> ldap_tls_cacert  = /etc/ldap/ca.pem
>
> ldap_tls_reqcert      = demand
> ldap_id_use_start_tls = true
>
> dns_discovery_domain   = x.com
>
> ldap_schema = rfc2307
> ldap_access_order = expire
> ldap_account_expire_policy = ad
> ldap_force_upper_case_realm = true
>
> ldap_user_search_base    = ou=people,dc=x,dc=com
> ldap_group_search_base   = ou=groups,dc=x,dc=com
> ldap_user_object_class   = inetOrgPerson
> ldap_user_home_directory = homeDirectory
> ldap_group_object_class  = posixGroup
> # ldap_group_name = cn
>
> #Bind credentials
> ldap_default_bind_dn = <...>
> ldap_default_authtok = <...>
>
> pjm@deb:~$

Can you post more context from the logs before the message that says the
ldb transaction is being cancelled?

[Peter Moody]

line breaks are in the original logs:

(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Ending
timer event 0x557c510ec600 "ltdb_callback"

(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): start ldb
transaction (nesting: 2)
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Added
timed event "ltdb_callback": 0x557c5111fdf0

(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Added
timed event "ltdb_timeout": 0x557c51135c00

(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Running
timer event 0x557c5111fdf0 "ltdb_callback"

(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000):
Destroying timer event 0x557c51135c00 "ltdb_timeout"

(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Ending
timer event 0x557c5111fdf0 "ltdb_callback"

(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
ldb transaction (nesting: 2)
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such
object](32)[ldb_wait from ldb_modify with LDB_WAIT_ALL: No such object
(32)]
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
[sysdb_set_cache_entry_attr] (0x0400): No such entry
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sysdb_set_entry_attr]
(0x0080): Cannot set attrs for
name=[e-mail],cn=users,cn=x.com,cn=sysdb, 2 [No such file or
directory]
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sysdb_store_user]
(0x0040): Cache update failed: 2
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
ldb transaction (nesting: 1)
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sysdb_store_user]
(0x0400): Error: 2 (No such file or directory)
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_save_user]
(0x0020): Failed to save user [[e-mail]]
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_save_users]
(0x0040): Failed to store user 0. Ignoring.
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): commit
ldb transaction (nesting: 0)
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_get_users_done]
(0x4000): Saving 1 Users - Done
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_id_op_done]
(0x4000): releasing operation connection
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_req_done] (0x0400):
DP Request [Account #2]: Request handler finished [0]: Success
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [_dp_req_recv] (0x0400):
DP Request [Account #2]: Receiving request data.
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
[dp_req_reply_list_success] (0x0400): DP Request [Account #2]:
Finished. Success.
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
[dp_table_value_destructor] (0x0400): Removing
[0:1:0x0001:1::x.com:name=[e-mail]] from reply table
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_req_destructor]
(0x0400): DP Request [Account #2]: Request removed.
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_req_destructor]
(0x0400): Number of active DP request: 0
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sbus_dispatch] (0x4000):
dbus conn: 0x557c510ec960
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sbus_dispatch] (0x4000):
Dispatching.
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
[dp_get_account_info_handler] (0x0200): Got request for
[0x2][BE_REQ_GROUP][idnumber=500]
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_attach_req] (0x0400):
DP Request [Account #3]: New request. Flags [0x0001].
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_attach_req] (0x0400):
Number of active DP request: 1
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_id_op_connect_step]
(0x4000): reusing cached connection
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
[sdap_get_groups_next_base] (0x0400): Searching for groups with base
[ou=groups,dc=x,dc=com]
(Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(gidNumber=500)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][ou=groups,dc=x,dc=com].

On Mon, Jul 9, 2018 at 4:38 AM Jakub Hrozek  wrote:
> On Fri, Jul 06, 2018 at 09:02:25AM -0700, Peter Moody wrote:
> > On Tue, Jul 3, 2018 at 11:45 PM Sumit Bose  wrote:
> > > On Thu, Jun 28, 2018 at 07:46:29PM -0700, Peter Moody wrote:
> > > > are there any logs I can provide to help anyone figure out why this is
> > > > happening? I've (re-)confirmed that this behavior is present in 1.16.1
> > >
> > > Can you send your sssd.conf for a start.
> >
> > Thanks!
> >
> > pjm@deb:~$ sudo cat /etc/sssd/sssd.conf
> > [nss]
> > debug_level = 0x06f0
> > filter_groups = root
> > filter_users  = root
> >
> > reconnection_retries = 3
> > use_fully_qualified_names = true
> >
> > [pam]
> > debug_level = 0x46f0
> > reconnection_retries = 3
> >
> > [sssd]
> > debug_level = 0x06f0
> > config_file_version  = 2
> > reconnection_retries = 3
> > services = nss, pam
> > domains = X.COM
> >
> > [domain/x.com]
> > debug_level    = 0x46f0
> > override_shell = /bin/bash
> > ignore_group_members = true
> > ldap_referrals = false
> > enumerate      = false
> > cache_credentials = true
> >
> > id_provider     = ldap
> > access_provider = ldap
> > auth_provider   = ldap
> >
> > ldap_uri         = ldaps://ldap.x.com
> > ldap_search_base = dc=x,dc=com
> > ldap_tls_cacert  = /etc/ldap/ca.pem
> >
> > ldap_tls_reqcert      = demand
> > ldap_id_use_start_tls = true
> >
> > dns_discovery_domain   = x.com
> >
> > ldap_schema = rfc2307
> > ldap_access_order = expire
> > ldap_account_expire_policy = ad
> > ldap_force_upper_case_realm = true
> >
> > ldap_user_search_base    = ou=people,dc=x,dc=com
> > ldap_group_search_base   = ou=groups,dc=x,dc=com
> > ldap_user_object_class   = inetOrgPerson
> > ldap_user_home_directory = homeDirectory
> > ldap_group_object_class  = posixGroup
> > # ldap_group_name = cn
> >
> > #Bind credentials
> > ldap_default_bind_dn = <...>
> > ldap_default_authtok = <...>
> >
> > pjm@deb:~$
>
> Can you post more context from the logs before the message that says the
> ldb transaction is being cancelled?
> _______________________________________________
> sssd-users mailing list -- [e-mail]
> To unsubscribe send an email to [e-mail]
> Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives: https://lists.fedoraproject.org/archives/list/[e-mail]....

[Jakub Hrozek]

On Tue, Jul 10, 2018 at 08:14:15PM -0700, Peter Moody wrote:
> line breaks are in the original logs:

Right, I saw this, but can I see more context earlier in the logs? See
inline..
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Ending
> timer event 0x557c510ec600 "ltdb_callback"
>
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): start ldb
> transaction (nesting: 2)
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Added
> timed event "ltdb_callback": 0x557c5111fdf0
>
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Added
> timed event "ltdb_timeout": 0x557c51135c00
>
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Running
> timer event 0x557c5111fdf0 "ltdb_callback"
>
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000):
> Destroying timer event 0x557c51135c00 "ltdb_timeout"
>
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): Ending
> timer event 0x557c5111fdf0 "ltdb_callback"
>
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
> ldb transaction (nesting: 2)

Here the transaction was cancelled.
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
> [sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such
> object](32)[ldb_wait from ldb_modify with LDB_WAIT_ALL: No such object
> (32)]

The error message sound line something we were trying to reference was
not present in the cache.
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
> [sysdb_set_cache_entry_attr] (0x0400): No such entry
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sysdb_set_entry_attr]
> (0x0080): Cannot set attrs for
> name=[e-mail],cn=users,cn=x.com,cn=sysdb, 2 [No such file or
> directory]

Could it be the user itself? I don't know exactly, that's why I asked
for more context..
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sysdb_store_user]
> (0x0040): Cache update failed: 2
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): cancel
> ldb transaction (nesting: 1)
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sysdb_store_user]
> (0x0400): Error: 2 (No such file or directory)
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_save_user]
> (0x0020): Failed to save user [[e-mail]]
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_save_users]
> (0x0040): Failed to store user 0. Ignoring.
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [ldb] (0x4000): commit
> ldb transaction (nesting: 0)
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_get_users_done]
> (0x4000): Saving 1 Users - Done
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_id_op_done]
> (0x4000): releasing operation connection
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_req_done] (0x0400):
> DP Request [Account #2]: Request handler finished [0]: Success
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [_dp_req_recv] (0x0400):
> DP Request [Account #2]: Receiving request data.
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
> [dp_req_reply_list_success] (0x0400): DP Request [Account #2]:
> Finished. Success.
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
> [dp_table_value_destructor] (0x0400): Removing
> [0:1:0x0001:1::x.com:name=[e-mail]] from reply table
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_req_destructor]
> (0x0400): DP Request [Account #2]: Request removed.
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_req_destructor]
> (0x0400): Number of active DP request: 0
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sbus_dispatch] (0x4000):
> dbus conn: 0x557c510ec960
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sbus_dispatch] (0x4000):
> Dispatching.
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
> [dp_get_account_info_handler] (0x0200): Got request for
> [0x2][BE_REQ_GROUP][idnumber=500]
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_attach_req] (0x0400):
> DP Request [Account #3]: New request. Flags [0x0001].
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [dp_attach_req] (0x0400):
> Number of active DP request: 1
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]] [sdap_id_op_connect_step]
> (0x4000): reusing cached connection
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
> [sdap_get_groups_next_base] (0x0400): Searching for groups with base
> [ou=groups,dc=x,dc=com]
> (Tue Jul 10 20:06:37 2018) [sssd[be[x.com]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(&(gidNumber=500)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][ou=groups,dc=x,dc=com].
>
> On Mon, Jul 9, 2018 at 4:38 AM Jakub Hrozek  wrote:
> > On Fri, Jul 06, 2018 at 09:02:25AM -0700, Peter Moody wrote:
> > > On Tue, Jul 3, 2018 at 11:45 PM Sumit Bose  wrote:
> > > > On Thu, Jun 28, 2018 at 07:46:29PM -0700, Peter Moody wrote:
> > > > > are there any logs I can provide to help anyone figure out why this is
> > > > > happening? I've (re-)confirmed that this behavior is present in 1.16.1
> > > >
> > > > Can you send your sssd.conf for a start.
> > >
> > > Thanks!
> > >
> > > pjm@deb:~$ sudo cat /etc/sssd/sssd.conf
> > > [nss]
> > > debug_level = 0x06f0
> > > filter_groups = root
> > > filter_users  = root
> > >
> > > reconnection_retries = 3
> > > use_fully_qualified_names = true
> > >
> > > [pam]
> > > debug_level = 0x46f0
> > > reconnection_retries = 3
> > >
> > > [sssd]
> > > debug_level = 0x06f0
> > > config_file_version  = 2
> > > reconnection_retries = 3
> > > services = nss, pam
> > > domains = X.COM
> > >
> > > [domain/x.com]
> > > debug_level    = 0x46f0
> > > override_shell = /bin/bash
> > > ignore_group_members = true
> > > ldap_referrals = false
> > > enumerate      = false
> > > cache_credentials = true
> > >
> > > id_provider     = ldap
> > > access_provider = ldap
> > > auth_provider   = ldap
> > >
> > > ldap_uri         = ldaps://ldap.x.com
> > > ldap_search_base = dc=x,dc=com
> > > ldap_tls_cacert  = /etc/ldap/ca.pem
> > >
> > > ldap_tls_reqcert      = demand
> > > ldap_id_use_start_tls = true
> > >
> > > dns_discovery_domain   = x.com
> > >
> > > ldap_schema = rfc2307
> > > ldap_access_order = expire
> > > ldap_account_expire_policy = ad
> > > ldap_force_upper_case_realm = true
> > >
> > > ldap_user_search_base    = ou=people,dc=x,dc=com
> > > ldap_group_search_base   = ou=groups,dc=x,dc=com
> > > ldap_user_object_class   = inetOrgPerson
> > > ldap_user_home_directory = homeDirectory
> > > ldap_group_object_class  = posixGroup
> > > # ldap_group_name = cn
> > >
> > > #Bind credentials
> > > ldap_default_bind_dn = <...>
> > > ldap_default_authtok = <...>
> > >
> > > pjm@deb:~$
> >
> > Can you post more context from the logs before the message that says the
> > ldb transaction is being cancelled?
> > _______________________________________________
> > sssd-users mailing list -- [e-mail]
> > To unsubscribe send an email to [e-mail]
> > Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
> > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> > List Archives: https://lists.fedoraproject.org/archives/list/[e-mail]....
>
> sssd-users mailing list -- [e-mail]
> To unsubscribe send an email to [e-mail]
> Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives: https://lists.fedoraproject.org/archives/list/[e-mail]....

[Peter Moody]

On Wed, Jul 11, 2018 at 12:39 AM Jakub Hrozek  wrote:
> On Tue, Jul 10, 2018 at 08:14:15PM -0700, Peter Moody wrote:
> > line breaks are in the original logs:
>
> Right, I saw this, but can I see more context earlier in the logs? See
> inline..

attached.

this is everything from sss_cache -E, to after 'id peter' returns info
for user pmoody
> Could it be the user itself? I don't know exactly, that's why I asked
> for more context..

it could be. I posted the current ldif's for both users in the first
message. is there something else I should be looking?

[Jakub Hrozek]

> On 13 Jul 2018, at 00:16, Peter Moody  wrote:
>
> On Wed, Jul 11, 2018 at 12:39 AM Jakub Hrozek  wrote:
> > On Tue, Jul 10, 2018 at 08:14:15PM -0700, Peter Moody wrote:
> > > line breaks are in the original logs:
> >
> > Right, I saw this, but can I see more context earlier in the logs? See
> > inline..
>
> attached.
>
> this is everything from sss_cache -E, to after 'id peter' returns info
> for user pmoody
> > Could it be the user itself? I don't know exactly, that's why I asked
> > for more context..
>
> it could be. I posted the current ldif's for both users in the first
> message. is there something else I should be looking?

Thank you for the logs, they show now clearly where the issue is happening, it looks like when setting the attributes for the user the user is not cached yet, which sounds bizzare because the user is looked up in the function before.

But I’m afraid that without stepping through the code with a debugger I won’t be able to find the reason..I guess I could add a patch with more debug data if you can apply it yourself (sorry, I have no idea how to patch a debian package) but currently the logs are not as helpful as I thought.

[Peter Moody]

On Thu, Jul 19, 2018 at 2:32 AM Jakub Hrozek  wrote:
> > On 13 Jul 2018, at 00:16, Peter Moody  wrote:
> >
> > On Wed, Jul 11, 2018 at 12:39 AM Jakub Hrozek  wrote:
> > > On Tue, Jul 10, 2018 at 08:14:15PM -0700, Peter Moody wrote:
> > > > line breaks are in the original logs:
> > >
> > > Right, I saw this, but can I see more context earlier in the logs? See
> > > inline..
> >
> > attached.
> >
> > this is everything from sss_cache -E, to after 'id peter' returns info
> > for user pmoody
> > > Could it be the user itself? I don't know exactly, that's why I asked
> > > for more context..
> >
> > it could be. I posted the current ldif's for both users in the first
> > message. is there something else I should be looking?
>
> Thank you for the logs, they show now clearly where the issue is happening, it looks like when setting the attributes for the user the user is not cached yet, which sounds bizzare because the user is looked up in the function before.
>
> But I’m afraid that without stepping through the code with a debugger I won’t be able to find the reason..I guess I could add a patch with more debug data if you can apply it yourself (sorry, I have no idea how to patch a debian package) but currently the logs are not as helpful as I thought.

looping in the debian package maintainers.

thread is here:
https://lists.fedoraproject.org/archives/list/[e-mail]....

the short version is that one user (in three) from my test setup can't
be looked up. I have pmoody, peter, and pjm with consecutive uids
(ldif in the link above). looking up pmoody and pjm works just fine.
looking up peter fails and returns info for pmoody. This is with sssd
1.16.2-1, with user info coming from openldap. Jakub, the redhat
maintainer for sssd has traced the issue down to:
> Thank you for the logs, they show now clearly where the issue is happening, it looks like when setting the attributes for the user the user is not cached yet, which sounds bizzare because the user is looked up in the function before.

thoughts?

cheers,
peter

[Peter Moody]

resent, subcribed to pkg-sssd-devel this time.

On Sat, Jul 21, 2018 at 10:13 PM Peter Moody  wrote:
> On Thu, Jul 19, 2018 at 2:32 AM Jakub Hrozek  wrote:
> > > On 13 Jul 2018, at 00:16, Peter Moody  wrote:
> > >
> > > On Wed, Jul 11, 2018 at 12:39 AM Jakub Hrozek  wrote:
> > > > On Tue, Jul 10, 2018 at 08:14:15PM -0700, Peter Moody wrote:
> > > > > line breaks are in the original logs:
> > > >
> > > > Right, I saw this, but can I see more context earlier in the logs? See
> > > > inline..
> > >
> > > attached.
> > >
> > > this is everything from sss_cache -E, to after 'id peter' returns info
> > > for user pmoody
> > > > Could it be the user itself? I don't know exactly, that's why I asked
> > > > for more context..
> > >
> > > it could be. I posted the current ldif's for both users in the first
> > > message. is there something else I should be looking?
> >
> > Thank you for the logs, they show now clearly where the issue is happening, it looks like when setting the attributes for the user the user is not cached yet, which sounds bizzare because the user is looked up in the function before.
> >
> > But I’m afraid that without stepping through the code with a debugger I won’t be able to find the reason..I guess I could add a patch with more debug data if you can apply it yourself (sorry, I have no idea how to patch a debian package) but currently the logs are not as helpful as I thought.
>
> looping in the debian package maintainers.
>
> thread is here:
> https://lists.fedoraproject.org/archives/list/[e-mail]....
>
> the short version is that one user (in three) from my test setup can't
> be looked up. I have pmoody, peter, and pjm with consecutive uids
> (ldif in the link above). looking up pmoody and pjm works just fine.
> looking up peter fails and returns info for pmoody. This is with sssd
> 1.16.2-1, with user info coming from openldap. Jakub, the redhat
> maintainer for sssd has traced the issue down to:
> > Thank you for the logs, they show now clearly where the issue is happening, it looks like when setting the attributes for the user the user is not cached yet, which sounds bizzare because the user is looked up in the function before.
>
> thoughts?
>
> cheers,
> peter