Phantom Group upon login

[Chris Hartman]

Hi guys,

Weird problem here. Running Ubuntu with SSSD 1.9.5.

Upon login after a long period between consecutive logins by the same user,
I receive the following error message:

groups: cannot find name for group ID 1596003661

`id` yields this:
> USER@smarty:~$ id

uid=1596001141(USER) gid=1596000513(domain users) groups=1596000513(domain
> users),1596001142(radioworksusers),1596001642(nixdesktopusers),1596001643(nixserverusers),1596003180(puppetmakers),1596003206(drupal_admin),1596003661

An immediate subsequent login on the same system by the same user fails to
produce the error message and the phantom group disappears from `id` output:
> USER@smarty:~$ id

uid=1596001141(USER) gid=1596000513(domain users) groups=1596000513(domain
> users),1596001142(radioworksusers),1596001642(nixdesktopusers),1596001643(nixserverusers),1596003180(puppetmakers),1596003206(drupal_admin)

I've also just noticed that the group ID reported is not consistent but can
vary. I've searched my AD server for a group objectSID in question but have
not found one; the group does not exist.

There seem to be no negative side effects aside from the error message and
unmapped GID in the output of the `id` command.

My config:
> [sssd]
> config_file_version = 2
> debug_level = 0
> reconnection_retries = 3
> sbus_timeout = 30
> services = nss, pam
> domains = DOMAIN
>
> [pam]
> debug_level = 0

[nss]
> debug_level = 0
> filter_users =
> root,ldap,named,avahi,haldaemon,dbus,radvd,tomcat,radiusd,news,mailman,nscd,gdm
> filter_groups =
> root,ldap,named,avahi,haldaemon,dbus,radvd,tomcat,radiusd,news,mailman,nscd,gdm
> reconnection_retries = 3
> default_shell = /bin/bash
> shell_fallback = /bin/bash

[domain/DOMAIN]
> debug_level = 0
> ad_domain = DOMAIN.local
> id_provider = ad
> auth_provider = ad
> chpass_provider = ad
> access_provider = ad
> enumerate = true
> cache_credentials = true
> # Will check unixHomeDirectory LDAP attribute for a value first
> fallback_homedir = /home/%u
> dyndns_update = true
> dyndns_update_ptr = true
> ldap_schema = ad
> ldap_id_mapping = true
> default_shell = /bin/bash

Thanks!

-Chris

[Lukas Slebodnik]

On (09/08/13 09:24), Chris Hartman wrote:
> Hi guys,
>
> Weird problem here. Running Ubuntu with SSSD 1.9.5.
>
> Upon login after a long period between consecutive logins by the same user,
> I receive the following error message:
>
> groups: cannot find name for group ID 1596003661
>
> `id` yields this:
> > USER@smarty:~$ id
>
> uid=1596001141(USER) gid=1596000513(domain users) groups=1596000513(domain
> > users),1596001142(radioworksusers),1596001642(nixdesktopusers),1596001643(nixserverusers),1596003180(puppetmakers),1596003206(drupal_admin),1596003661
>
> An immediate subsequent login on the same system by the same user fails to
> produce the error message and the phantom group disappears from `id` output:
> > USER@smarty:~$ id
>
> uid=1596001141(USER) gid=1596000513(domain users) groups=1596000513(domain
> > users),1596001142(radioworksusers),1596001642(nixdesktopusers),1596001643(nixserverusers),1596003180(puppetmakers),1596003206(drupal_admin)
>
> I've also just noticed that the group ID reported is not consistent but can
> vary. I've searched my AD server for a group objectSID in question but have
> not found one; the group does not exist.
>
> There seem to be no negative side effects aside from the error message and
> unmapped GID in the output of the `id` command.
>
> My config:
> > [sssd]
> > config_file_version = 2
> > debug_level = 0
> > reconnection_retries = 3
> > sbus_timeout = 30
> > services = nss, pam
> > domains = DOMAIN
> >
> > [pam]
> > debug_level = 0
>
> [nss]
> > debug_level = 0
> > filter_users =
> > root,ldap,named,avahi,haldaemon,dbus,radvd,tomcat,radiusd,news,mailman,nscd,gdm
> > filter_groups =
> > root,ldap,named,avahi,haldaemon,dbus,radvd,tomcat,radiusd,news,mailman,nscd,gdm
> > reconnection_retries = 3
> > default_shell = /bin/bash
> > shell_fallback = /bin/bash
>
> [domain/DOMAIN]
> > debug_level = 0
> > ad_domain = DOMAIN.local
> > id_provider = ad
> > auth_provider = ad
> > chpass_provider = ad
> > access_provider = ad
> > enumerate = true
> > cache_credentials = true
> > # Will check unixHomeDirectory LDAP attribute for a value first
> > fallback_homedir = /home/%u
> > dyndns_update = true
> > dyndns_update_ptr = true
> > ldap_schema = ad
> > ldap_id_mapping = true
> > default_shell = /bin/bash
>
> Thanks!
>
> -Chris

Please enable verbose logging in sssd.
   add debug_level = 10 into domain and nss section.

Restart sssd.

And then try to get some information about problematic group.
   getent group -s sss 1596003661

I hope that something useful will be in sssd log files,
if the same error message  will be shown.
> > groups: cannot find name for group ID 1596003661

LS

[Chris Hartman]

On Fri, Aug 9, 2013 at 9:42 AM, Lukas Slebodnik  wrote:
> And then try to get some information about problematic group.
>    getent group -s sss 1596003661

Output from that command:
> USER@smarty:~$ getent group -s sss 1596003661
> certificate service dcom access:*:1596003661:

Performed again with another phantom group:
> USER@smarty:/etc/puppet/modules/sssd$ getent group -s sss 1596003662
> users:*:1596003662:aspnet

I've got debug output but it contains some relatively private information
(first and last names, usernames, possibly other directory information).
It's also rather large (11K lines). Could I share this offlist if necessary?

As it is, here are some relevant lines. In this case, the reported bad
group was 1596003663.
> ==> sssd_nss.log <==
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sbus_remove_timeout] (0x2000):
> 0x9656278
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sbus_dispatch] (0x4000): dbus
> conn: 964B150
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sbus_dispatch] (0x4000):
> Dispatching.
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got
> reply from Data Provider - DP error code: 0 errno: 0 error message: Success
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0100):
> Requesting info for [1596003206@TESTDOMAIN]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [ldb] (0x4000): tevent: Added timed
> event "ltdb_callback": 0x9655fe0
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [ldb] (0x4000): tevent: Added timed
> event "ltdb_timeout": 0x9648240
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [ldb] (0x4000): tevent: Destroying
> timer event 0x9648240 "ltdb_timeout"
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [ldb] (0x4000): tevent: Ending
> timer event 0x9655fe0 "ltdb_callback"
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0400):
> Returning info for gid [1596003206@TESTDOMAIN]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sss_ncache_check_str] (0x2000):
> Checking negative cache for [NCE/GROUP/TESTDOMAIN/drupal_admin]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sss_ncache_check_str] (0x2000):
> Checking negative cache for [NCE/USER/TESTDOMAIN/testuser]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sss_dp_req_destructor] (0x0400):
> Deleting request: [0x807bb20:2:1596003206@TESTDOMAIN]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [reset_idle_timer] (0x4000): Idle
> timer re-set for client [0x9658678][23]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [reset_idle_timer] (0x4000): Idle
> timer re-set for client [0x9658678][23]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sss_ncache_check_str] (0x2000):
> Checking negative cache for [NCE/GID/1596003663]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0100):
> Requesting info for [1596003663@TESTDOMAIN]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [ldb] (0x4000): tevent: Added timed
> event "ltdb_callback": 0x9648298
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [ldb] (0x4000): tevent: Added timed
> event "ltdb_timeout": 0x9656a70
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [ldb] (0x4000): tevent: Destroying
> timer event 0x9656a70 "ltdb_timeout"
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [ldb] (0x4000): tevent: Ending
> timer event 0x9648298 "ltdb_callback"
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sss_dp_issue_request] (0x0400):
> Issuing request for [0x807bb20:2:1596003663@TESTDOMAIN]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sss_dp_get_account_msg] (0x0400):
> Creating request for [TESTDOMAIN][4098][1][idnumber=1596003663]
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sbus_add_timeout] (0x2000):
> 0x96579e8
> (Fri Aug  9 10:46:01 2013) [sssd[nss]] [sss_dp_internal_get_send]
> (0x0400): Entering request [0x807bb20:2:1596003663@TESTDOMAIN]
> ==> sssd_TESTDOMAIN.log <==
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [acctinfo_callback]
> (0x0100): Request processed. Returned 0,0,Success
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> (0x2000): Trace: sh[0x9543678], connected[1], ops[(nil)], ldap[0x9537030]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> (0x2000): Trace: ldap_result found nothing!
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sbus_dispatch]
> (0x4000): dbus conn: 95379C0
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sbus_dispatch]
> (0x4000): Dispatching.
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sbus_message_handler]
> (0x4000): Received SBUS method [getAccountInfo]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [be_get_account_info]
> (0x0100): Got request for [4098][1][idnumber=1596003663]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_id_op_connect_step] (0x4000): reusing cached connection
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_groups_next_base] (0x0400): Searching for groups with base
> [DC=TESTDOMAIN,DC=local]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))][DC=TESTDOMAIN,DC=local].
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 104
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> (0x2000): Trace: sh[0x9543678], connected[1], ops[0x958c300],
> ldap[0x9537030]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_message]
> (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> (0x2000): Trace: sh[0x9543678], connected[1], ops[0x958c300],
> ldap[0x9537030]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_message]
> (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> (0x2000): Trace: sh[0x9543678], connected[1], ops[0x958c300],
> ldap[0x9537030]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_message]
> (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> (0x2000): Trace: sh[0x9543678], connected[1], ops[0x958c300],
> ldap[0x9537030]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_message]
> (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
> set
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> [sdap_get_groups_process] (0x0400): Search for groups, returned 0 results.
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_id_op_done]
> (0x4000): releasing operation connection
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_callback": 0x9550388
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_timeout": 0x9658190
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Destroying timer event 0x9658190 "ltdb_timeout"
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Ending timer event 0x9550388 "ltdb_callback"
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): start
> ldb transaction (nesting: 0)
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_callback": 0x95562b0
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_timeout": 0x9556310
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_callback": 0x95f5ac8
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_timeout": 0x95507e0
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Destroying timer event 0x9556310 "ltdb_timeout"
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Ending timer event 0x95562b0 "ltdb_callback"
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_callback": 0x95ea5e8
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_timeout": 0x95c6c58
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Destroying timer event 0x95507e0 "ltdb_timeout"
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Ending timer event 0x95f5ac8 "ltdb_callback"
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_callback": 0x95c6d60
> (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [ldb] (0x4000): tevent:
> Added timed event "ltdb_timeout": 0x95e9b20
> etc...
>
> <output ommitted>
> ==> sssd_nss.log <==
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [sbus_remove_timeout] (0x2000):
> 0x96579e8
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [sbus_dispatch] (0x4000): dbus
> conn: 964B150
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [sbus_dispatch] (0x4000):
> Dispatching.
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got
> reply from Data Provider - DP error code: 0 errno: 0 error message: Success
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0100):
> Requesting info for [1596003663@TESTDOMAIN]
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [ldb] (0x4000): tevent: Added timed
> event "ltdb_callback": 0x965a8f0
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [ldb] (0x4000): tevent: Added timed
> event "ltdb_timeout": 0x96575c0
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [ldb] (0x4000): tevent: Destroying
> timer event 0x96575c0 "ltdb_timeout"
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [ldb] (0x4000): tevent: Ending
> timer event 0x965a8f0 "ltdb_callback"
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0040):
> No matching domain found for [1596003663], fail!
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [sss_dp_req_destructor] (0x0400):
> Deleting request: [0x807bb20:2:1596003663@TESTDOMAIN]
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [reset_idle_timer] (0x4000): Idle
> timer re-set for client [0x9658678][23]
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [reset_idle_timer] (0x4000): Idle
> timer re-set for client [0x9658678][23]
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [client_recv] (0x0200): Client
> disconnected!
> (Fri Aug  9 10:46:02 2013) [sssd[nss]] [client_destructor] (0x2000):
> Terminated client [0x9658678][23]
> ==> sssd_TESTDOMAIN.log <==
> (Fri Aug  9 10:46:02 2013) [sssd[be[TESTDOMAIN]]] [acctinfo_callback]
> (0x0100): Request processed. Returned 0,0,Success
> (Fri Aug  9 10:46:02 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> (0x2000): Trace: sh[0x9543678], connected[1], ops[(nil)], ldap[0x9537030]
> (Fri Aug  9 10:46:02 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> (0x2000): Trace: ldap_result found nothing!

Thanks.

-Chris

[Lukas Slebodnik]

On (09/08/13 10:57), Chris Hartman wrote:
> On Fri, Aug 9, 2013 at 9:42 AM, Lukas Slebodnik  wrote:
> > And then try to get some information about problematic group.
> >    getent group -s sss 1596003661
>
> Output from that command:
> > USER@smarty:~$ getent group -s sss 1596003661
> > certificate service dcom access:*:1596003661:
>
> Performed again with another phantom group:
> > USER@smarty:/etc/puppet/modules/sssd$ getent group -s sss 1596003662
> > users:*:1596003662:aspnet
>
> I've got debug output but it contains some relatively private information
> (first and last names, usernames, possibly other directory information).
> It's also rather large (11K lines). Could I share this offlist if necessary?
>
> As it is, here are some relevant lines. In this case, the reported bad
> group was 1596003663.

... snip ...
> > (0x4000): Received SBUS method [getAccountInfo]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [be_get_account_info]
> > (0x0100): Got request for [4098][1][idnumber=1596003663]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_id_op_connect_step] (0x4000): reusing cached connection
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_groups_next_base] (0x0400): Searching for groups with base
> > [DC=TESTDOMAIN,DC=local]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> > [(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))][DC=TESTDOMAIN,DC=local].

^^^^^^^
This is the 1st interesting part.
Could you try to do same query with ldapsearch? (the first part is filster and
        the second one is search base.
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [member]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 104
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> > (0x2000): Trace: sh[0x9543678], connected[1], ops[0x958c300],
> > ldap[0x9537030]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_message]
> > (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> > (0x2000): Trace: sh[0x9543678], connected[1], ops[0x958c300],
> > ldap[0x9537030]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_message]
> > (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> > (0x2000): Trace: sh[0x9543678], connected[1], ops[0x958c300],
> > ldap[0x9537030]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_message]
> > (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_result]
> > (0x2000): Trace: sh[0x9543678], connected[1], ops[0x958c300],
> > ldap[0x9537030]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_process_message]
> > (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg
> > set
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]]
> > [sdap_get_groups_process] (0x0400): Search for groups, returned 0 results.

^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                            Group  was not found.
> > (Fri Aug  9 10:46:01 2013) [sssd[be[TESTDOMAIN]]] [sdap_id_op_done]
> > (0x4000): releasing operation connection
> >
> > <output ommitted>
> > ==> sssd_nss.log <==
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [sbus_remove_timeout] (0x2000):
> > 0x96579e8
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [sbus_dispatch] (0x4000): dbus
> > conn: 964B150
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [sbus_dispatch] (0x4000):
> > Dispatching.
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got
> > reply from Data Provider - DP error code: 0 errno: 0 error message: Success
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0100):
> > Requesting info for [1596003663@TESTDOMAIN]

^^^^^^^^
Here is begin of request in sssd_nss
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [ldb] (0x4000): tevent: Added timed
> > event "ltdb_callback": 0x965a8f0
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [ldb] (0x4000): tevent: Added timed
> > event "ltdb_timeout": 0x96575c0
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [ldb] (0x4000): tevent: Destroying
> > timer event 0x96575c0 "ltdb_timeout"
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [ldb] (0x4000): tevent: Ending
> > timer event 0x965a8f0 "ltdb_callback"
> > (Fri Aug  9 10:46:02 2013) [sssd[nss]] [nss_cmd_getgrgid_search] (0x0040):
> > No matching domain found for [1596003663], fail!

^^^^^^^^^^^^^^^^^^^^^^^^^^^
I don't know why this message is here. I would expect:
    a) No results for getgrgid call
    b) Returning info for gid .....

Maybe someone else will help you.

LS

[Chris Hartman]

On Fri, Aug 9, 2013 at 11:47 AM, Lukas Slebodnik wrote:
> Could you try to do same query with ldapsearch? (the first part is filster
> and
>         the second one is search base.

Sure can:
> root@smarty:/etc/puppet/modules/sssd/files#  kinit -k -t /etc/krb5.keytab
> host/$(hostname -f)
> root@smarty:/etc/puppet/modules/sssd/files# ldapsearch -H
> ldap://milkdud.TESTDOMAIN.local/ -Y GSSAPI -N -b "dc=testdomain,dc=local"
> "(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"
> SASL/GSSAPI authentication started
> SASL username: host/[e-mail]
> SASL SSF: 56
> SASL data security layer installed.
> # extended LDIF
> #
> # LDAPv3
> # base <dc=testdomain,dc=local> with scope subtree
> # filter:
> (&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))
> # requesting: ALL
> #
> # search reference
> ref:
> ldap://ForestDnsZones.testdomain.local/DC=ForestDnsZones,DC=testdomain,DC=local
> # search reference
> ref:
> ldap://DomainDnsZones.testdomain.local/DC=DomainDnsZones,DC=testdomain,DC=local
> # search reference
> ref: ldap://testdomain.local/CN=Configuration,DC=testdomain,DC=local
> # search result
> search: 4
> result: 0 Success
> # numResponses: 4
> # numReferences: 3

It's also interesting that some of the GIDs that are returned are not
actually groups but user objects in AD.

-Chris

[Dmitri Pal]

On 08/09/2013 12:31 PM, Chris Hartman wrote:
> On Fri, Aug 9, 2013 at 11:47 AM, Lukas Slebodnik <[e-mail]
> > wrote:
> Could you try to do same query with ldapsearch? (the first part is
> filster and
>         the second one is search base.
>
>
> Sure can:
> root@smarty:/etc/puppet/modules/sssd/files#  kinit -k -t
> /etc/krb5.keytab host/$(hostname -f)
> root@smarty:/etc/puppet/modules/sssd/files# ldapsearch -H
> ldap://milkdud.TESTDOMAIN.local/ -Y GSSAPI -N -b
> "dc=testdomain,dc=local"
> "(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"
> SASL/GSSAPI authentication started
> SASL username: host/[e-mail]
> SASL SSF: 56
> SASL data security layer installed.
> # extended LDIF
> #
> # LDAPv3
> # base <dc=testdomain,dc=local> with scope subtree
> # filter:
> (&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))
> # requesting: ALL
> #
> # search reference
> ref:
> ldap://ForestDnsZones.testdomain.local/DC=ForestDnsZones,DC=testdomain,DC=local
> # search reference
> ref:
> ldap://DomainDnsZones.testdomain.local/DC=DomainDnsZones,DC=testdomain,DC=local
> # search reference
> ref: ldap://testdomain.local/CN=Configuration,DC=testdomain,DC=local
> # search result
> search: 4
> result: 0 Success
> # numResponses: 4
> # numReferences: 3
>
>
> It's also interesting that some of the GIDs that are returned are not
> actually groups but user objects in AD.
>
> -Chris
>
> sssd-users mailing list
> [e-mail]
> https://lists.fedorahosted.org/mailman/listinfo/sssd-users

Was there any resolution to this issue?

[Jakub Hrozek]

On Fri, Aug 09, 2013 at 12:31:01PM -0400, Chris Hartman wrote:
> On Fri, Aug 9, 2013 at 11:47 AM, Lukas Slebodnik wrote:
> > Could you try to do same query with ldapsearch? (the first part is filster
> > and
> >         the second one is search base.
>
> Sure can:
> > root@smarty:/etc/puppet/modules/sssd/files#  kinit -k -t /etc/krb5.keytab
> > host/$(hostname -f)
> > root@smarty:/etc/puppet/modules/sssd/files# ldapsearch -H
> > ldap://milkdud.TESTDOMAIN.local/ -Y GSSAPI -N -b "dc=testdomain,dc=local"
> > "(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"
> > SASL/GSSAPI authentication started
> > SASL username: host/[e-mail]
> > SASL SSF: 56
> > SASL data security layer installed.
> > # extended LDIF
> > #
> > # LDAPv3
> > # base <dc=testdomain,dc=local> with scope subtree
> > # filter:
> > (&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))
> > # requesting: ALL
> > #
> > # search reference
> > ref:
> > ldap://ForestDnsZones.testdomain.local/DC=ForestDnsZones,DC=testdomain,DC=local
> > # search reference
> > ref:
> > ldap://DomainDnsZones.testdomain.local/DC=DomainDnsZones,DC=testdomain,DC=local
> > # search reference
> > ref: ldap://testdomain.local/CN=Configuration,DC=testdomain,DC=local
> > # search result
> > search: 4
> > result: 0 Success
> > # numResponses: 4
> > # numReferences: 3
>
> It's also interesting that some of the GIDs that are returned are not
> actually groups but user objects in AD.
>
> -Chris

Do you run AD server in a trusted setup? Is it possible this group comes
from another AD domain?

Can you check if searching the SID in the Global Catalog works (just
search port 3268)?

# ldapsearch -H ldap://milkdud.TESTDOMAIN.local:3268 -Y GSSAPI -N -b "dc=testdomain,dc=local" \
"(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"

[Chris Hartman]

On Fri, Aug 23, 2013 at 8:29 AM, Jakub Hrozek  wrote:
> Do you run AD server in a trusted setup? Is it possible this group comes
> from another AD domain?

No. We have a single domain. No trusts or subdomains.

Can you check if searching the SID in the Global Catalog works (just
> search port 3268)?
> # ldapsearch -H ldap://milkdud.TESTDOMAIN.local:3268 -Y GSSAPI -N -b
> "dc=testdomain,dc=local" \
>
> "(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"

Here are the results of that query:
> USER@HOST:~$ ldapsearch -H ldap://milkdud.TESTDOMAIN.local:3268 -Y GSSAPI
> -N -b "dc=testdomain,dc=local"
> "(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"SASL/GSSAPI
> authentication started
> SASL username: [e-mail]
> SASL SSF: 56
> SASL data security layer installed.
> # extended LDIF
> #
> # LDAPv3
> # base <dc=wysu,dc=local> with scope subtree
> # filter:
> (&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))
> # requesting: ALL
> #
> # search result
> search: 4
> result: 0 Success
> # numResponses: 1

Also, I've actually not seen the original error in a few days and have
failed to reproduce it the few times I tried just now, so perhaps this was
a fluke? The only thing that has happened since then has been a reboot or
two of each domain controller. No changes to AD or any of the SIDs in
question. I'd be okay with shelving this issue until it rears its head
again. If any curious party wants me to experiment some more, I'd be happy
to oblige, I'll just need some direction because I'm stumped. Otherwise,
I'll monitor the issue for a few more days and post back with one more
follow up if I can't reproduce it.

Thanks.

-Chris

[Stephen Gallagher]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 08/23/2013 11:09 AM, Chris Hartman wrote:
> On Fri, Aug 23, 2013 at 8:29 AM, Jakub Hrozek <[e-mail] 
> > wrote:
>
> Do you run AD server in a trusted setup? Is it possible this group
> comes from another AD domain?
>
> No. We have a single domain. No trusts or subdomains.
>
> Can you check if searching the SID in the Global Catalog works
> (just search port 3268)? # ldapsearch -H
> ldap://milkdud.TESTDOMAIN.local:3268 -Y GSSAPI -N -b 
> "dc=testdomain,dc=local" \ 
> "(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"
>
> Here are the results of that query:
>
> USER@HOST:~$ ldapsearch -H ldap://milkdud.TESTDOMAIN.local:3268 -Y 
> GSSAPI -N -b "dc=testdomain,dc=local" 
> "(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"SASL/GSSAPI

authentication started
> SASL username: [e-mail] SASL SSF: 56 SASL data
> security layer installed. # extended LDIF # # LDAPv3 # base
> <dc=wysu,dc=local> with scope subtree # filter: 
> (&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))

# requesting: ALL
> # # search result search: 4 result: 0 Success # numResponses: 1
>
> Also, I've actually not seen the original error in a few days and
> have failed to reproduce it the few times I tried just now, so
> perhaps this was a fluke? The only thing that has happened since
> then has been a reboot or two of each domain controller. No changes
> to AD or any of the SIDs in question. I'd be okay with shelving
> this issue until it rears its head again. If any curious party
> wants me to experiment some more, I'd be happy to oblige, I'll just
> need some direction because I'm stumped. Otherwise, I'll monitor
> the issue for a few more days and post back with one more follow up
> if I can't reproduce it.

My best guess here is that you might have had an entry with that SID
on one replica that wasn't syncing properly. Every once in a while,
SSSD would end up connected to that replica at login.
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.14 (GNU/Linux)
> Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
>
> iEYEARECAAYFAlIXfbEACgkQeiVVYja6o6PtiQCeOWxrq3Dmbbuo7hT7YHNrUjNr
> NaMAn3AVnDB0qaI5iFUbZN+Qg6JDlwdf
> =0K5v
> -----END PGP SIGNATURE-----

[Chris Hartman]

Well, I've gotten the phantom group error message again.

groups: cannot find name for group ID 1596003650

So, I tried to get some info:
> root@snickers:~# getent group -s sss 1596003650
> root@snickers:~#

As you can see, no output from getent.

So, I did an AD query as outlined here:
http://blog.schertz.name/2008/03/searching-ad-for-a-user-account-with-a-sid/
This
is the query I performed:
> (&(objectCategory=*)(objectSID=\01\05\00\00\00\00\00\05\15\00\00\00\D9\4D\0B\6A\B4\D6\05\0E\16\51\0D\E2\42\0E\00\00))

No results found. So, the group reported REALLY doesn't exist, contrary to
what we found earlier. I've got sanitized, detailed logs:

- SSSD NSS log: http://pastebin.com/CQS4rYUe (I removed most timer event
   messages as they took up ~2300 lines)
   - SSSD domain log: http://tny.cz/41eec8a3

Bear in mind, I had to do some regex to remove sensitive information like
usernames and full names.

-Chris

On Fri, Aug 23, 2013 at 11:20 AM, Stephen Gallagher wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> On 08/23/2013 11:09 AM, Chris Hartman wrote:
> > On Fri, Aug 23, 2013 at 8:29 AM, Jakub Hrozek <[e-mail]
> > > wrote:
> >
> > Do you run AD server in a trusted setup? Is it possible this group
> > comes from another AD domain?
> >
> > No. We have a single domain. No trusts or subdomains.
> >
> > Can you check if searching the SID in the Global Catalog works
> > (just search port 3268)? # ldapsearch -H
> > ldap://milkdud.TESTDOMAIN.local:3268 -Y GSSAPI -N -b
> > "dc=testdomain,dc=local" \
>
> "(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"
> > Here are the results of that query:
> >
> > USER@HOST:~$ ldapsearch -H ldap://milkdud.TESTDOMAIN.local:3268 -Y
> > GSSAPI -N -b "dc=testdomain,dc=local"
>
> "(&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))"SASL/GSSAPI
> >
>
> authentication started
> > SASL username: [e-mail] SASL SSF: 56 SASL data
> > security layer installed. # extended LDIF # # LDAPv3 # base
> > <dc=wysu,dc=local> with scope subtree # filter:
>
> (&(objectSID=S-1-5-21-1779125721-235263668-3792523542-3663)(objectclass=group)(name=*))
> >
>
> # requesting: ALL
> > # # search result search: 4 result: 0 Success # numResponses: 1
> >
> > Also, I've actually not seen the original error in a few days and
> > have failed to reproduce it the few times I tried just now, so
> > perhaps this was a fluke? The only thing that has happened since
> > then has been a reboot or two of each domain controller. No changes
> > to AD or any of the SIDs in question. I'd be okay with shelving
> > this issue until it rears its head again. If any curious party
> > wants me to experiment some more, I'd be happy to oblige, I'll just
> > need some direction because I'm stumped. Otherwise, I'll monitor
> > the issue for a few more days and post back with one more follow up
> > if I can't reproduce it.
>
> My best guess here is that you might have had an entry with that SID
> on one replica that wasn't syncing properly. Every once in a while,
> SSSD would end up connected to that replica at login.
>
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.14 (GNU/Linux)
> Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
>
> iEYEARECAAYFAlIXfbEACgkQeiVVYja6o6PtiQCeOWxrq3Dmbbuo7hT7YHNrUjNr
> NaMAn3AVnDB0qaI5iFUbZN+Qg6JDlwdf
> =0K5v
> -----END PGP SIGNATURE-----
> _______________________________________________
> sssd-users mailing list
> [e-mail]
> https://lists.fedorahosted.org/mailman/listinfo/sssd-users