Can SSSD query users from a domain different than the one computer has joined?

[Abhijit Tikekar]

>  
>  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
> [(&amp;(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
> [(&amp;(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
>

[Jakub Hrozek]

On Tue, Jun 27, 2017 at 01:35:18PM -0400, Abhijit Tikekar wrote:
>  
>  > 
>  > 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) 
This sounds like GPO access control prevented you from logging in.

Can you (just for a test!) please set either:
    ad_gpo_access_control = permissive
or even:
    access_provider = permit

and see if the issue persists?


>  >  
>  > 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 
Why exactly did you disable tokengroups?

>  > 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 
Same here, can you test with a more vanilla configuration, removing
anything that starts with ldap_ (unless you had a reason to set those) ?

Point being, the AD provider normally has the defaults set sensibly
enough, so there shouldn't be any point in overriding the AD config..

>  > 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. 
Thank you for the logs, but I don't think the logs are complete, is
there anything after:

> > (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

[Abhijit Tikekar]

Hi Jakub,

Thanks for the response.

After enabling ldap_use_tokengroups = true, "id" command is now able to
retrieve all the group memberships for that user. But Authentication still
doesn't work.

Also tried setting   ad_gpo_access_control = permissive / access_provider =
permit but that didn't help.

I am attaching both krb5_child.log and sssd_domain.log ( Both with Logon
level 10) here. These were captures during the authentication attempt.

Thanks,

~ Abhi


On Tue, Jun 27, 2017 at 2:39 PM, Jakub Hrozek <jhrozek(a)redhat.com&gt; wrote:

>  On Tue, Jun 27, 2017 at 01:35:18PM -0400, Abhijit Tikekar wrote:
>  >
>  > >
>  > > 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)
>
>  This sounds like GPO access control prevented you from logging in.
>
>  Can you (just for a test!) please set either:
>      ad_gpo_access_control = permissive
>  or even:
>      access_provider = permit
>
>  and see if the issue persists?
>
>
>  > >
>  > > 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
>
>  Why exactly did you disable tokengroups?
>
>  > > 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
>
>  Same here, can you test with a more vanilla configuration, removing
>  anything that starts with ldap_ (unless you had a reason to set those) ?
>
>  Point being, the AD provider normally has the defaults set sensibly
>  enough, so there shouldn't be any point in overriding the AD config..
>
>  > > 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.
>
>  Thank you for the logs, but I don't think the logs are complete, is
>  there anything after:
>
>  > > (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
>  _______________________________________________
>  sssd-users mailing list -- sssd-users(a)lists.fedorahosted.org
>  To unsubscribe send an email to sssd-users-leave(a)lists.fedorahosted.org
>

[Lukas Slebodnik]

On (28/06/17 16:51), Abhijit Tikekar wrote:
> Hi Jakub,
>
> Thanks for the response.
>
> After enabling ldap_use_tokengroups = true, "id" command is now able to
> retrieve all the group memberships for that user. But Authentication still
> doesn't work.
>
> Also tried setting   ad_gpo_access_control = permissive / access_provider =
> permit but that didn't help.
>
> I am attaching both krb5_child.log and sssd_domain.log ( Both with Logon
> level 10) here. These were captures during the authentication attempt.
>  
Logs are not from the same time. There is 8 minutes between authentication
attempt an krb5_child.log.

But I smell a crash in krb5_child.log

(Wed Jun 28 16:02:27 2017) [[sssd[krb5_child[23140]]]] [sss_child_krb5_trace_cb] (0x4000):
[23140] 1498680147.720777: Requesting tickets for
host/hostname.def.xyz.local(a)ABC.XYZ.LOCAL,
+referrals on
(Wed Jun 28 16:02:27 2017) [[sssd[krb5_child[23140]]]] [sss_child_krb5_trace_cb] (0x4000):
[23140] 1498680147.720845: Generated subkey for TGS request: aes256-cts/D868
(Wed Jun 28 16:02:27 2017) [[sssd[krb5_child[23140]]]] [sss_child_krb5_trace_cb] (0x4000):
[23140] 1498680147.720891: etypes requested in TGS request: aes256-cts, aes128-cts,
+des3-cbc-sha1, rc4-hmac
(Wed Jun 28 16:02:27 2017) [[sssd[krb5_child[23140]]]] [sss_child_krb5_trace_cb] (0x4000):
[23140] 1498680147.721078: Sending request (1750 bytes) to ABC.XYZ.LOCAL
(Wed Jun 28 16:02:29 2017) [[sssd[krb5_child[23141]]]] [main] (0x0400): krb5_child
started.
(Wed Jun 28 16:02:29 2017) [[sssd[krb5_child[23141]]]] [unpack_buffer] (0x1000): total
buffer size: [181]


Because I would expect different messages at the end "16:02:27"
and we can see only that new child started.

LS

[Jakub Hrozek]

On Wed, Jun 28, 2017 at 11:09:38PM +0200, Lukas Slebodnik wrote:
>  On (28/06/17 16:51), Abhijit Tikekar wrote:
>  >Hi Jakub,
>  >
>  >Thanks for the response.
>  >
>  >After enabling ldap_use_tokengroups = true, "id" command is now able to
>  >retrieve all the group memberships for that user. But Authentication still
>  >doesn't work.
>  >
>  >Also tried setting   ad_gpo_access_control = permissive / access_provider =
>  >permit but that didn't help.
>  >
>  >I am attaching both krb5_child.log and sssd_domain.log ( Both with Logon
>  >level 10) here. These were captures during the authentication attempt.
>  >
>  
>  Logs are not from the same time. There is 8 minutes between authentication
>  attempt an krb5_child.log.
>  
>  But I smell a crash in krb5_child.log
>  
>  (Wed Jun 28 16:02:27 2017) [[sssd[krb5_child[23140]]]] [sss_child_krb5_trace_cb]
> (0x4000): [23140] 1498680147.720777: Requesting tickets for
> host/hostname.def.xyz.local(a)ABC.XYZ.LOCAL,
>  +referrals on
>  (Wed Jun 28 16:02:27 2017) [[sssd[krb5_child[23140]]]] [sss_child_krb5_trace_cb]
> (0x4000): [23140] 1498680147.720845: Generated subkey for TGS request: aes256-cts/D868
>  (Wed Jun 28 16:02:27 2017) [[sssd[krb5_child[23140]]]] [sss_child_krb5_trace_cb]
> (0x4000): [23140] 1498680147.720891: etypes requested in TGS request: aes256-cts,
> aes128-cts,
>  +des3-cbc-sha1, rc4-hmac
>  (Wed Jun 28 16:02:27 2017) [[sssd[krb5_child[23140]]]] [sss_child_krb5_trace_cb]
> (0x4000): [23140] 1498680147.721078: Sending request (1750 bytes) to ABC.XYZ.LOCAL
>  (Wed Jun 28 16:02:29 2017) [[sssd[krb5_child[23141]]]] [main] (0x0400): krb5_child
> started.
>  (Wed Jun 28 16:02:29 2017) [[sssd[krb5_child[23141]]]] [unpack_buffer] (0x1000): total
> buffer size: [181]
>  
>  
>  Because I would expect different messages at the end "16:02:27"
>  and we can see only that new child started. 
Yes, either a crash, or the back end killed the krb5_child because of a
timeout. This could be seen in the matching domain log --either you
would see that the child was killed by signal 6 or 11 or similar
(=crash) or you would see that the child was killed by the back end due
to a time out.