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(a)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(a)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(a)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(a)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(a)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(a)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!