11:57 a.m.
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!