==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7fadf253c4a0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_dispatch] (0x4000): Dispatching. (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 17707 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #78]: New request. Flags [0000]. (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain ipa.splat.acme.com is Active (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain splat.acme.com is Inactive (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain ipa.splat.acme.com is Active (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain splat.acme.com is Inactive (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [myuser@splat.acme.com] is empty, running request [0x7fadf254e780] immediately. (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain ipa.splat.acme.com is Active (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain splat.acme.com is Inactive (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_setup] (0x4000): No mapping for: myuser@splat.acme.com (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fadf2540fa0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fadf255be80 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Running timer event 0x7fadf2540fa0 "ltdb_callback" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Destroying timer event 0x7fadf255be80 "ltdb_timeout" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Ending timer event 0x7fadf2540fa0 "ltdb_callback" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fadf254c770 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fadf255a1e0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Running timer event 0x7fadf254c770 "ltdb_callback" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Destroying timer event 0x7fadf255a1e0 "ltdb_timeout" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Ending timer event 0x7fadf254c770 "ltdb_callback" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [get_server_status] (0x1000): Status of server 'va-prod-ipa01.ipa.splat.acme.com' is 'working' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [get_port_status] (0x1000): Port status of port 0 for server 'va-prod-ipa01.ipa.splat.acme.com' is 'working' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [get_server_status] (0x1000): Status of server 'va-prod-ipa01.ipa.splat.acme.com' is 'working' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x0200): Found address for server va-prod-ipa01.ipa.splat.acme.com: [172.18.181.132] TTL 7200 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://va-prod-ipa01.ipa.splat.acme.com' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_TjcBSc] (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_TjcBSc] (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain splat.acme.com is Inactive (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_resolve_done] (0x2000): Subdomain splat.acme.com is inactive, will proceed offline (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [17708] (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [17708] (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7fadf25326a0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_dispatch] (0x4000): Dispatching. (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent! ==> /var/log/sssd/krb5_child.log <== (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [main] (0x0400): krb5_child started. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [unpack_buffer] (0x1000): total buffer size: [147] (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [unpack_buffer] (0x0100): cmd [249] uid [612329111] gid [612329111] validate [true] enterprise principal [false] offline [true] UPN [myuser@SPLAT.acme.COM] (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:612329111] old_ccname: [KEYRING:persistent:612329111] keytab: [/etc/krb5.keytab] (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [become_user] (0x0200): Trying to become user [612329111][612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [main] (0x2000): Running as [612329111][612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [become_user] (0x0200): Trying to become user [612329111][612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [become_user] (0x0200): Already user [612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [k5c_setup] (0x2000): Running as [612329111][612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [main] (0x0400): Will perform pre-auth (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [tgt_req_child] (0x1000): Attempting to get a TGT (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.COM] (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107670: Getting initial credentials for myuser@SPLAT.acme.COM (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107672: Sending request (174 bytes) to SPLAT.acme.COM (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107673: Resolving hostname SV-DC-01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107674: Resolving hostname EQ-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107675: Resolving hostname VA-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107676: Resolving hostname FR-PROD-AD01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107677: Resolving hostname SV-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107678: Resolving hostname FR-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107679: Resolving hostname VA-PROD-AD01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107680: Resolving hostname EQ-PROD-AD01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107681: Resolving hostname SV-DC-01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107682: Initiating TCP connection to stream 172.18.171.35:88 ==> /var/log/sssd/sssd_pam.log <== (Tue Feb 19 19:04:52 2019) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [myuser@splat.acme.com] removed from PAM initgroup cache ==> /var/log/sssd/krb5_child.log <== (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436765: Resolving hostname EQ-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436766: Initiating TCP connection to stream 10.25.172.49:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436767: Sending TCP request to stream 10.25.172.49:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436768: Received answer (185 bytes) from stream 10.25.172.49:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436769: Terminating TCP connection to stream 172.18.171.35:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436770: Terminating TCP connection to stream 10.25.172.49:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436771: Response was not from master KDC (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436772: Received error from KDC: -1765328359/Additional pre-authentication required (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436775: Processing preauth types: 16, 15, 19, 2 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436776: Selected etype info: etype aes256-cts, salt "SPLAT.acme.COMmyuser", params "" (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436777: PKINIT client has no configured identity; giving up (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_krb5_responder] (0x4000): Got question [password]. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436778: PKINIT client has no configured identity; giving up (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436779: Preauth module pkinit (16) (real) returned: 22/Invalid argument (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436780: PKINIT client has no configured identity; giving up (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436781: Preauth module pkinit (14) (real) returned: 22/Invalid argument (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for myuser@SPLAT.acme.COM]. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436782: Preauth module encrypted_timestamp (2) (real) returned: -1765328254/Cannot read password (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436783: Retrying AS request with master KDC (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436784: Getting initial credentials for myuser@SPLAT.acme.COM (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436786: Sending request (174 bytes) to SPLAT.acme.COM (master) (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [k5c_send_data] (0x0200): Received error code 0 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [pack_response_packet] (0x2000): response packet size: [12] (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [k5c_send_data] (0x4000): Response sent. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [main] (0x0400): krb5_child completed successfully ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x1000): Waiting for child [17708]. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [17708] finished successfully. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [parse_krb5_child_response] (0x1000): child response [0][11][0]. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/krb5/krb5_auth.c: krb5_auth_done: 1093 (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [set_server_common_status] (0x0100): Marking server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_mod_ccname] (0x4000): Save ccname [KEYRING:persistent:612329111] for user [myuser@splat.acme.com]. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fadf255a9e0 (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fadf255aaa0 (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Running timer event 0x7fadf255a9e0 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Destroying timer event 0x7fadf255aaa0 "ltdb_timeout" (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Ending timer event 0x7fadf255a9e0 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myuser@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [ts_cache] attrs. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_cache_creds] (0x0080): Delayed authentication is only available for password authentication (single factor). (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [check_wait_queue] (0x1000): Wait queue for user [myuser@splat.acme.com] is empty. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x7fadf254e780] done. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #78]: Request handler finished [0]: Success (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #78]: Receiving request data. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #78]: Request removed. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_reply] (0x1000): DP Request [PAM Preauth #78]: Sending result [4][splat.acme.com] ==> /var/log/sssd/sssd_pam.log <== (Tue Feb 19 19:04:53 2019) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7f2ccb506110 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7f2ccb5026e0 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Tue Feb 19 19:04:53 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][splat.acme.com] (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2ccb525510 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2ccb503700 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7f2ccb503700 "ltdb_timeout" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error. (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2ccb525510 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2ccb514620 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7f2ccb514620 "ltdb_timeout" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2ccb525510 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2ccb503700 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7f2ccb503700 "ltdb_timeout" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Tue Feb 19 19:04:53 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 37 ^C