On Thu, Jun 4, 2020, at 11:47 AM, Abhijit Tikekar wrote:

Hi all,

We recently started having issues with some SSSD clients that are connecting to RODC. They were all working fine when suddenly all authentications started getting following

sshd[4487]: pam_sss(sshd:auth): received for user firstname.lastname: 4 (System error)

Try setting krb5_validate=false in the domain section.

V/r, James Cassell

Being a RODC, keytab was created manually on a writable DC using setspn & ktpass and then integrated on the system using ktutil. Things were fine until last week when it stopped working on all such systems. We are not able to identify if the issue is on the system side or AD. Network side looks good and all required ports are open between client and Server. Host can also resolve RODC via DNS. Even other utilities such as ldapsearch, getent, id etc retrieve the results just fine. It is only the main login process that fails. Attaching parts of logs generated with debug level 10.

It would be great if someone can review these and point us in the right direction.

_*sssd_domain.log*_

(Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [get_server_status] (0x1000): Status of server 'RODC.x.y.local' is 'name resolved' (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [get_port_status] (0x1000): Port status of port 0 for server 'RODC.x.y.local' is 'not working' (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [fo_resolve_service_send] (0x0020): No available servers for service 'AD' (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_op_connect_done] (0x0020): Failed to connect, going offline (5 [Input/output error]) (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_mark_offline] (0x2000): Going offline! (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_mark_offline] (0x2000): Enable check_if_online_ptask. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_ptask_enable] (0x0080): Task [Check if online (periodic)]: already enabled (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_run_offline_cb] (0x4000): Flag indicates that offline callback were already called. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_op_connect_done] (0x4000): notify offline to op #1 (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [ad_subdomains_refresh_connect_done] (0x0020): Unable to connect to LDAP [11]: Resource temporarily unavailable (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [ad_subdomains_refresh_connect_done] (0x0080): No AD server is available, cannot get the subdomain list while offline (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_done] (0x0400): DP Request [Subdomains #2]: Request handler finished [0]: Success (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [_dp_req_recv] (0x0400): DP Request [Subdomains #2]: Receiving request data. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_reply_list_success] (0x0400): DP Request [Subdomains #2]: Finished. Success. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_reply_std] (0x1000): DP Request [Subdomains #2]: Returning [Provider is Offline]: 1,1432158212,Offline (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_table_value_destructor] (0x0400): Removing [8:8:0000:<ALL>] from reply table (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_destructor] (0x0400): DP Request [Subdomains #2]: Request removed. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sbus_dispatch] (0x4000): dbus conn: 0x55c31927bed0 (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_ptask_offline_cb] (0x0400): Back end is offline

_*ldap_child.log*_

(Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x0400): ldap_child started. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000): context initialized (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): total buffer size: 73 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): realm_str size: 14 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): got realm_str: x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): princ_str size: 35 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): got princ_str: host/dmz_host.x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x0200): Will run as [0][0]. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [privileged_krb5_setup] (0x2000): Kerberos context initialized (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000): Kerberos context initialized (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [become_user] (0x0200): Trying to become user [0][0]. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [become_user] (0x0200): Already user [0]. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000): Running as [0][0]. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000): getting TGT sync (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [x.y.local] (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [host/dmz_host.x.y.local@x.y.local] (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab] (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529555: Getting initial credentials for host/dmz_host.x.y.local@x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529556: Looked up etypes in keytab: rc4-hmac, rc4-hmac, rc4-hmac (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529558: Sending unauthenticated request (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529559: Sending request (227 bytes) to x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529560: Sending initial UDP request to dgram x.x.x.x:88 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529561: Received answer (220 bytes) from dgram x.x.x.x:88 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529562: Response was from master KDC (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529563: Received error from KDC: -1765328359/Additional pre-authentication required (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529566: Preauthenticating using KDC method data (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529567: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2) (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529568: Selected etype info: etype rc4-hmac, salt "", params "" (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529569: Retrieving host/dmz_host.x.y.local@x.y.local from MEMORY:/etc/krb5.keytab (vno 0, enctype rc4-hmac) with result: 0/Success (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529570: AS key obtained for encrypted timestamp: rc4-hmac/D7FD (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529572: Encrypted timestamp (for 1590549052.518887): plain 301AA011180F32303230303532373033313035325AA105020307EAE7, encrypted 5B0813887E05A9BDC49D2BA37EEC1C61CC0E6A51212B5A29DB1AA6F319E5C11BD6E9F9D843A3E4E5ED511C932BAFAB13B7995E39 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529573: Preauth module encrypted_timestamp (2) (real) returned: 0/Success (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529574: Produced preauth for next request: PA-ENC-TIMESTAMP (2) (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529575: Sending request (303 bytes) to x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529576: Sending initial UDP request to dgram x.x.x.x:88 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529577: Received answer (100 bytes) from dgram x.x.x.x:88 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529578: Response was from master KDC (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529579: Received error from KDC: -1765328370/KDC has no support for encryption type (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [ldap_child_get_tgt_sync] (0x0010): Failed to init credentials: KDC has no support for encryption type (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_x.y.local_AosPub] (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x0020): ldap_child_get_tgt_sync failed.

_*krb5_child.log*_

(Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x0400): krb5_child started. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [unpack_buffer] (0x1000): total buffer size: [171] (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [unpack_buffer] (0x0100): cmd [241] uid [xxxxxxxxx] gid [yyyyyyyyy] validate [false] enterprise principal [false] offline [true] UPN [firstname.lastname@x.y.local] (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:xxxxxxxxx] old_ccname: [KEYRING:persistent:xxxxxxxxx] keytab: [/etc/krb5.keytab] (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [check_use_fast] (0x0100): Not using FAST. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [switch_creds] (0x0200): Switch user to [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [switch_creds] (0x0200): Switch user to [0][0]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:xxxxxxxxx] and is not active and TGT is valid. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [become_user] (0x0200): Trying to become user [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x2000): Running as [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [become_user] (0x0200): Trying to become user [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [become_user] (0x0200): Already user [xxxxxxxxx]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_setup] (0x2000): Running as [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x0400): Will perform offline auth (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [create_empty_ccache] (0x1000): Existing ccache still valid, reusing (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_send_data] (0x0200): Received error code 0 (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [pack_response_packet] (0x2000): response packet size: [52] (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_send_data] (0x4000): Response sent. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x0400): krb5_child completed successfully

_*sssd_pam.log*_

(Tue May 26 23:11:06 2020) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[12602]. (Tue May 26 23:11:06 2020) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x562762f1f590][19] (Tue May 26 23:11:06 2020) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe! (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3]. (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3]. (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering pam_cmd_authenticate (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'firstname.lastname' matched without domain, user is firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): domain: not set (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): user: firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost: remote_host.x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 12602 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): logon name: firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_initgr_check_timeout] (0x4000): User [firstname.lastname] not found in PAM cache. (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_set_plugin] (0x2000): CR #0: Setting "Initgroups by name" plugin (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_send] (0x0400): CR #0: New request 'Initgroups by name' (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_process_input] (0x0400): CR #0: Parsing input name [firstname.lastname] (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'firstname.lastname' matched without domain, user is firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_set_name] (0x0400): CR #0: Setting name [firstname.lastname] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #0: Performing a multi-domain search (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #0: Search will bypass the cache and check the data provider (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain x.y.local type POSIX is valid (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #0: Using domain [x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #0: Preparing input data for domain [x.y.local] rules (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_send] (0x0400): CR #0: Looking up firstname.lastname@x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0: Checking negative cache for [firstname.lastname@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/x.y.local/firstname.lastname@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0: [firstname.lastname@x.y.local] is not present in negative cache (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #0: Looking up [firstname.lastname@x.y.local] in data provider (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x5627622d5930:3:firstname.lastname@x.y.local@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [x.y.local][0x3][BE_REQ_INITGROUPS][name=firstname.lastname@x.y.local:-] (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x562762f19c90 (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x5627622d5930:3:firstname.lastname@x.y.local@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x562762f19c90 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x562762f17990 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_get_reply] (0x0010): The Data Provider returned an error [org.freedesktop.sssd.Error.DataProvider.Offline] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_common_dp_recv] (0x0040): CR #0: Data Provider Error: 3, 5, Failed to get reply from Data Provider (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_common_dp_recv] (0x0400): CR #0: Due to an error we will return cached data (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #0: Looking up [firstname.lastname@x.y.local] in cache (Tue May 26 23:11:06 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x562762f294a0 ... ... (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #0: This request type does not support filtering result by negative cache (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_done] (0x0400): CR #0: Returning updated object [firstname.lastname@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #0: Found 15 entries in domain x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x5627622d5930:3:firstname.lastname@x.y.local@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_done] (0x0400): CR #0: Finished: Success (Tue May 26 23:11:06 2020) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is firstname.lastname@x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [firstname.lastname] added to PAM initgroup cache (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): domain: x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): user: firstname.lastname@x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost: remote_host.x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 12602 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): logon name: firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x562762f19c90 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x562762f19c90 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x562762f17990 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x562762f3be60 ... ... (Tue May 26 23:11:06 2020) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_reply] (0x0200): blen: 79 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_reply] (0x0200): Returning [4]: System error to the client (Tue May 26 23:11:08 2020) [sssd[pam]] [client_recv] (0x0200): Client disconnected! (Tue May 26 23:11:08 2020) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x562762f1f590][19] (Tue May 26 23:11:11 2020) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [firstname.lastname] removed from PAM initgroup cache

Thanks,

~ Abhi

On Thu, Jun 04, 2020 at 11:47:36AM -0400, Abhijit Tikekar wrote:

Hi all,

We recently started having issues with some SSSD clients that are connecting to RODC. They were all working fine when suddenly all authentications started getting following

sshd[4487]: pam_sss(sshd:auth): received for user firstname.lastname: 4 (System error)

Being a RODC, keytab was created manually on a writable DC using setspn & ktpass and then integrated on the system using ktutil. Things were fine until last week when it stopped working on all such systems. We are not able to identify if the issue is on the system side or AD. Network side looks good and all required ports are open between client and Server. Host can also resolve RODC via DNS. Even other utilities such as ldapsearch, getent, id etc retrieve the results just fine. It is only the main login process that fails. Attaching parts of logs generated with debug level 10.

It would be great if someone can review these and point us in the right direction.

*sssd_domain.log*

(Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [get_server_status] (0x1000): Status of server 'RODC.x.y.local' is 'name resolved' (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [get_port_status] (0x1000): Port status of port 0 for server 'RODC.x.y.local' is 'not working' (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [fo_resolve_service_send] (0x0020): No available servers for service 'AD' (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_resolve_server_done] (0x1000): Server resolution failed: [5]: Input/output error (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_op_connect_done] (0x0020): Failed to connect, going offline (5 [Input/output error]) (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_mark_offline] (0x2000): Going offline! (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_mark_offline] (0x2000): Enable check_if_online_ptask. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_ptask_enable] (0x0080): Task [Check if online (periodic)]: already enabled (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_run_offline_cb] (0x4000): Flag indicates that offline callback were already called. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_op_connect_done] (0x4000): notify offline to op #1 (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [ad_subdomains_refresh_connect_done] (0x0020): Unable to connect to LDAP [11]: Resource temporarily unavailable (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [ad_subdomains_refresh_connect_done] (0x0080): No AD server is available, cannot get the subdomain list while offline (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_done] (0x0400): DP Request [Subdomains #2]: Request handler finished [0]: Success (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [_dp_req_recv] (0x0400): DP Request [Subdomains #2]: Receiving request data. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_reply_list_success] (0x0400): DP Request [Subdomains #2]: Finished. Success. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_reply_std] (0x1000): DP Request [Subdomains #2]: Returning [Provider is Offline]: 1,1432158212,Offline (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_table_value_destructor] (0x0400): Removing [8:8:0000:<ALL>] from reply table (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_destructor] (0x0400): DP Request [Subdomains #2]: Request removed. (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sbus_dispatch] (0x4000): dbus conn: 0x55c31927bed0 (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_ptask_offline_cb] (0x0400): Back end is offline

*ldap_child.log*

(Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x0400): ldap_child started. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000): context initialized (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): total buffer size: 73 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): realm_str size: 14 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): got realm_str: x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): princ_str size: 35 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): got princ_str: host/dmz_host.x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer] (0x0200): Will run as [0][0]. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [privileged_krb5_setup] (0x2000): Kerberos context initialized (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000): Kerberos context initialized (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [become_user] (0x0200): Trying to become user [0][0]. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [become_user] (0x0200): Already user [0]. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000): Running as [0][0]. (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000): getting TGT sync (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [x.y.local] (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [host/dmz_host.x.y.local@x.y.local] (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab] (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529555: Getting initial credentials for host/dmz_host.x.y.local@x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529556: Looked up etypes in keytab: rc4-hmac, rc4-hmac, rc4-hmac

^^^^^^^^^^^^^^^^^^^^^^^^^^^^

(Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529558: Sending unauthenticated request (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529559: Sending request (227 bytes) to x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529560: Sending initial UDP request to dgram x.x.x.x:88 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529561: Received answer (220 bytes) from dgram x.x.x.x:88 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529562: Response was from master KDC (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529563: Received error from KDC: -1765328359/Additional pre-authentication required (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529566: Preauthenticating using KDC method data (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529567: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2) (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529568: Selected etype info: etype rc4-hmac, salt "", params "" (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529569: Retrieving host/dmz_host.x.y.local@x.y.local from MEMORY:/etc/krb5.keytab (vno 0, enctype rc4-hmac) with result: 0/Success (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529570: AS key obtained for encrypted timestamp: rc4-hmac/D7FD (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529572: Encrypted timestamp (for 1590549052.518887): plain 301AA011180F32303230303532373033313035325AA105020307EAE7, encrypted 5B0813887E05A9BDC49D2BA37EEC1C61CC0E6A51212B5A29DB1AA6F319E5C11BD6E9F9D843A3E4E5ED511C932BAFAB13B7995E39 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529573: Preauth module encrypted_timestamp (2) (real) returned: 0/Success (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529574: Produced preauth for next request: PA-ENC-TIMESTAMP (2) (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529575: Sending request (303 bytes) to x.y.local (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529576: Sending initial UDP request to dgram x.x.x.x:88 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529577: Received answer (100 bytes) from dgram x.x.x.x:88 (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529578: Response was from master KDC (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529579: Received error from KDC: -1765328370/KDC has no support for encryption type (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [ldap_child_get_tgt_sync] (0x0010): Failed to init credentials: KDC has no support for encryption type

Hi,

it looks like the keytab only has keys with rc4 and the AD DC does not like those keys anymore. Is there a chance that there was a change on the AD side recently which enforces AES keys? Can you try to get a new keytab with AES keys?

bye, Sumit

(Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_x.y.local_AosPub] (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x0020): ldap_child_get_tgt_sync failed.

*krb5_child.log*

(Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x0400): krb5_child started. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [unpack_buffer] (0x1000): total buffer size: [171] (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [unpack_buffer] (0x0100): cmd [241] uid [xxxxxxxxx] gid [yyyyyyyyy] validate [false] enterprise principal [false] offline [true] UPN [firstname.lastname@x.y.local] (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:xxxxxxxxx] old_ccname: [KEYRING:persistent:xxxxxxxxx] keytab: [/etc/krb5.keytab] (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [check_use_fast] (0x0100): Not using FAST. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [switch_creds] (0x0200): Switch user to [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [switch_creds] (0x0200): Switch user to [0][0]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:xxxxxxxxx] and is not active and TGT is valid. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [become_user] (0x0200): Trying to become user [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x2000): Running as [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [become_user] (0x0200): Trying to become user [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [become_user] (0x0200): Already user [xxxxxxxxx]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_setup] (0x2000): Running as [xxxxxxxxx][yyyyyyyyy]. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x0400): Will perform offline auth (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [create_empty_ccache] (0x1000): Existing ccache still valid, reusing (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_send_data] (0x0200): Received error code 0 (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [pack_response_packet] (0x2000): response packet size: [52] (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_send_data] (0x4000): Response sent. (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x0400): krb5_child completed successfully

*sssd_pam.log*

(Tue May 26 23:11:06 2020) [sssd[pam]] [get_client_cred] (0x4000): Client creds: euid[0] egid[0] pid[12602]. (Tue May 26 23:11:06 2020) [sssd[pam]] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x562762f1f590][19] (Tue May 26 23:11:06 2020) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe! (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3]. (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3]. (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering pam_cmd_authenticate (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'firstname.lastname' matched without domain, user is firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): domain: not set (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): user: firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost: remote_host.x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 12602 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): logon name: firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_initgr_check_timeout] (0x4000): User [firstname.lastname] not found in PAM cache. (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_set_plugin] (0x2000): CR #0: Setting "Initgroups by name" plugin (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_send] (0x0400): CR #0: New request 'Initgroups by name' (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_process_input] (0x0400): CR #0: Parsing input name [firstname.lastname] (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'firstname.lastname' matched without domain, user is firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_set_name] (0x0400): CR #0: Setting name [firstname.lastname] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #0: Performing a multi-domain search (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #0: Search will bypass the cache and check the data provider (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain x.y.local type POSIX is valid (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #0: Using domain [x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #0: Preparing input data for domain [x.y.local] rules (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_send] (0x0400): CR #0: Looking up firstname.lastname@x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0: Checking negative cache for [firstname.lastname@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/x.y.local/firstname.lastname@x.y.local ] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #0: [firstname.lastname@x.y.local] is not present in negative cache (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #0: Looking up [firstname.lastname@x.y.local] in data provider (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x5627622d5930:3:firstname.lastname@x.y.local @x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [x.y.local][0x3][BE_REQ_INITGROUPS][name=firstname.lastname@x.y.local:-] (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x562762f19c90 (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x5627622d5930:3:firstname.lastname@x.y.local@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x562762f19c90 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x562762f17990 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_get_reply] (0x0010): The Data Provider returned an error [org.freedesktop.sssd.Error.DataProvider.Offline] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_common_dp_recv] (0x0040): CR #0: Data Provider Error: 3, 5, Failed to get reply from Data Provider (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_common_dp_recv] (0x0400): CR #0: Due to an error we will return cached data (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #0: Looking up [firstname.lastname@x.y.local] in cache (Tue May 26 23:11:06 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x562762f294a0 ... ... (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #0: This request type does not support filtering result by negative cache (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_done] (0x0400): CR #0: Returning updated object [firstname.lastname@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #0: Found 15 entries in domain x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x5627622d5930:3:firstname.lastname@x.y.local@x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_done] (0x0400): CR #0: Finished: Success (Tue May 26 23:11:06 2020) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is firstname.lastname@x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [firstname.lastname] added to PAM initgroup cache (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): domain: x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): user: firstname.lastname@x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost: remote_host.x.y.local (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 12602 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): logon name: firstname.lastname (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x562762f19c90 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x562762f19c90 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x562762f17990 (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][x.y.local] (Tue May 26 23:11:06 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x562762f3be60 ... ... (Tue May 26 23:11:06 2020) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_reply] (0x0200): blen: 79 (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_reply] (0x0200): Returning [4]: System error to the client (Tue May 26 23:11:08 2020) [sssd[pam]] [client_recv] (0x0200): Client disconnected! (Tue May 26 23:11:08 2020) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x562762f1f590][19] (Tue May 26 23:11:11 2020) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [firstname.lastname] removed from PAM initgroup cache

Thanks,

~ Abhi

---

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.o...