Hi folks,
Summary: Replica w/ Trust agents can't resolve AD users. Not sure which
debug_level=log error I should focus on. Would appreciate extra eyeballs
on this ..
Have a brand new replica (v4.4) running and after installing the AD
trust agents I still can't recognize users who exist in the trusted AD
domains.
Running at debug_level=10 for logging as usual however deleting the logs
and doing a fresh reboot followed by trying to resolve a users still
make 4000+ log entries so rather than include it here I've posted a
sanitized sssd_domain.log file here:
http://chrisdag.me/sssd_companyidm.org.log.txt
There are two sets of messages in that massive log file that concern me
but I don't know enough yet to figure out which one to focus on.
The first set of messages show what appears to be a fatal error in
connecting to the local ldap:// server on the replica.
However -
- dirsirv logs look fine
- the various ldapsearch commands in the Free-IPA troublehooting page
work to query both the replica and the remote master
- 'ipactl status' shows directory services running
- no firewall blocking and AWS VPC flowLogs show no REJECT traffic
whatsoever for the NIC on the replica
But I still see this scary section in the logs right after startup:
This is about line #577 in the log where I see some scary LDAP related
errors:
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [new_subdomain]
(0x0400): Creating [shanetest.org] as subdomain of [companyidm.org]!
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [new_subdomain]
(0x0400): Creating [companyaws.org] as subdomain of [companyidm.org]!
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [new_subdomain]
(0x0400): Creating [COMPANY.ORG] as subdomain of [companyidm.org]!
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [new_subdomain]
(0x0400): Creating [child2.shanetest.org] as subdomain of
[companyidm.org]!
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [new_subdomain]
(0x0400): Creating [EAME.COMPANY.ORG] as subdomain of [companyidm.org]!
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [new_subdomain]
(0x0400): Creating [APAC.COMPANY.ORG] as subdomain of [companyidm.org]!
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [new_subdomain]
(0x0400): Creating [LATAM.COMPANY.ORG] as subdomain of [companyidm.org]!
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [new_subdomain]
(0x0400): Creating [NAFTA.COMPANY.ORG] as subdomain of [companyidm.org]!
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[link_forest_roots] (0x2000): [companyidm.org] is a forest root
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[link_forest_roots] (0x2000): [shanetest.org] is a forest root
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[link_forest_roots] (0x2000): [shanetest.org] is a forest root of
[child2.shanetest.org]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[link_forest_roots] (0x2000): [companyaws.org] is a forest root
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[link_forest_roots] (0x2000): [COMPANY.ORG] is a forest root
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[link_forest_roots] (0x2000): [COMPANY.ORG] is a forest root of
[EAME.COMPANY.ORG]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[link_forest_roots] (0x2000): [COMPANY.ORG] is a forest root of
[APAC.COMPANY.ORG]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[link_forest_roots] (0x2000): [COMPANY.ORG] is a forest root of
[LATAM.COMPANY.ORG]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[link_forest_roots] (0x2000): [COMPANY.ORG] is a forest root of
[NAFTA.COMPANY.ORG]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sss_write_domain_mappings] (0x0200): Mapping file for domain
[companyidm.org] is
[/var/lib/sss/pubconf/krb5.include.d/domain_realm_companyidm_org]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [become_user]
(0x0200): Trying to become user [0][0].
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [become_user]
(0x0200): Already user [0].
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [main] (0x0400):
Backend provider (companyidm.org) started!
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[ipa_server_trusted_dom_setup_send] (0x1000): Trust direction of
subdom shanetest.org from forest shanetest.org is: one-way inbound:
local domain trusts the remote domain
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[ipa_server_trusted_dom_setup_1way] (0x0400): Will re-fetch keytab for
shanetest.org
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[ipa_getkeytab_send] (0x0400): Retrieving keytab for
[email protected] from usaeilidmp002.companyidm.org into
/var/lib/sss/keytabs/shanetest.org.keytabRw7Iai using ccache
/var/lib/sss/db/ccache_companyidm.ORG
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[child_handler_setup] (0x2000): Setting up signal handler up for pid [649]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[child_handler_setup] (0x2000): Signal handler set up for pid [649]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [sbus_dispatch]
(0x4000): dbus conn: 0x7f4f63ae1600
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [sbus_dispatch]
(0x4000): dbus conn: 0x7f4f63ae1600
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[be_ptask_execute] (0x0400): Task [Subdomains Refresh]: executing
task, timeout 14400 seconds
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sdap_id_op_connect_step] (0x4000): beginning to connect
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[get_server_status] (0x1000): Status of server
'usaeilidmp002.companyidm.org' is 'name not resolved'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[get_port_status] (0x1000): Port status of port 0 for server
'usaeilidmp002.companyidm.org' is 'neutral'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to
6 seconds
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[get_server_status] (0x1000): Status of server
'usaeilidmp002.companyidm.org' is 'name not resolved'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[resolv_is_address] (0x4000): [usaeilidmp002.companyidm.org] does not
look like an IP address
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[resolv_gethostbyname_step] (0x2000): Querying files
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record
of 'usaeilidmp002.companyidm.org' in files
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[set_server_common_status] (0x0100): Marking server
'usaeilidmp002.companyidm.org' as 'resolving name'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[set_server_common_status] (0x0100): Marking server
'usaeilidmp002.companyidm.org' as 'name resolved'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[be_resolve_server_process] (0x1000): Saving the first resolved server
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[be_resolve_server_process] (0x0200): Found address for server
usaeilidmp002.companyidm.org: [10.127.66.11] TTL 7200
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[ipa_resolve_callback] (0x0400): Constructed uri
'ldap://usaeilidmp002.companyidm.org'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[unique_filename_destructor] (0x2000): Unlinking
[/var/lib/sss/pubconf/.krb5info_dummy_k6Y0iO]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]] [unlink_dbg]
(0x2000): File already removed:
[/var/lib/sss/pubconf/.krb5info_dummy_k6Y0iO]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sssd_async_socket_init_send] (0x4000): Using file descriptor [21] for
the connection.
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sssd_async_connect_send] (0x0020): connect failed [101][Network is
unreachable].
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for
connecting
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sssd_async_socket_init_done] (0x0020): sdap_async_sys_connect request
failed: [101]: Network is unreachable.
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sssd_async_socket_state_destructor] (0x0400): closing socket [21]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sss_ldap_init_sys_connect_done] (0x0020): sssd_async_socket_init
request failed: [101]: Network is unreachable.
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sdap_sys_connect_done] (0x0020): sdap_async_connect_call request
failed: [101]: Network is unreachable.
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sdap_handle_release] (0x2000): Trace: sh[0x7f4f63b0a5f0],
connected[0], ops[(nil)], ldap[(nil)], destructor_lock[0],
release_memory[0]
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[_be_fo_set_port_status] (0x8000): Setting status: PORT_NOT_WORKING.
Called from: src/providers/ldap/sdap_async_connection.c:
sdap_cli_connect_done: 1572
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[fo_set_port_status] (0x0100): Marking port 0 of server
'usaeilidmp002.companyidm.org' as 'not working'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[fo_set_port_status] (0x0400): Marking port 0 of duplicate server
'usaeilidmp002.companyidm.org' as 'not working'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[get_server_status] (0x1000): Status of server
'usaeilidmp002.companyidm.org' is 'name resolved'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[get_port_status] (0x1000): Port status of port 0 for server
'usaeilidmp002.companyidm.org' is 'not working'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[fo_resolve_service_send] (0x0020): No available servers for service 'IPA'
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[be_resolve_server_done] (0x1000): Server resolution failed: [5]:
Input/output error
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[sdap_id_op_connect_done] (0x0020): Failed to connect, going offline
(5 [Input/output error])
(Thu Dec 22 15:43:11 2016) [sssd[be[companyidm.org]]]
[be_mark_offline] (0x2000): Going offline
The second scary thing I see relates to some "Invalid Argument" errors
related to ipa_get_*_acct stuff that I see when I try to resolve my AD
user account:
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]] [sbus_dispatch]
(0x4000): dbus conn: 0x7f4f63b1d290
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]] [sbus_dispatch]
(0x4000): Dispatching.
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sbus_message_handler] (0x2000): Received SBUS method
org.freedesktop.sssd.dataprovider.getAccountInfo on path
/org/freedesktop/sssd/dataprovider
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[dp_get_account_info_handler] (0x0200): Got request for
[0x1][BE_REQ_USER][1][[email protected]]
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]] [dp_attach_req]
(0x0400): DP Request [Account #43]: New request. Flags [0x0001].
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]] [dp_attach_req]
(0x0400): Number of active DP request: 1
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_id_op_connect_step] (0x4000): reusing cached connection
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_id_op_connect_step] (0x4000): reusing cached connection
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[ipa_get_ad_override_connect_done] (0x4000): Searching for overrides
in view [Default Trust View] with filter
[(&(objectClass=ipaUserOverride)(uid=t859531))].
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_print_server] (0x2000): Searching 10.127.66.11:389
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(objectClass=ipaUserOverride)(uid=t859531))][cn=Default Trust
View,cn=views,cn=accounts,dc=companyidm,dc=org].
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 14
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]] [sdap_op_add]
(0x2000): New operation 14 timeout 6
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_process_result] (0x2000): Trace: sh[0x7f4f63ace530],
connected[1], ops[0x7f4f63ada1c0], ldap[0x7f4f63b28720]
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no
errmsg set
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_op_destructor] (0x2000): Operation 14 finished
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[ipa_get_ad_override_done] (0x4000): No override found with filter
[(&(objectClass=ipaUserOverride)(uid=t859531))].
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_id_op_destroy] (0x4000): releasing operation connection
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[be_mark_dom_offline] (0x1000): Marking subdomain NAFTA.COMPANY.ORG
offline
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[be_mark_subdom_offline] (0x1000): Marking subdomain NAFTA.COMPANY.ORG
as inactive
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed:
[22]: Invalid argument.
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed:
[22]: Invalid argument.
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_id_op_destroy] (0x4000): releasing operation connection
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]] [dp_req_done]
(0x0400): DP Request [Account #43]: Request handler finished [0]: Success
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]] [_dp_req_recv]
(0x0400): DP Request [Account #43]: Receiving request data.
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[dp_req_reply_list_success] (0x0400): DP Request [Account #43]:
Finished. Success.
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[dp_req_reply_std] (0x1000): DP Request [Account #43]: Returning
[Internal Error]: 3,22,Invalid argument
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[dp_table_value_destructor] (0x0400): Removing
[0:1:0x0001:1:1::NAFTA.COMPANY.ORG:[email protected]]
from reply table
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[dp_req_destructor] (0x0400): DP Request [Account #43]: Request removed.
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[dp_req_destructor] (0x0400): Number of active DP request: 0
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_process_result] (0x2000): Trace: sh[0x7f4f63ace530],
connected[1], ops[(nil)], ldap[0x7f4f63b28720]
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]]
[sdap_process_result] (0x2000): Trace: end of ldap_result list
(Thu Dec 22 15:49:49 2016) [sssd[be[companyidm.org]]] [sbus_dispatch]
(0x4000): dbus conn: 0x7f4f63b1d290
Regards,
Chris
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
