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 companyidm$@SHANETEST.ORG 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][name=t859...@nafta.company.org] (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:name=t859...@nafta.company.org] 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

Reply via email to