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(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!
> _______________________________________________
> FreeIPA-users mailing list -- freeipa-users(a)lists.fedorahosted.org
> To unsubscribe send an email to freeipa-users-leave(a)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.fedorah...