Hi,

 

We are running into some SSSD authentication issues and would really appreciate any advice. Here’s some background:

 

Until now, all CentOS machines which use SSSD were joined to the same domain that also holds all user’s along with their respective groups.  Let’s call this abc.xyz.local. Now, due to some compliance issue, we cannot have these Linux computer accounts in “abc” domain, and need to be moved to another domain called “def.xyz.local”. User’s / Groups who would be accessing these servers  are unchanged and continue to be part of abc.xyz.local.

 

“xyz.local” is the forest whereas both “abc” & “def” are child domains with bi-directional trust. Was able to successfully join this machine to “def” domain. ad_access_filter and other SSSD configurations are kept the same except domains, ad_server, krb5_realm, ldap_uri which all point to the “DEF” domain now.

 

But when trying to authenticate, we get the following under /var/log/secure:

 

Jun 27 12:58:48 sshd[15716]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost= user=first.last@ABC.XYZ.LOCAL

Jun 27 12:58:48 sshd[15716]: pam_sss(sshd:auth): received for user first.last@ABC.XYZ.LOCAL: 6 (Permission denied)

 

From the logs, it looks like SSSD was able to change request domain from “def” to “abc” and was able to locate the OU where the user’s reside, but could not get any further.

 

Also, “id” commands returns only a default group of “domain users” instead of all the groups this user is member of in “ABC” domain.

[root@]# id first.last@ABC.XYZ.LOCAL

Uid=xxxxxxxxx(first.last@abc.xyz.local) gid=yyyyyyyyy(first.last@abc.xyz.local) groups=yyyyyyyyy(first.last@abc.xyz.local),xxxxxxxxx(domain users@abc.xyz.local)

 

Tried changing the ldap_user_search_base to dc=xyz,dc=local but still same results.

 

SSSD Configuration:

 

 

[sssd]

domains = DEF.XYZ.LOCAL

services = nss, pam, sudo

config_file_version = 2

debug_level = 10

[nss]

[pam]

[sudo]

debug_level=10

[domain/def.xyz.local]

debug_level=10

ad_server = AD-Server.def.xyz.local

id_provider = ad

auth_provider = ad

access_provider = ad

sudo_provider = ad

ldap_use_tokengroups = False

krb5_realm = DEF.XYZ.LOCAL

ldap_uri = ldap://<AD-Server>.def.xyz.local

ldap_sudo_search_base = .........................   dc=abc,dc=xyz,dc=local

ldap_user_search_base = dc=xyz,dc=local

ldap_group_search_base = ........................  dc=abc,dc=xyz,dc=local

ldap_access_order = filter, expire

ad_access_filter =  ...

cache_credentials = true

override_homedir = /home/%d/%u

default_shell = /bin/bash

 

 

 

krb5.conf:

 

[logging]

default = FILE:/var/log/krb5libs.log

kdc = FILE:/var/log/krb5kdc.log

admin_server = FILE:/var/log/kadmind.log

[libdefaults]

default_realm = DEF.XYZ.LOCAL

dns_lookup_realm = true

dns_lookup_kdc = true

ticket_lifetime = 24h

renew_lifetime = 7d

forwardable = yes

[realms]

DEF.XYZ.LOCAL = {

kdc = AD-Server.def.xyz.local:88

admin_server = AD-Server.def.xyz.local:749

}

[domain_realm]

.def.xyz.local = DEF.XYZ.LOCAL

def.xyz.local = DEF.XYZ.LOCAL

 

 

 

 

 

Here is sssd_domain log set to level 10. Captured during authentication.

 

 

(Tue Jun 27 10:40:48 2017) [sssd[be[def.xyz.local]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)

(Tue Jun 27 10:40:48 2017) [sssd[be[def.xyz.local]]] [sdap_sudo_full_refresh_done] (0x0400): Successful full refresh of sudo rules

(Tue Jun 27 10:40:48 2017) [sssd[be[def.xyz.local]]] [be_ptask_done] (0x0400): Task [SUDO Full Refresh]: finished successfully

(Tue Jun 27 10:40:48 2017) [sssd[be[def.xyz.local]]] [be_ptask_schedule] (0x0400): Task [SUDO Full Refresh]: scheduling task 21600 seconds from last execution time [1498596048]

(Tue Jun 27 10:40:48 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x11101b0], connected[1], ops[(nil)], ldap[0x1111cf0]

(Tue Jun 27 10:40:48 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!

(Tue Jun 27 10:40:57 2017) [sssd[be[def.xyz.local]]] [sbus_dispatch] (0x4000): dbus conn: 0x10b2500

(Tue Jun 27 10:40:57 2017) [sssd[be[def.xyz.local]]] [sbus_dispatch] (0x4000): Dispatching.

(Tue Jun 27 10:40:57 2017) [sssd[be[def.xyz.local]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.service.ping on path /org/freedesktop/sssd/service

(Tue Jun 27 10:40:57 2017) [sssd[be[def.xyz.local]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sbus_dispatch] (0x4000): dbus conn: 0x1109eb0

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sbus_dispatch] (0x4000): Dispatching.

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [be_get_account_info] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][1][name=first.last]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [be_req_set_domain] (0x0400): Changing request domain from [def.xyz.local] to [abc.xyz.local]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_id_op_connect_step] (0x4000): beginning to connect

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD_GC'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [get_server_status] (0x1000): Status of server 'AD_Server.def.xyz.local' is 'working'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [get_port_status] (0x1000): Port status of port 0 for server 'AD_Server.def.xyz.local' is 'neutral'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [get_server_status] (0x1000): Status of server 'AD_Server.def.xyz.local' is 'working'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [be_resolve_server_process] (0x1000): Saving the first resolved server

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [be_resolve_server_process] (0x0200): Found address for server AD_Server.def.xyz.local: [x.x.x.x] TTL 3600

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://AD_Server.def.xyz.local'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://AD_Server.def.xyz.local:3268'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sss_ldap_init_send] (0x4000): Using file descriptor [22] for LDAP connection.

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://AD_Server.def.xyz.local:3268/??base] with fd [22].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_print_server] (0x2000): Searching x.x.x.x

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].

...

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_op_add] (0x2000): New operation 1 timeout 6

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[0x111dcf0], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_parse_entry] (0x1000): OriginalDN: [].

...

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_op_destructor] (0x2000): Operation 1 finished

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_rootdse_done] (0x2000): Got rootdse

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_server_opts_from_rootdse] (0x4000): USN value: 28129115 (int: 28129115)

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility level to [6]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_kinit_send] (0x0400): Attempting kinit (default, HOSTNAME$, def.xyz.LOCAL, 86400)

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service AD

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [get_server_status] (0x1000): Status of server 'AD_Server.def.xyz.local' is 'working'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [get_port_status] (0x1000): Port status of port 0 for server 'AD_Server.def.xyz.local' is 'working'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [get_server_status] (0x1000): Status of server 'AD_Server.def.xyz.local' is 'working'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [be_resolve_server_process] (0x1000): Saving the first resolved server

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [be_resolve_server_process] (0x0200): Found address for server AD_Server.def.xyz.local: [x.x.x.x] TTL 3600

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT...

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [create_tgt_req_send_buffer] (0x0400): buffer size: 53

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [14482]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [child_handler_setup] (0x2000): Signal handler set up for pid [14482]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[(nil)], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [write_pipe_handler] (0x0400): All data has been sent!

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [read_pipe_handler] (0x0400): EOF received, client finished

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_tgt_recv] (0x0400): Child responded: 0 [FILE:/var/lib/sss/db/ccache_def.xyz.LOCAL], expired on [1498610460]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1498575360

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: HOSTNAME$

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [child_sig_handler] (0x1000): Waiting for child [14482].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [child_sig_handler] (0x0100): child [14482] finished successfully.

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_cli_connect_recv] (0x0400): Connection established.

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2054

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'AD_Server.def.xyz.local' as 'working'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [set_server_common_status] (0x0100): Marking server 'AD_Server.def.xyz.local' as 'working'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'AD_Server.def.xyz.local' as 'working'

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_id_op_connect_done] (0x2000): Old USN: 28129111, New USN: 28129115

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_initgr_send] (0x4000): Retrieving info for initgroups call

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [dc=abc,dc=xyz,dc=local]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_print_server] (0x2000): Searching x.x.x.x

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=first.last)(objectclass=user)(objectSID=*))][dc=abc,dc=xyz,dc=local].

...

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_op_add] (0x2000): New operation 5 timeout 6

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[0x1138340], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=first last,OU=Users, OU=company,DC=abc,DC=xyz,DC=local].

...

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[0x1138340], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_op_destructor] (0x2000): Operation 5 finished

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_initgr_user] (0x4000): Receiving info for the user

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [ldb] (0x4000): start ldb transaction (nesting: 0)

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_initgr_user] (0x4000): Storing the user

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x0400): Save user

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_primary_name] (0x0400): Processing object first.last@abc.xyz.local

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x0400): Processing user first.last@abc.xyz.local

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x1000): Mapping user [first.last@abc.xyz.local] objectSID [S-1-5-21-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx] to unix ID

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x2000): Adding originalDN [CN=first last,OU=Users,OU=ITSS,OU=xyz Teams,OU=Offices,OU=United States,OU=company,DC=abc,DC=xyz,DC=local] to attributes of [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20170622141237.0Z] to attributes of [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x0400): Adding user principal [first.last@company.COM] to attributes of [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): adAccountExpires is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adUserAccountControl [512] to attributes of [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): authType is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_attrs_add_ldap_attr] (0x2000): userCertificate is not available for [first.last@abc.xyz.local].

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x0400): Storing info for user first.last@abc.xyz.local

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [ldb] (0x4000): start ldb transaction (nesting: 1)

 

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_initgr_user] (0x4000): Process user's groups

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_initgr_rfc2307bis_next_base] (0x0400): Searching for parent groups for user [CN=first last,OU=Users,OU=ITSS,OU=xyz Teams,OU=company,DC=abc,DC=xyz,DC=local] with base [dc=abc,dc=xyz,dc=local]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_print_server] (0x2000): Searching x.x.x.x

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(member=CN=first\20last,OU=Users,OU=ITSS,OU=xyz\20Teams,OU=company,DC=abc,DC=xyz,DC=local)(objectClass=group)(sAMAccountName=*)(objectSID=*))][dc=abc,dc=xyz,dc=local].

...

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 6

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_op_add] (0x2000): New operation 6 timeout 6

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[0x114c300], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[0x114c300], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=def Administrators,OU=Universal Groups,OU=Groups,OU=company,DC=abc,DC=xyz,DC=local].

...

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_parse_range] (0x2000): No sub-attributes for [groupType]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[0x114c300], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_op_finished] (0x2000): Total count [0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_op_destructor] (0x2000): Operation 6 finished

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_initgr_rfc2307bis_process] (0x1000): Found 1 parent groups for user [first.last@abc.xyz.local]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [rfc2307bis_nested_groups_send] (0x2000): About to process 1 groups in nesting level 0

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_primary_name] (0x0400): Processing object def Administrators@abc.xyz.local

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [rfc2307bis_nested_groups_step] (0x1000): Processing group [def Administrators@abc.xyz.local]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [rfc2307bis_nested_groups_next_base] (0x0400): Searching for parent groups of group [CN=def Administrators,OU=Universal Groups,OU=Groups,OU=company,DC=abc,DC=xyz,DC=local] with base [dc=abc,dc=xyz,dc=local]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_print_server] (0x2000): Searching x.x.x.x

...

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_op_add] (0x2000): New operation 7 timeout 6

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[0x114aa40], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[0x114aa40], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_get_generic_op_finished] (0x2000): Total count [0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_op_destructor] (0x2000): Operation 7 finished

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [rfc2307bis_nested_groups_process] (0x1000): Found 0 parent groups of [CN=def Administrators,OU=Universal Groups,OU=Groups,OU=All US abcorate Offices,OU=United States,OU=company,DC=abc,DC=xyz,DC=local]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sysdb_get_direct_parents] (0x2000): searching sysdb with filter [(&(objectClass=group)(member=name=def\20Administrators@abc.xyz.local,cn=groups,cn=abc.xyz.local,cn=sysdb))]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sysdb_get_direct_parents] (0x1000): def Administrators@abc.xyz.local is a member of 0 sysdb groups

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [save_rfc2307bis_user_memberships] (0x1000): Save parent groups to sysdb

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [ldb] (0x4000): start ldb transaction (nesting: 1)

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sysdb_get_direct_parents] (0x2000): searching sysdb with filter [(&(objectClass=group)(member=name=first.last@abc.xyz.local,cn=users,cn=abc.xyz.local,cn=sysdb))]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sysdb_get_direct_parents] (0x1000): first.last@abc.xyz.local is a member of 1 sysdb groups

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [save_rfc2307bis_user_memberships] (0x2000): Updating memberships for first.last@abc.xyz.local

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [ldb] (0x4000): commit ldb transaction (nesting: 0)

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: sh[0x1137ec0], connected[1], ops[(nil)], ldap[0x11338c0]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sbus_dispatch] (0x4000): dbus conn: 0x1109eb0

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sbus_dispatch] (0x4000): Dispatching.

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [be_req_set_domain] (0x0400): Changing request domain from [def.xyz.local] to [abc.xyz.local]

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [be_pam_handler] (0x0100): Got request with the following data

...

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [first.last@abc.xyz.local] is empty, running request [0x1136800] immediately.

(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [krb5_setup] (0x4000): No mapping for: first.last@abc.xyz.local

 

 

Are we missing any component in SSSD config which allows for such transitions? Or does it looks like something broken in the join itself?

 

 

[root@ ~]# net ads testjoin

Join is OK

 

[root@ ~]# net ads info

LDAP server: x.x.x.x

LDAP server name: AD-Server.def.xyz.local

Realm: DEF.XYZ.LOCAL

Bind Path: dc=DEF,dc=XYZ,dc=LOCAL

LDAP port: 389

Server time: Tue, 27 Jun 2017 13:13:47 EDT

KDC server: x.x.x.x

Server time offset: 0

Last machine account password change: Tue, 27 Jun 2017 10:09:01 EDT

 

 

 

Thanks,

 

~ Abhi