Hi, 

The troubleshooting guide in the docs said to email the list if the System Error (4) shows up, so I figured I bring this issue up.  I'm running sssd version 1.16.0 on Debian testing and recently encountered a new behavior.  We set up sssd with active directory based authentication on an already established system.  For various reasons there are still local passwd users, some of whom also have ad accounts.  What used to happen is that the pam/nsswitch stack was set up so that those users would end up with their passwd id.  If they had an ad account they could log in with either their shadow password or their ad password.  Right after we upgraded from 1.16.0-1 to 1.16.0-2 any local user generated a System Error (4) in the logs and and local users with ad accounts could no longer use their ad passwords (although they could still use their local passwords).  There isn't a lot of information in the logs.

auth.log: 

Jan 23 19:02:27 spoon su[28320]: pam_unix(su:auth): authentication failure; logname=goehle uid=1000 euid=0 tty=/dev/pts/0 ruser=goehle rhost=  user=picard

Jan 23 19:02:27 spoon su[28320]: pam_sss(su:auth): authentication failure; logname=goehle uid=1000 euid=0 tty=/dev/pts/0 ruser=goehle rhost= user=picard

Jan 23 19:02:27 spoon su[28320]: pam_sss(su:auth): received for user picard: 4 (System error)

sssd_pam.log (full version below):

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): domain: implicit_files

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): user: picard@implicit_files

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): service: su

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/pts/0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): ruser: goehle

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): priv: 0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 28320

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): logon name: picard

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x55bc08045290

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x55bc08045290

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_dp_process_reply] (0x0010): Reply error.

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error.

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_reply] (0x0200): blen: 31

There aren't any other log entries with this time stamp.  In particular there aren't any entries in the domain log, the pam_nss log or the krb5_child log.  I am able to authenticate manually with kinit, however.  I would really appreciate it if someone could point me to the right logs, or even just tell me that mixing local and sss users in this way is not supported.  

Thanks for your time. 

Geoff Goehle. 

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected!

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3].

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3].

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering pam_cmd_authenticate

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_domain_get_state] (0x1000): Domain wcu.edu is Active

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'picard' matched without domain, user is picard

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): domain: not set

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): user: picard

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): service: su

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/pts/0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): ruser: goehle

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): priv: 0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 28320

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): logon name: picard

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_set_plugin] (0x2000): CR #12: Setting "Initgroups by name" plugin

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_send] (0x0400): CR #12: New request 'Initgroups by name'

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_process_input] (0x0400): CR #12: Parsing input name [picard]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_domain_get_state] (0x1000): Domain wcu.edu is Active

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'picard' matched without domain, user is picard

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_set_name] (0x0400): CR #12: Setting name [picard]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #12: Performing a multi-domain search

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #12: Search will bypass the cache and check the data provider

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain implicit_files type POSIX is valid

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #12: Using domain [implicit_files]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #12: Preparing input data for domain [implicit_files] rules

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_search_send] (0x0400): CR #12: Looking up picard@implicit_files

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #12: Checking negative cache for [picard@implicit_files]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/implicit_files/picard@implicit_files]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #12: [picard@implicit_files] is not present in negative cache

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #12: Looking up [picard@implicit_files] in data provider

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_dp_account_files_params] (0x2000): Domain files is not consistent, issuing update

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x55bc077c6930:3:files_initgr_request@implicit_files]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [implicit_files][0x3][BE_REQ_INITGROUPS][name=files_initgr_request:-]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x55bc08045290

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x55bc077c6930:3:files_initgr_request@implicit_files]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x55bc08045290

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #12: Looking up [picard@implicit_files] in cache

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400)

: CR #12: This request type does not support filtering result by negative cache

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_search_done] (0x0400): CR #12: Returning updated object [picard@implicit_files]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #12: Found 3 entries in domain implicit_files

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x55bc077c6930:3:files_initgr_request@implicit_files]

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [cache_req_done] (0x0400): CR #12: Finished: Success

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is picard@implicit_files

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [picard] added to PAM initgroup cache

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): domain: implicit_files

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): user: picard@implicit_files

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): service: su

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): tty: /dev/pts/0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): ruser: goehle

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): priv: 0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 28320

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_print_data] (0x0100): logon name: picard

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x55bc08045290

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x55bc08045290

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_dp_process_reply] (0x0010): Reply error.

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error.

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.

(Tue Jan 23 19:02:27 2018) [sssd[pam]] [pam_reply] (0x0200): blen: 31