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(a)ABC.XYZ.LOCAL
Jun 27 12:58:48 sshd[15716]: pam_sss(sshd:auth): received for user
first.last(a)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(a)ABC.XYZ.LOCAL
Uid=xxxxxxxxx(first.last(a)abc.xyz.local) gid=yyyyyyyyy(first.last(a)abc.xyz.local)
groups=yyyyyyyyy(first.last(a)abc.xyz.local),xxxxxxxxx(domain users(a)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(a)abc.xyz.local
(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x0400):
Processing user first.last(a)abc.xyz.local
(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x1000): Mapping
user [first.last(a)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(a)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(a)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(a)abc.xyz.local].
(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [sdap_save_user] (0x0400): Adding
user principal [first.last(a)company.COM] to attributes of [first.last(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)abc.xyz.local
(Tue Jun 27 10:41:00 2017) [sssd[be[def.xyz.local]]] [rfc2307bis_nested_groups_step]
(0x1000): Processing group [def Administrators(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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