I've seen similar situations in other threads, but searching for a solution hasn't proven fruitful so far; please point me in the right direction! I've configured an ipa server with a trusted AD domain and both lookups and authentication are working on the server (I can getent and id AD users, and can ssh to the server as an AD user.) On the client side, however, only lookups are working. I can getent and id AD users, but can't authenticate as one.
Here's a section of the sssd_cs.domain.dom.log from an authentication attempt. The obvious red flag is: (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain cs.domain.dom is Active (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain domain.dom is Inactive
But I'm unsure how to troubleshoot.
LOG: (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sbus_dispatch] (0x4000): dbus conn: 0x55911dd26920 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sbus_dispatch] (0x4000): Dispatching. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_pam_handler] (0x0100): Got request with the following data (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): domain: domain.dom (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): user: username@domain.dom (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): service: sshd (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): tty: ssh (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): ruser: (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): rhost: IP.ADDR (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): authtok type: 1 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): newauthtok type: 0 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): priv: 1 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): cli_pid: 1096 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): logon name: not set (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #4]: New request. Flags [0000]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain cs.domain.dom is Active (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain domain.dom is Inactive (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [username@domain.dom] is empty, running request [0x55911dd133f0] immediately. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain cs.domain.dom is Active (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain domain.dom is Inactive (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_setup] (0x4000): No mapping for: username@domain.dom (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd31600
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd316c0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd31600 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd316c0 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd31600 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd2da90
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd2db50
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd2da90 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd2db50 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd2da90 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [get_server_status] (0x1000): Status of server 'ipa.cs.domain.dom' is 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [get_port_status] (0x1000): Port status of port 0 for server 'ipa.cs.domain.dom' is 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [get_server_status] (0x1000): Status of server 'ipa.cs.domain.dom' is 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [be_resolve_server_process] (0x0200): Found address for server ipa.cs.domain.dom: [IP.ADDR] TTL 86400 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://ipa.cs.domain.dom' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_g504pM] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_g504pM] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain domain.dom is Inactive (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_auth_resolve_done] (0x2000): Subdomain domain.dom is inactive, will proceed offline (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [1097] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [child_handler_setup] (0x2000): Signal handler set up for pid [1097] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [write_pipe_handler] (0x0400): All data has been sent! (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [read_pipe_handler] (0x0400): EOF received, client finished (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [parse_krb5_child_response] (0x1000): child response [0][3][46]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: ../src/providers/krb5/krb5_auth.c: krb5_auth_done: 1093 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'ipa.cs.domain.dom' as 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [set_server_common_status] (0x0100): Marking server 'ipa.cs.domain.dom' as 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'ipa.cs.domain.dom' as 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_mod_ccname] (0x4000): Save ccname [FILE:/tmp/krb5cc_1326822197_QIfZhR] for user [username@domain.dom]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd60a00
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd12a30
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd60a00 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd12a30 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd60a00 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sysdb_set_entry_attr] (0x0200): Entry [name=username@domain.dom,cn=users,cn=domain.dom,cn=sysdb] has set [ts_cache] attrs. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd12af0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd12bb0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd12af0 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd12bb0 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd12af0 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd29c80
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd29d40
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd29c80 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd29d40 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd29c80 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd57ee0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd29ea0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd57ee0 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd29ea0 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd57ee0 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sysdb_cache_auth] (0x4000): Offline credentials expiration is [0] days. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [check_failed_login_attempts] (0x4000): Failed login attempts [0], allowed failed login attempts [0], failed login delay [5]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sysdb_cache_auth] (0x0100): Cached credentials not available. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): cancel ldb transaction (nesting: 0) (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_auth_cache_creds] (0x0020): Offline authentication failed (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [check_wait_queue] (0x1000): Wait queue for user [username@domain.dom] is empty. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x55911dd133f0] done. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #4]: Request handler finished [0]: Success (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #4]: Receiving request data. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #4]: Request removed. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_pam_reply] (0x1000): DP Request [PAM Authenticate #4]: Sending result [6][domain.dom] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [child_sig_handler] (0x1000): Waiting for child [1097]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [child_sig_handler] (0x0100): child [1097] finished successfully.
Thanks for any help!
On Thu, Jul 05, 2018 at 04:57:26PM -0000, Mike Conner via FreeIPA-users wrote:
I've seen similar situations in other threads, but searching for a solution hasn't proven fruitful so far; please point me in the right direction! I've configured an ipa server with a trusted AD domain and both lookups and authentication are working on the server (I can getent and id AD users, and can ssh to the server as an AD user.) On the client side, however, only lookups are working. I can getent and id AD users, but can't authenticate as one.
Here's a section of the sssd_cs.domain.dom.log from an authentication attempt. The obvious red flag is: (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain cs.domain.dom is Active (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain domain.dom is Inactive
But I'm unsure how to troubleshoot.
Can you send you sssd.conf and the version of SSSD you are using?
You should check in the logs before 'Thu Jul 5 11:31:44 2018' why the domain is offline. Since IPA client only need to access to AD domains for authentication I would expect that some earlier authentication attempts failed and cause the domain to switch to offline.
Typical reasons for failed authentication might be timeouts because the authentication needs too much time. If that's the case increasing krb5_auth_timeout might help, the default is 6s, see man sssd-krb5 for details.
Another typical reason is a failed Kerberos ticket validation. If that's the case you can disable the validation by setting 'krb5_validate = False' (see man sssd-krb5 for details as well). But please do this only temporary and try to figure out why the ticket validate failed. The libkrb5 trace messages in krb5_child.log should help here. Ticket validation help to increase the security especially in environments with trust between multiple domains.
Btw, general troubleshooting tips for SSSD can be found at https://docs.pagure.org/SSSD.sssd/users/troubleshooting.html
HTH
bye, Sumit
LOG: (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sbus_dispatch] (0x4000): dbus conn: 0x55911dd26920 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sbus_dispatch] (0x4000): Dispatching. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_pam_handler] (0x0100): Got request with the following data (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): domain: domain.dom (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): user: username@domain.dom (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): service: sshd (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): tty: ssh (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): ruser: (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): rhost: IP.ADDR (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): authtok type: 1 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): newauthtok type: 0 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): priv: 1 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): cli_pid: 1096 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [pam_print_data] (0x0100): logon name: not set (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #4]: New request. Flags [0000]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain cs.domain.dom is Active (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain domain.dom is Inactive (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [username@domain.dom] is empty, running request [0x55911dd133f0] immediately. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain cs.domain.dom is Active (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain domain.dom is Inactive (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_setup] (0x4000): No mapping for: username@domain.dom (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd31600
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd316c0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd31600 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd316c0 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd31600 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd2da90
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd2db50
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd2da90 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd2db50 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd2da90 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [get_server_status] (0x1000): Status of server 'ipa.cs.domain.dom' is 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [get_port_status] (0x1000): Port status of port 0 for server 'ipa.cs.domain.dom' is 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [get_server_status] (0x1000): Status of server 'ipa.cs.domain.dom' is 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [be_resolve_server_process] (0x0200): Found address for server ipa.cs.domain.dom: [IP.ADDR] TTL 86400 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://ipa.cs.domain.dom' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_g504pM] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_g504pM] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sss_domain_get_state] (0x1000): Domain domain.dom is Inactive (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_auth_resolve_done] (0x2000): Subdomain domain.dom is inactive, will proceed offline (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [1097] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [child_handler_setup] (0x2000): Signal handler set up for pid [1097] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [write_pipe_handler] (0x0400): All data has been sent! (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [read_pipe_handler] (0x0400): EOF received, client finished (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [parse_krb5_child_response] (0x1000): child response [0][3][46]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: ../src/providers/krb5/krb5_auth.c: krb5_auth_done: 1093 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'ipa.cs.domain.dom' as 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [set_server_common_status] (0x0100): Marking server 'ipa.cs.domain.dom' as 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'ipa.cs.domain.dom' as 'working' (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_mod_ccname] (0x4000): Save ccname [FILE:/tmp/krb5cc_1326822197_QIfZhR] for user [username@domain.dom]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd60a00
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd12a30
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd60a00 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd12a30 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd60a00 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sysdb_set_entry_attr] (0x0200): Entry [name=username@domain.dom,cn=users,cn=domain.dom,cn=sysdb] has set [ts_cache] attrs. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd12af0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd12bb0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd12af0 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd12bb0 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd12af0 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd29c80
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd29d40
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd29c80 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd29d40 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd29c80 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x55911dd57ee0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x55911dd29ea0
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Running timer event 0x55911dd57ee0 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Destroying timer event 0x55911dd29ea0 "ltdb_timeout"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): Ending timer event 0x55911dd57ee0 "ltdb_callback"
(Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sysdb_cache_auth] (0x4000): Offline credentials expiration is [0] days. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [check_failed_login_attempts] (0x4000): Failed login attempts [0], allowed failed login attempts [0], failed login delay [5]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [sysdb_cache_auth] (0x0100): Cached credentials not available. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [ldb] (0x4000): cancel ldb transaction (nesting: 0) (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_auth_cache_creds] (0x0020): Offline authentication failed (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [check_wait_queue] (0x1000): Wait queue for user [username@domain.dom] is empty. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x55911dd133f0] done. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #4]: Request handler finished [0]: Success (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #4]: Receiving request data. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #4]: Request removed. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [dp_pam_reply] (0x1000): DP Request [PAM Authenticate #4]: Sending result [6][domain.dom] (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [child_sig_handler] (0x1000): Waiting for child [1097]. (Thu Jul 5 11:31:44 2018) [sssd[be[cs.domain.dom]]] [child_sig_handler] (0x0100): child [1097] finished successfully.
Thanks for any help! _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/freeipa-users@lists.fedorahost...
This is now working after adding a stanza for the AD realm in /etc/krb5.conf file. Should that be necessary?
On Wed, Jul 11, 2018 at 03:56:22PM -0000, Mike Conner via FreeIPA-users wrote:
This is now working after adding a stanza for the AD realm in /etc/krb5.conf file. Should that be necessary?
Did you also add the KDCs for the AD realm?
I'm asking because by default, sssd on the client does not know which KDCs to authenticate against and just calls into libkrb5 which discovers the AD KDCs with DNS SRV calls. So maybe you added some DCs which are known to be reachable which avoids SSSD going offline because the authenticated otherwise times out?
So you're saying the client is probably not finding the AD KDC through DNS SRV calls? I think that I've tested all the DNS configs that are called for in the documentation. What could I do to test whether the AD realm's KDC is being discovered?
Here's what I've tried to see if the dns is correctly configured: [root@freeipaclient ~]# dig +short -t SRV _kerberos._tcp.dc._msdcs.cs.domain.dom 0 100 88 ipa.cs.domain.dom. [root@freeipaclient ~]# dig +short -t SRV _kerberos._tcp.dc._msdcs.domain.dom 0 100 88 kdc1.domain.dom. 0 100 88 kdc2.domain.dom.
On Wed, Jul 11, 2018 at 08:30:16PM -0000, Mike Conner via FreeIPA-users wrote:
So you're saying the client is probably not finding the AD KDC through DNS SRV calls?
Not necessarily not finding, but perhaps the AD KDCs the client discovers are slow to respond?
What exactly were the changes to krb5.conf that helped you?
btw previously in the log snippet you sent, the AD domain was already marked as Inactive, so I was mostly guessing as per what caused the AD domain to flip to the Inactive state in the first place -- although on the client, an authentication timeout is the most likely issue.
I think that I've tested all the DNS configs that are called for in the documentation. What could I do to test whether the AD realm's KDC is being discovered?
Here's what I've tried to see if the dns is correctly configured: [root@freeipaclient ~]# dig +short -t SRV _kerberos._tcp.dc._msdcs.cs.domain.dom 0 100 88 ipa.cs.domain.dom. [root@freeipaclient ~]# dig +short -t SRV _kerberos._tcp.dc._msdcs.domain.dom 0 100 88 kdc1.domain.dom. 0 100 88 kdc2.domain.dom. _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/freeipa-users@lists.fedorahost...
To the /etc/krb5.conf file on the client, I changed from this:
[realms] CS.GRINNELL.EDU = { kdc = ipa.cs.grinnell.edu:88 master_kdc = ipa.cs.grinnell.edu:88 admin_server = ipa.cs.grinnell.edu:749 kpasswd_server = ipa.cs.grinnell.edu:464 default_domain = cs.grinnell.edu pkinit_anchors = FILE:/var/lib/ipa-client/pki/kdc-ca-bundle.pem pkinit_pool = FILE:/var/lib/ipa-client/pki/ca-bundle.pem
}
To this: [realms] CS.DOMAIN.DOM = { kdc = ipa.cs.domain.dom:88 master_kdc = ipa.cs.domain.dom:88 admin_server = ipa.cs.domain.dom:749 kpasswd_server = ipa.cs.domain.dom:464 default_domain = cs.domain.dom pkinit_anchors = FILE:/var/lib/ipa-client/pki/kdc-ca-bundle.pem pkinit_pool = FILE:/var/lib/ipa-client/pki/ca-bundle.pem
} DOMAIN.DOM = { kdc = kdc1.domain.dom admin_server = kdc1.domain.dom }
On Wed, Jul 11, 2018 at 09:16:19PM -0000, Mike Conner via FreeIPA-users wrote:
To the /etc/krb5.conf file on the client, I changed from this:
[realms] CS.GRINNELL.EDU = { kdc = ipa.cs.grinnell.edu:88 master_kdc = ipa.cs.grinnell.edu:88 admin_server = ipa.cs.grinnell.edu:749 kpasswd_server = ipa.cs.grinnell.edu:464 default_domain = cs.grinnell.edu pkinit_anchors = FILE:/var/lib/ipa-client/pki/kdc-ca-bundle.pem pkinit_pool = FILE:/var/lib/ipa-client/pki/ca-bundle.pem
}
To this: [realms] CS.DOMAIN.DOM = { kdc = ipa.cs.domain.dom:88 master_kdc = ipa.cs.domain.dom:88 admin_server = ipa.cs.domain.dom:749 kpasswd_server = ipa.cs.domain.dom:464 default_domain = cs.domain.dom pkinit_anchors = FILE:/var/lib/ipa-client/pki/kdc-ca-bundle.pem pkinit_pool = FILE:/var/lib/ipa-client/pki/ca-bundle.pem
} DOMAIN.DOM = { kdc = kdc1.domain.dom admin_server = kdc1.domain.dom }
OK and just to confirm the theory, does running kinit for a user from DOMAIN.COM finish faster than when the DOMAIN.COM entry is commented out?
On ke, 11 heinä 2018, Mike Conner via FreeIPA-users wrote:
So you're saying the client is probably not finding the AD KDC through DNS SRV calls? I think that I've tested all the DNS configs that are called for in the documentation. What could I do to test whether the AD realm's KDC is being discovered?
Here's what I've tried to see if the dns is correctly configured: [root@freeipaclient ~]# dig +short -t SRV _kerberos._tcp.dc._msdcs.cs.domain.dom 0 100 88 ipa.cs.domain.dom. [root@freeipaclient ~]# dig +short -t SRV _kerberos._tcp.dc._msdcs.domain.dom 0 100 88 kdc1.domain.dom. 0 100 88 kdc2.domain.dom.
What about _kerberos._tcp.domain.com? This is what libkrb5 will be checking if DNS SRV resolution is done, not _msdcs entries which only checked by Windows.
Also seems to be set:
freeipaclient$ dig +short -t SRV _kerberos._udp.cs.domain.dom 0 100 88 ipa.cs.domain.com. freeipaclients$ dig +short -t SRV _kerberos._udp.domain.com 0 100 88 kdc1.domain.com. 0 100 88 kdc2.domain.com.
freeipa-users@lists.fedorahosted.org
-
Alexander Bokovoy -
Jakub Hrozek -
Mike Conner -
Sumit Bose