(Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [get_server_status] (0x1000): Status of server 'va-prod-ipa01.ipa.splat.acme.com' is 'working' (Mon Feb 25 16:19:41 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' (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [get_server_status] (0x1000): Status of server 'va-prod-ipa01.ipa.splat.acme.com' is 'working' (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Mon Feb 25 16:19:41 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 (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://va-prod-ipa01.ipa.splat.acme.com' (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_add_krb5info_offline_callback] (0x4000): Removal callback already available for service [IPA]. (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_fLmekx] (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_fLmekx] (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain splat.acme.com is Inactive (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_resolve_done] (0x2000): Subdomain splat.acme.com is inactive, will proceed offline (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [24328] (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [24328] (Mon Feb 25 16:19:41 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent! ==> /var/log/sssd/krb5_child.log-20190223 <== (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [main] (0x0400): krb5_child started. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [unpack_buffer] (0x1000): total buffer size: [149] (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [unpack_buffer] (0x0100): cmd [249] uid [611070070] gid [611070070] validate [true] enterprise principal [false] offline [true] UPN [myuser@SPLAT.acme.COM] (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:611070070] old_ccname: [KEYRING:persistent:611070070] keytab: [/etc/krb5.keytab] (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [become_user] (0x0200): Trying to become user [611070070][611070070]. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [main] (0x2000): Running as [611070070][611070070]. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [become_user] (0x0200): Trying to become user [611070070][611070070]. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [become_user] (0x0200): Already user [611070070]. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [k5c_setup] (0x2000): Running as [611070070][611070070]. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [main] (0x0400): Will perform pre-auth (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [tgt_req_child] (0x1000): Attempting to get a TGT (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.COM] (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111581.528136: Getting initial credentials for myuser@SPLAT.acme.COM (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111581.528138: Sending unauthenticated request (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111581.528139: Sending request (176 bytes) to SPLAT.acme.COM (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111581.528140: Resolving hostname EQ-PROD-AD01.splat.acme.com. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111581.528141: Resolving hostname SV-DC-01.splat.acme.com. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111581.528142: Resolving hostname EQ-PROD-AD02.splat.acme.com. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111581.528143: Resolving hostname VA-PROD-AD02.splat.acme.com. (Mon Feb 25 16:19:41 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111581.528144: Resolving hostname FR-PROD-AD01.splat.acme.com. (Mon Feb 25 16:19:42 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111582.87730: Resolving hostname SV-PROD-AD02.splat.acme.com. (Mon Feb 25 16:19:42 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111582.87731: Resolving hostname FR-PROD-AD02.splat.acme.com. (Mon Feb 25 16:19:42 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111582.87732: Resolving hostname VA-PROD-AD01.splat.acme.com. (Mon Feb 25 16:19:42 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111582.87733: Resolving hostname EQ-PROD-AD01.splat.acme.com. (Mon Feb 25 16:19:42 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111582.87734: Initiating TCP connection to stream 10.25.172.48:88 (Mon Feb 25 16:19:42 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111582.87735: Sending TCP request to stream 10.25.172.48:88 (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181475: Received answer (188 bytes) from stream 10.25.172.48:88 (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181476: Terminating TCP connection to stream 10.25.172.48:88 (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181477: Response was not from master KDC (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181478: Received error from KDC: -1765328359/Additional pre-authentication required (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181481: Preauthenticating using KDC method data (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181482: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2) (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181483: Selected etype info: etype aes256-cts, salt "SPLAT.acme.COMmyuser", params "" (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181484: PKINIT client has no configured identity; giving up (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_krb5_responder] (0x4000): Got question [password]. (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181485: PKINIT client has no configured identity; giving up (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181486: Preauth module pkinit (16) (real) returned: 22/Invalid argument (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181487: PKINIT client has no configured identity; giving up (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181488: Preauth module pkinit (14) (real) returned: 22/Invalid argument (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL. (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for myuser@SPLAT.acme.COM]. (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts. (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181489: Preauth module encrypted_timestamp (2) (real) returned: -1765328254/Cannot read password (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181490: Retrying AS request with master KDC (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181491: Getting initial credentials for myuser@SPLAT.acme.COM (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181493: Sending unauthenticated request (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [sss_child_krb5_trace_cb] (0x4000): [24328] 1551111583.181494: Sending request (176 bytes) to SPLAT.acme.COM (master) (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth. (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [k5c_send_data] (0x0200): Received error code 0 (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [pack_response_packet] (0x2000): response packet size: [12] (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [k5c_send_data] (0x4000): Response sent. (Mon Feb 25 16:19:43 2019) [[sssd[krb5_child[24328]]]] [main] (0x0400): krb5_child completed successfully ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x1000): Waiting for child [24328]. (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [24328] finished successfully. (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [parse_krb5_child_response] (0x1000): child response [0][11][0]. (Mon Feb 25 16:19:43 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: 1088 (Mon Feb 25 16:19:43 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' (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [set_server_common_status] (0x0100): Marking server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Mon Feb 25 16:19:43 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' (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_mod_ccname] (0x4000): Save ccname [KEYRING:persistent:611070070] for user [myuser@splat.acme.com]. (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fbf21c4d390 (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fbf21c4d450 (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Running timer event 0x7fbf21c4d390 "ltdb_callback" (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Destroying timer event 0x7fbf21c4d450 "ltdb_timeout" (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Ending timer event 0x7fbf21c4d390 "ltdb_callback" (Mon Feb 25 16:19:43 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. (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_done] (0x0100): Backend is marked offline, retry later! (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [check_wait_queue] (0x1000): Wait queue for user [myuser@splat.acme.com] is empty. (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x7fbf21c3c870] done. (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #160]: Request handler finished [0]: Success (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #160]: Receiving request data. (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #160]: Request removed. (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Mon Feb 25 16:19:43 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_reply] (0x1000): DP Request [PAM Preauth #160]: Sending result [9][splat.acme.com] ==> /var/log/sssd/sssd_pam.log <== (Mon Feb 25 16:19:43 2019) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7fa6e89723b0 (Mon Feb 25 16:19:43 2019) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7fa6e8962c70 (Mon Feb 25 16:19:43 2019) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Mon Feb 25 16:19:43 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [9 (Authentication service cannot retrieve authentication info)][splat.acme.com] (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fa6e8982ba0 (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fa6e8982370 (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7fa6e8982ba0 "ltdb_callback" (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7fa6e8982370 "ltdb_timeout" (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7fa6e8982ba0 "ltdb_callback" (Mon Feb 25 16:19:43 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [9]: Authentication service cannot retrieve authentication info. (Mon Feb 25 16:19:43 2019) [sssd[pam]] [pam_reply] (0x0020): Unknown PAM call [249]. (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fa6e8982370 (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fa6e89833d0 (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7fa6e8982370 "ltdb_callback" (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7fa6e89833d0 "ltdb_timeout" (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7fa6e8982370 "ltdb_callback" (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fa6e89833d0 (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fa6e89866a0 (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7fa6e89833d0 "ltdb_callback" (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7fa6e89866a0 "ltdb_timeout" (Mon Feb 25 16:19:43 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7fa6e89833d0 "ltdb_callback" (Mon Feb 25 16:19:43 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Mon Feb 25 16:19:43 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 37 ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Mon Feb 25 16:19:44 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_id_conn_data_expire_handler] (0x0080): connection is about to expire, releasing it (Mon Feb 25 16:19:44 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection (Mon Feb 25 16:19:44 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_handle_release] (0x2000): Trace: sh[0x7fbf21c3cdc0], connected[1], ops[(nil)], ldap[0x7fbf21c1d380], destructor_lock[0], release_memory[0] (Mon Feb 25 16:19:44 2019) [sssd[be[ipa.splat.acme.com]]] [remove_connection_callback] (0x4000): Successfully removed connection callback. ==> /var/log/sssd/sssd_pam.log <== (Mon Feb 25 16:19:46 2019) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [myuser@splat.acme.com] removed from PAM initgroup cache