[Freeipa-users] replica running trust-agents can't resolve AD users - which of these sssd errors should I be focusing on?
Chris Dagdigian
dag at sonsorol.org
Thu Dec 22 16:27:01 UTC 2016
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=t859531 at 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=t859531 at 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
More information about the Freeipa-users
mailing list