Hi Sumit

Thanks a lot for your email. Apologies for the late answer, it took me a little time to get used to how gdb works ;)

Anyway, after debugging the latest git version, it looks like the issue systematically happens line 237 of  ad_gpo_ndr.c, in  the ndr_pull_security_ace_object_ctr() method, calling Samba's new ndr_pull_steal_switch_value method (introduced in 4.12 according to this):

237: NDR_CHECK(ndr_pull_steal_switch_value(ndr, r, &level));

This check systematically returns NDR_ERR_TOKEN (instead, I guess, of NDR_ERR_SUCCESS), which then makes all other methods fail in the following order: ndr_pull_security_ace() (line 320), ndr_pull_security_acl() (line 372) and ad_gpo_ndr_pull_security_descriptor() (line 513). See gdb logs below

Anything I could do to investigate this further?

Thanks again,

Best,

Thibault


Breakpoint 15, ndr_pull_security_ace_object_ctr (ndr=0x5581d6ddd5b0, ndr_flags=512, r=0x5581d6e2147c) at src/providers/ad/ad_gpo_ndr.c:237
237            NDR_CHECK(ndr_pull_steal_switch_value(ndr, r, &level));
(gdb) fin
Run till exit from #0  ndr_pull_security_ace_object_ctr (ndr=0x5581d6ddd5b0, ndr_flags=512, r=0x5581d6e2147c) at src/providers/ad/ad_gpo_ndr.c:237
0x00007f18aa8cf0d2 in ndr_pull_security_ace (ndr=0x5581d6ddd5b0, ndr_flags=512, r=0x5581d6e21470) at src/providers/ad/ad_gpo_ndr.c:320
320        NDR_CHECK(ndr_pull_security_ace_object_ctr
Value returned is $123 = NDR_ERR_TOKEN
(gdb) fin
Run till exit from #0  0x00007f18aa8cf0d2 in ndr_pull_security_ace (ndr=0x5581d6ddd5b0, ndr_flags=512, r=0x5581d6e21470) at src/providers/ad/ad_gpo_ndr.c:320
0x00007f18aa8cf576 in ndr_pull_security_acl (ndr=0x5581d6ddd5b0, ndr_flags=768, r=0x5581d6de3230) at src/providers/ad/ad_gpo_ndr.c:372
372            NDR_CHECK(ndr_pull_security_ace
Value returned is $124 = NDR_ERR_TOKEN
(gdb) fin
Run till exit from #0  0x00007f18aa8cf576 in ndr_pull_security_acl (ndr=0x5581d6ddd5b0, ndr_flags=768, r=0x5581d6de3230) at src/providers/ad/ad_gpo_ndr.c:372
0x00007f18aa8d03ee in ad_gpo_ndr_pull_security_descriptor (ndr=0x5581d6ddd5b0, ndr_flags=768, r=0x7ffdec42d870) at src/providers/ad/ad_gpo_ndr.c:513
513                NDR_CHECK(ndr_pull_security_acl(ndr,
Value returned is $125 = NDR_ERR_TOKEN
(gdb) fin
Run till exit from #0  0x00007f18aa8d03ee in ad_gpo_ndr_pull_security_descriptor (ndr=0x5581d6ddd5b0, ndr_flags=768, r=0x7ffdec42d870) at src/providers/ad/ad_gpo_ndr.c:513
0x00007f18aa8ca867 in ad_gpo_parse_sd (mem_ctx=0x5581d6e0cf50, data=0x5581d6e171d0 "\001", length=256, _gpo_sd=0x5581d6e0cf50) at src/providers/ad/ad_gpo.c:3925
3925    ndr_err = ad_gpo_ndr_pull_security_descriptor(ndr_pull,
Value returned is $126 = NDR_ERR_TOKEN


On Mon, May 11, 2020 at 11:07 AM Sumit Bose <sbose@redhat.com> wrote:
On Fri, May 08, 2020 at 03:35:56PM +0200, Thibault Boyeux wrote:
> Hi all,
>
> I'm encountering an issue after upgrading to Samba 4.12.2. I can no longer
> login with an Active Directory account from a terminal or gnome. I'm
> prompted with a "System error" message.
>
> When I downgrade to samba 4.11.3 everything works fine. AD authentication
> works OK with the same account from a Windows machine.
>
> "getent passwd my_username" works well, as "getent passwd <group>". kinit
> my_username@DOMAIN.NET works OK too. Logging in in with "su <username>"
> from a local account works too.
>
> SSSD version: 2.2.3. This is from an Arch Linux package, that has been
> patched
> <https://git.archlinux.org/svntogit/community.git/tree/trunk?h=packages/sssd>
> by its maintainer for compatibility with Samba 4.12 (I also compiled sssd
> from the current git source code, but encountered the same cryptic error.)
> Samba version: 4.12.2
> Operating system: Arch Linux (fully upgraded)

Hi,

do I understand correctly that you recompiled SSSD after updating Samba
to version 4.12.2 or did you use the same SSSD binary you used with
Samba 4.11.3?

According to the logs the error most probably happened in
ad_gpo_ndr_pull_security_descriptor(). Can you step through this
function with gdb to see which operation failed (please add 'timeout =
999999' to the [domain/...] section of sssd.conf to not run into issues
with the watchdog and gdb)? If not I can try to reproduce this locally.

bye,
Sumit

>
> Any idea how I could fix this / investigate this further? Please find
> sssd.conf and logs below - I couldn't find anything interesting in there
> but I'm no expert :)
>
> Thanks a lot!
>
> === sssd.conf ===
>
> [sssd]
> config_file_version = 2
> domains = domain.net
> services = nss, pam
> debug_level = 6
>
> [domain/domain.net]
> ad_hostname = computer.domain.net
> krb5_realm = DOMAIN.NET
> cache_credentials = true
> id_provider = ad
> auth_provider = ad
> access_provider = ad
> chpass_provider = ad
> ldap_schema = ad
> default_shell = /bin/zsh
> fallback_homedir = /home/DOMAIN/%u
> dyndns_update = true
> dyndns_refresh_interval = 43200
> dyndns_update_ptr = true
> dyndns_ttl = 3600
> debug_level = 6
> #enumerate = true
>
> [pam]
> debug_level = 6
>
> [nss]
> debug_level = 6
>
>
> === sssd_domain.net.log ===
>
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [dp_get_account_info_send] (0x0200): Got request for
> [0x3][BE_REQ_INITGROUPS][name=my_username@domain.net]
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_attach_req] (0x0400):
> DP Request [Initgroups #17]: New request. Flags [0x0001].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_attach_req] (0x0400):
> Number of active DP request: 1
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_initgr_next_base] (0x0400): Searching for users with base
> [DC=domain,DC=net]
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(&(sAMAccountName=my_username)(objectclass=user)(objectSID=*))][DC=domain,DC=net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_save_user]
> (0x0400): Save user
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_get_primary_name]
> (0x0400): Processing object MY_USERNAME
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_save_user]
> (0x0400): Processing user MY_USERNAME@domain.net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_save_user]
> (0x0400): Adding original memberOf attributes to [MY_USERNAME@domain.net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_save_user]
> (0x0400): Adding user principal [MY_USERNAME@DOMAIN.NET] to attributes of [
> MY_USERNAME@domain.net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_save_user]
> (0x0400): Storing info for user MY_USERNAME@domain.net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sysdb_set_entry_attr]
> (0x0200): Entry [name=MY_USERNAME@domain.net,cn=users,cn=domain.net,cn=sysdb]
> has set [ts_cache] attrs.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sysdb_store_user]
> (0x0400): User "MY_USERNAME@domain.net" has been stored
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no
> filter][CN=My Username,OU=Users,DC=domain,DC=net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_idmap_sid_to_unix]
> (0x0400): Object SID [S-1-5-32-545] is a built-in one.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_ad_save_group_membership_with_idmapping] (0x0400): Skipping built-in
> object.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_get_initgr_done]
> (0x0400): Primary group already cached, nothing to do.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_req_done] (0x0400):
> DP Request [Initgroups #17]: Request handler finished [0]: Success
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [_dp_req_recv] (0x0400):
> DP Request [Initgroups #17]: Receiving request data.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_req_destructor]
> (0x0400): DP Request [Initgroups #17]: Request removed.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_req_destructor]
> (0x0400): Number of active DP request: 0
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [dp_get_account_info_initgroups_step] (0x0400): Ordering NSS responder to
> update memory cache
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sysdb_set_entry_attr]
> (0x0200): Entry [name=MY_USERNAME@domain.net,cn=users,cn=domain.net,cn=sysdb]
> has set [ts_cache] attrs.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sbus_issue_request_done]
> (0x0400): sssd.dataprovider.getAccountInfo: Success
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_pam_handler_send]
> (0x0100): Got request with the following data
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): command: SSS_PAM_AUTHENTICATE
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): domain: domain.net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): user: MY_USERNAME@domain.net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): service: login
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): tty: tty4
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): ruser:
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): rhost:
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): authtok type: 1
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): newauthtok type: 0
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): priv: 1
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): cli_pid: 70306
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): logon name: not set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): flags: 0
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_attach_req] (0x0400):
> DP Request [PAM Authenticate #18]: New request. Flags [0000].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_attach_req] (0x0400):
> Number of active DP request: 1
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [krb5_auth_send]
> (0x0100): Domain directory for user [MY_USERNAME@domain.net] not known.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [fo_resolve_service_send]
> (0x0100): Trying to resolve service 'AD'
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [resolve_srv_send]
> (0x0200): The status of SRV lookup is resolved
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [be_resolve_server_process] (0x0200): Found address for server
> ADDC.domain.net: [192.168.5.4] TTL 900
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [write_pipe_handler]
> (0x0400): All data has been sent!
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [child_sig_handler]
> (0x0100): child [71170] finished successfully.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [read_pipe_handler]
> (0x0400): EOF received, client finished
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [fo_set_port_status]
> (0x0100): Marking port 389 of server 'ADDC.domain.net' as 'working'
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [set_server_common_status] (0x0100): Marking server 'ADDC.domain.net' as
> 'working'
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [fo_set_port_status]
> (0x0400): Marking port 389 of duplicate server 'ADDC.domain.net' as
> 'working'
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sysdb_set_entry_attr]
> (0x0200): Entry [name=MY_USERNAME@domain.net,cn=users,cn=domain.net,cn=sysdb]
> has set [cache, ts_cache] attrs.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sysdb_set_entry_attr]
> (0x0200): Entry [name=MY_USERNAME@domain.net,cn=users,cn=domain.net,cn=sysdb]
> has set [cache, ts_cache] attrs.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_req_done] (0x0400):
> DP Request [PAM Authenticate #18]: Request handler finished [0]: Success
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [_dp_req_recv] (0x0400):
> DP Request [PAM Authenticate #18]: Receiving request data.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_req_destructor]
> (0x0400): DP Request [PAM Authenticate #18]: Request removed.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_req_destructor]
> (0x0400): Number of active DP request: 0
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_method_enabled]
> (0x0400): Target selinux is not configured
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sbus_issue_request_done]
> (0x0400): sssd.dataprovider.pamHandler: Success
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_pam_handler_send]
> (0x0100): Got request with the following data
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): command: SSS_PAM_ACCT_MGMT
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): domain: domain.net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): user: MY_USERNAME@domain.net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): service: login
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): tty: tty4
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): ruser:
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): rhost:
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): authtok type: 0
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): newauthtok type: 0
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): priv: 1
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): cli_pid: 70306
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): logon name: not set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [pam_print_data]
> (0x0100): flags: 0
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_attach_req] (0x0400):
> DP Request [PAM Account #19]: New request. Flags [0000].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_attach_req] (0x0400):
> Number of active DP request: 1
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_access_send]
> (0x0400): Performing access check for user [MY_USERNAME@domain.net]
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_account_expired_ad]
> (0x0400): Performing AD access check for user [MY_USERNAME@domain.net]
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [ad_gpo_access_send]
> (0x0400): service login maps to Interactive
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [ad_gpo_connect_done]
> (0x0400): sam_account_name is COMPUTER$
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(&(objectclass=user)(sAMAccountName=COMPUTER$))][dc=domain,dc=net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [objectclass=domain][DC=domain,DC=net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_master_domain_next_done] (0x0400): Found SID
> [S-1-5-21-3635097336-3991203712-2063481127].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(&(DnsDomain=domain.net)(NtVer=\14\00\00\00))][].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_master_domain_netlogon_done] (0x0400): Found flat name [DOMAIN].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_master_domain_netlogon_done] (0x0400): Found site [Domain].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_master_domain_netlogon_done] (0x0400): Found forest [domain.net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_gpo_site_name_retrieval_done] (0x0400): Using AD site 'cn=Domain'.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(objectclass=*)][].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_gpo_site_dn_retrieval_done] (0x0400): som_list[0]->som_dn is
> OU=Computers,DC=domain,DC=net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_gpo_site_dn_retrieval_done] (0x0400): som_list[1]->som_dn is
> DC=domain,DC=net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_gpo_site_dn_retrieval_done] (0x0400): som_list[2]->som_dn is
> cn=Domain,cn=Sites,CN=Configuration,DC=domain,DC=net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(objectclass=*)][OU=Computers,DC=domain,DC=net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_gpo_populate_gplink_list] (0x0400): som_dn:
> OU=Computers,DC=domain,DC=net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(objectclass=*)][DC=domain,DC=net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_gpo_populate_gplink_list] (0x0400): som_dn: DC=domain,DC=net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(objectclass=*)][cn=Domain,cn=Sites,CN=Configuration,DC=domain,DC=net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_gpo_get_som_attrs_done] (0x0040): no attrs found for SOM; try next SOM
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_gpo_populate_candidate_gpos] (0x0400): candidate_gpos[0]->gpo_dn:
> CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=domain,DC=net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [ad_gpo_populate_candidate_gpos] (0x0400): candidate_gpos[1]->gpo_dn:
> cn={6FF5E2F5-D491-45A1-9432-5AB497AEF031},cn=policies,cn=system,DC=domain,DC=net
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sdap_sd_search_send]
> (0x0400): Searching entry
> [CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=domain,DC=net]
> using SD
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_send] (0x0400): WARNING: Disabling paging because
> scope is set to base.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
> [(objectclass=*)][CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=domain,DC=net].
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]]
> [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
> errmsg set
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [ad_gpo_parse_sd]
> (0x0020): Failed to pull security descriptor
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [ad_gpo_sd_process_attrs]
> (0x0040): ad_gpo_parse_sd() failed
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [ad_gpo_process_gpo_done]
> (0x0040): Unable to get GPO list: [22](Invalid argument)
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [ad_gpo_access_done]
> (0x0040): GPO-based access control failed.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_req_done] (0x0400):
> DP Request [PAM Account #19]: Request handler finished [0]: Success
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [_dp_req_recv] (0x0400):
> DP Request [PAM Account #19]: Receiving request data.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_req_destructor]
> (0x0400): DP Request [PAM Account #19]: Request removed.
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_req_destructor]
> (0x0400): Number of active DP request: 0
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [dp_method_enabled]
> (0x0400): Target selinux is not configured
> (Fri May  8 15:10:10 2020) [sssd[be[domain.net]]] [sbus_issue_request_done]
> (0x0400): sssd.dataprovider.pamHandler: Success
>
>
> === sssd_pam.log ====
>
> (Fri May  8 15:10:10 2020) [sssd[pam]] [get_client_cred] (0x0080): The
> following failure is expected to happen in case SELinux is disabled:
> SELINUX_getpeercon failed [95][Operation not supported].
> Please, consider enabling SELinux in your system.
> (Fri May  8 15:10:10 2020) [sssd[pam]] [accept_fd_handler] (0x0400): Client
> [0x5606d6371860][19] connected to privileged pipe!
> (Fri May  8 15:10:10 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200):
> Received client version [3].
> (Fri May  8 15:10:10 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200):
> Offered version [3].
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_cmd_authenticate] (0x0100):
> entering pam_cmd_authenticate
> (Fri May  8 15:10:10 2020) [sssd[pam]] [sss_parse_name_for_domains]
> (0x0200): name 'my_username' matched without domain, user is my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): command:
> SSS_PAM_AUTHENTICATE
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): domain:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): user:
> my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): service:
> login
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: tty4
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok
> type: 1
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100):
> newauthtok type: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid:
> 70306
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): logon
> name: my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): flags: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_send] (0x0400): CR #12:
> New request 'Initgroups by name'
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_process_input] (0x0400):
> CR #12: Parsing input name [my_username]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [sss_parse_name_for_domains]
> (0x0200): name 'my_username' matched without domain, user is my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_set_name] (0x0400): CR
> #12: Setting name [my_username]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_select_domains] (0x0400):
> CR #12: Performing a multi-domain search
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_domains] (0x0400):
> CR #12: Search will bypass the cache and check the data provider
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_set_domain] (0x0400): CR
> #12: Using domain [domain.net]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_prepare_domain_data]
> (0x0400): CR #12: Preparing input data for domain [domain.net] rules
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_send] (0x0400): CR
> #12: Looking up my_username@domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400):
> CR #12: Checking negative cache for [my_username@domain.net]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400):
> CR #12: [my_username@domain.net] is not present in negative cache
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_dp] (0x0400): CR
> #12: Looking up [my_username@domain.net] in data provider
> (Fri May  8 15:10:10 2020) [sssd[pam]] [sss_dp_get_account_send] (0x0400):
> Creating request for [domain.net
> ][0x3][BE_REQ_INITGROUPS][name=my_username@domain.net:-]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_cache] (0x0400):
> CR #12: Looking up [my_username@domain.net] in cache
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_ncache_filter]
> (0x0400): CR #12: This request type does not support filtering result by
> negative cache
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_done] (0x0400): CR
> #12: Returning updated object [my_username@domain.net]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_create_and_add_result]
> (0x0400): CR #12: Found 4 entries in domain domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_done] (0x0400): CR #12:
> Finished: Success
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pd_set_primary_name] (0x0400):
> User's primary name is my_username@domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending
> request with the following data:
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): command:
> SSS_PAM_AUTHENTICATE
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): domain:
> domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): user:
> my_username@domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): service:
> login
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: tty4
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok
> type: 1
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100):
> newauthtok type: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid:
> 70306
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): logon
> name: my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): flags: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_dom_forwarder] (0x0100):
> pam_dp_send_req returned 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_dp_send_req_done] (0x0200):
> received: [0 (Success)][domain.net]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [sysdb_set_entry_attr] (0x0200):
> Entry [name=my_username@domain.net,cn=users,cn=domain.net,cn=sysdb] has set
> [cache, ts_cache] attrs.
> (Fri May  8 15:10:10 2020) [sssd[pam]] [filter_responses] (0x0100):
> [pam_response_filter] not available, not fatal.
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_reply] (0x0200): blen: 85
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_reply] (0x0200): Returning [0]:
> Success to the client
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_cmd_acct_mgmt] (0x0100):
> entering pam_cmd_acct_mgmt
> (Fri May  8 15:10:10 2020) [sssd[pam]] [sss_parse_name_for_domains]
> (0x0200): name 'my_username' matched without domain, user is my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): command:
> SSS_PAM_ACCT_MGMT
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): domain:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): user:
> my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): service:
> login
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: tty4
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok
> type: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100):
> newauthtok type: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid:
> 70306
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): logon
> name: my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): flags: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_send] (0x0400): CR #13:
> New request 'Initgroups by name'
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_process_input] (0x0400):
> CR #13: Parsing input name [my_username]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [sss_parse_name_for_domains]
> (0x0200): name 'my_username' matched without domain, user is my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_set_name] (0x0400): CR
> #13: Setting name [my_username]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_select_domains] (0x0400):
> CR #13: Performing a multi-domain search
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_domains] (0x0400):
> CR #13: Search will check the cache and check the data provider
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_set_domain] (0x0400): CR
> #13: Using domain [domain.net]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_prepare_domain_data]
> (0x0400): CR #13: Preparing input data for domain [domain.net] rules
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_send] (0x0400): CR
> #13: Looking up my_username@domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400):
> CR #13: Checking negative cache for [my_username@domain.net]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400):
> CR #13: [my_username@domain.net] is not present in negative cache
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_cache] (0x0400):
> CR #13: Looking up [my_username@domain.net] in cache
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_send] (0x0400): CR
> #13: Returning [my_username@domain.net] from cache
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_search_ncache_filter]
> (0x0400): CR #13: This request type does not support filtering result by
> negative cache
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_create_and_add_result]
> (0x0400): CR #13: Found 4 entries in domain domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [cache_req_done] (0x0400): CR #13:
> Finished: Success
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pd_set_primary_name] (0x0400):
> User's primary name is my_username@domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending
> request with the following data:
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): command:
> SSS_PAM_ACCT_MGMT
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): domain:
> domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): user:
> my_username@domain.net
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): service:
> login
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: tty4
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost:
> not set
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok
> type: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100):
> newauthtok type: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid:
> 70306
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): logon
> name: my_username
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_print_data] (0x0100): flags: 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_dom_forwarder] (0x0100):
> pam_dp_send_req returned 0
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_dp_send_req_done] (0x0200):
> received: [4 (System error)][domain.net]
> (Fri May  8 15:10:10 2020) [sssd[pam]] [filter_responses] (0x0100):
> [pam_response_filter] not available, not fatal.
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_reply] (0x0200): blen: 31
> (Fri May  8 15:10:10 2020) [sssd[pam]] [pam_reply] (0x0200): Returning [4]:
> System error to the client
> (Fri May  8 15:10:10 2020) [sssd[pam]] [client_recv] (0x0200): Client
> disconnected!

> _______________________________________________
> sssd-users mailing list -- sssd-users@lists.fedorahosted.org
> To unsubscribe send an email to sssd-users-leave@lists.fedorahosted.org
> Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives: https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.org
_______________________________________________
sssd-users mailing list -- sssd-users@lists.fedorahosted.org
To unsubscribe send an email to sssd-users-leave@lists.fedorahosted.org
Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.org