[Freeipa-users] Debugging failed password checks (SSH) for AD users at the other end of 1-way trusts
List dedicated to discussions about use, configuration and deployment of the IPA server.
freeipa-users at redhat.com
Tue Dec 6 17:45:18 UTC 2016
####
This is a new thread related to one I started today about upgrading
FreeIPA software before continuing troubleshooting work ...
New post here so I don't pollute the other thread.
####
Looking for additional eyeballs or tips on this ongoing problem. The
short summary
is we can't check passwords for AD users.
SSSD is running in debug-10 mode and we have tons of logs
I've got 2 interesting things to trace down, would be interested in
feedback on
which may be best to concentrate on ...
1. In the SAMBA logs there are very clear and interesting
"message=Cannot contact any KDC for realm 'COMPANY-IDM.ORG'"
which seems very straightforward and interesting
2. However the SSSD logs contain more worrisome messages about TGT
ticket errors
Should I concentrate on the samba logs that talk about being unable to
find the KDC?
That seems more straightforward at the moment.
Thanks!
-Chris
Basic IDM Setup
---------------
1. We run COMPANY-IDM.ORG as our IPA server and realm within AWS
2. We operate hosts as company-aws.org (basically IPA clients have
different DNS domain) in AWS
3. COMPANY-IDM.ORG has 1-way trusts to many remote AD Forests at remote
corporate sites including COMPANY.ORG
Situation
----------
1. Lots of 1-way trusts to COMPANY.ORG via our COMPANY-IDM.ORG IPA server
2. We can enumerate AD users via "id <username>" command
3. Groups, uid etc. all resolvable for AD users
4. As root we can "sudo - user at nafta.company.org" and it works fine
but ...
5. Anything involving password checking fails (SSH and "sudo - user" as
non-root)
IPA Server /etc/krb5.conf:
------------------------
includedir /var/lib/sss/pubconf/krb5.include.d/
[logging]
default = FILE:/var/log/krb5libs.log
kdc = FILE:/var/log/krb5kdc.log
admin_server = FILE:/var/log/kadmind.log
[libdefaults]
default_realm = COMPANY-IDM.ORG
dns_lookup_realm = true
dns_lookup_kdc = true
rdns = false
ticket_lifetime = 24h
forwardable = yes
udp_preference_limit = 0
default_ccache_name = KEYRING:persistent:%{uid}
[realms]
COMPANY-IDM.ORG = {
kdc = usaeilidmp001.company-idm.org:88
master_kdc = usaeilidmp001.company-idm.org:88
admin_server = usaeilidmp001.company-idm.org:749
default_domain = company-idm.org
pkinit_anchors = FILE:/etc/ipa/ca.crt
}
[dbmodules]
COMPANY-IDM.ORG = {
db_library = ipadb.so
}
IPA server /etc/sssd/sssd.conf
------------------------------
[domain/company-idm.org]
krb5_validate = false
debug_level = 10
cache_credentials = True
krb5_store_password_if_offline = True
ipa_domain = company-idm.org
id_provider = ipa
auth_provider = ipa
access_provider = ipa
ipa_hostname = usaeilidmp001.company-idm.org
chpass_provider = ipa
ipa_server = usaeilidmp001.company-idm.org
ipa_server_mode = True
ldap_tls_cacert = /etc/ipa/ca.crt
[sssd]
services = nss, sudo, pam, ssh
config_file_version = 2
domains = company-idm.org
[nss]
memcache_timeout = 600
homedir_substring = /home
[pam]
debug_level = 10
[sudo]
[autofs]
[ssh]
debug_level = 10
[pac]
[ifp]
/var/log/sssd/krb5_child.log
-------------
Tue Dec 6 15:36:47 2016) [[sssd[krb5_child[4004]]]] [tgt_req_child]
(0x1000): Attempting to get a TGT
(Tue Dec 6 15:36:47 2016) [[sssd[krb5_child[4004]]]] [get_and_save_tgt]
(0x0400): Attempting kinit for realm [COMPANY.ORG]
(Tue Dec 6 15:36:47 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038607.821494: Getting
initial credentials for user at COMPANY.ORG
(Tue Dec 6 15:36:47 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038607.823470: Sending
request (169 bytes) to COMPANY.ORG
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038608.3566: Resolving
hostname friawadsgc16.company.org.
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038608.93116: Sending
initial UDP request to dgram 15.141.1.63:88
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038608.179995: Received
answer (118 bytes) from dgram 15.141.1.63:88
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038608.269806: Response
was not from master KDC
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038608.269869: Received
error from KDC: -1765328316/Realm not local to KDC
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038608.269902: Retrying
AS request with master KDC
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038608.269911: Getting
initial credentials for user at COMPANY.ORG
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]]
[sss_child_krb5_trace_cb] (0x4000): [4004] 1481038608.269956: Sending
request (169 bytes) to COMPANY.ORG (master)
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]] [get_and_save_tgt]
(0x0400): krb5_get_init_creds_password returned [-1765328316} during
pre-auth.
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]] [k5c_send_data]
(0x0200): Received error code 0
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]]
[pack_response_packet] (0x2000): response packet size: [4]
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]] [k5c_send_data]
(0x4000): Response sent.
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4004]]]] [main] (0x0400):
krb5_child completed successfully
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [main] (0x0400):
krb5_child started.
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [unpack_buffer]
(0x1000): total buffer size: [158]
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [unpack_buffer]
(0x0100): cmd [241] uid [1843770609] gid [1843770609] validate [false]
enterprise principal [false] offline [true] UPN [user at COMPANY.ORG]
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [unpack_buffer]
(0x0100): ccname: [KEYRING:persistent:1843770609] old_ccname:
[KEYRING:persistent:1843770609] keytab: [/etc/krb5.keytab]
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [switch_creds]
(0x0200): Switch user to [1843770609][1843770609].
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]]
[sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired.
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [switch_creds]
(0x0200): Switch user to [0][0].
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]]
[k5c_check_old_ccache] (0x4000): Ccache_file is
[KEYRING:persistent:1843770609] and is not active and TGT is valid.
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [become_user]
(0x0200): Trying to become user [1843770609][1843770609].
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [main] (0x2000):
Running as [1843770609][1843770609].
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [become_user]
(0x0200): Trying to become user [1843770609][1843770609].
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [become_user]
(0x0200): Already user [1843770609].
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [k5c_setup]
(0x2000): Running as [1843770609][1843770609].
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]]
[set_lifetime_options] (0x0100): Cannot read
[SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]]
[set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from
environment.
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [main] (0x0400):
Will perform offline auth
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]]
[create_empty_ccache] (0x1000): Existing ccache still valid, reusing
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [k5c_send_data]
(0x0200): Received error code 0
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]]
[pack_response_packet] (0x2000): response packet size: [53]
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [k5c_send_data]
(0x4000): Response sent.
(Tue Dec 6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [main] (0x0400):
krb5_child completed successfully
/etc/samba/smb.conf
-------------------
### Added by IPA Installer ###
[global]
debug pid = yes
config backend = registry
/var/log/samba/smbd.log
------------------------
2016/12/06 14:56:42, 0] ../source3/smbd/server.c:1241(main)
smbd version 4.2.10 started.
Copyright Andrew Tridgell and the Samba Team 1992-2014
[2016/12/06 14:56:42.272249, 1] ipa_sam.c:4686(pdb_init_ipasam)
pdb_init_ipasam: support for pdb_enum_upn_suffixes enabled for domain
company-idm.org
[2016/12/06 14:56:43.364455, 1]
../source3/rpc_server/epmd.c:150(start_epmd)
Forking Endpoint Mapper Daemon
[2016/12/06 14:56:43.366678, 0]
../lib/util/become_daemon.c:124(daemon_ready)
STATUS=daemon 'smbd' finished starting up and ready to serve connections
[2016/12/06 14:56:43.366722, 1]
../source3/rpc_server/lsasd.c:837(start_lsasd)
Forking LSA Service Daemon
[2016/12/06 15:08:28, 0] ../source3/smbd/server.c:1241(main)
smbd version 4.2.10 started.
Copyright Andrew Tridgell and the Samba Team 1992-2014
[2016/12/06 15:09:11.688374, 0] ipa_sam.c:4208(bind_callback_cleanup)
kerberos error: code=-1765328228, message=Cannot contact any KDC for
realm 'COMPANY-IDM.ORG'
[2016/12/06 15:09:11.688513, 0]
../source3/lib/smbldap.c:998(smbldap_connect_system)
failed to bind to server
ldapi://%2fvar%2frun%2fslapd-COMPANY-IDM-ORG.socket with dn="[Anonymous
bind]" Error: Local error
(unknown)
[2016/12/06 15:09:11.688639, 1]
../source3/lib/smbldap.c:1206(get_cached_ldap_connect)
Connection to LDAP server failed for the 1 try!
Another /var/log/samba log:
---------------------------
kerberos error: code=-1765328228, message=Cannot contact any KDC for
realm 'COMPANY-IDM.ORG'
[2016/12/06 15:32:00.850742, 1]
../source3/lib/smbldap.c:1206(get_cached_ldap_connect)
Connection to LDAP server failed for the 14 try!
[2016/12/06 15:32:01.851630, 0] ipa_sam.c:4208(bind_callback_cleanup)
kerberos error: code=-1765328228, message=Cannot contact any KDC for
realm 'COMPANY-IDM.ORG'
[2016/12/06 15:32:01.851707, 1]
../source3/lib/smbldap.c:1206(get_cached_ldap_connect)
Connection to LDAP server failed for the 15 try!
[2016/12/06 15:32:02.852728, 0] ipa_sam.c:4208(bind_callback_cleanup)
kerberos error: code=-1765328228, message=Cannot contact any KDC for
realm 'COMPANY-IDM.ORG'
[2016/12/06 15:32:02.852797, 1]
../source3/lib/smbldap.c:1206(get_cached_ldap_connect)
Connection to LDAP server failed for the 16 try!
sssd_pam.log
------------
Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100): logon
name: user at nafta.company.org
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [sss_ncache_check_str] (0x2000):
Checking negative cache for [NCE/USER/NAFTA.COMPANY.ORG/user]
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_initgr_check_timeout]
(0x2000): User [user at nafta.company.org] found in PAM cache.
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_check_user_search] (0x0100):
Requesting info for [user at NAFTA.COMPANY.ORG]
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x7ff54d25f1e0
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x7ff54d261310
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [ldb] (0x4000): Running timer
event 0x7ff54d25f1e0 "ltdb_callback"
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [ldb] (0x4000): Destroying timer
event 0x7ff54d261310 "ltdb_timeout"
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [ldb] (0x4000): Ending timer
event 0x7ff54d25f1e0 "ltdb_callback"
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_check_user_search] (0x0400):
Returning info for user [user at NAFTA.COMPANY.ORG]
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pd_set_primary_name] (0x0400):
User's primary name is user at NAFTA.COMPANY.ORG
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_dp_send_req] (0x0100):
Sending request with the following data:
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100):
command: PAM_AUTHENTICATE
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100):
domain: NAFTA.COMPANY.ORG
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100): user:
user at NAFTA.COMPANY.ORG
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100):
service: sshd
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser:
not set
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost:
localhost
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100):
authtok type: 1
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100):
newauthtok type: 0
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100):
cli_pid: 4001
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_print_data] (0x0100): logon
name: user at nafta.company.org
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [sbus_add_timeout] (0x2000):
0x7ff54d262940
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_dom_forwarder] (0x0100):
pam_dp_send_req returned 0
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [sbus_remove_timeout] (0x2000):
0x7ff54d262940
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus
conn: 0x7ff54d2590f0
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [sbus_dispatch] (0x4000):
Dispatching.
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_dp_process_reply] (0x0200):
received: [6 (Permission denied)][NAFTA.COMPANY.ORG]
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_reply] (0x0200): pam_reply
called with result [6]: Permission denied.
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_reply] (0x0200): blen: 84
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle
timer re-set for client [0x7ff54d25e620][19]
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [pam_initgr_cache_remove]
(0x2000): [user at nafta.company.org] removed from PAM initgroup cache
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle
timer re-set for client [0x7ff54d25e620][19]
(Tue Dec 6 15:36:52 2016) [sssd[pam]] [client_recv] (0x0200): Client
disconnected!
More information about the Freeipa-users
mailing list