Bug 712434

Summary:	c-ares falls back to IPv4 when IPv6 doesn't exist.
Product:	Red Hat Enterprise Linux 5	Reporter:	Kaushik Banerjee <kbanerje>
Component:	c-ares	Assignee:	Jakub Hrozek <jhrozek>
Status:	CLOSED WONTFIX	QA Contact:
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	5.7	CC:	dpal, grajaiya, jgalipea, sgallagh
Target Milestone:	rc
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:
Clones:	730695 (view as bug list)		Environment:
Last Closed:	2013-11-06 15:47:54 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Bug Depends On:
Bug Blocks:	730695

Description Kaushik Banerjee 2011-06-10 15:38:01 UTC

Description of problem:
c-ares falls back to IPv4 if IPv6 fails.
As tested in sssd, "lookup_family_order = ipv6_only" is able to lookup ipv4 address.

Version-Release number of selected component (if applicable):
c-ares-1.6.0-5.el5
sssd-1.5.1-36.el5

How reproducible:
Always

Steps to Reproduce:
1. Configure sssd as shown in the Additional Info section.
2. Confiure DNS to lookup only A record for pluto.sssdad.com(I commented out the AAAA record and restarted named).
pluto           IN A 10.65.201.48
;pluto          IN AAAA fe80::2063:ced1:c0f8:506c

3. Restart sssd or enumerate a user.
  
Actual results:
Even with "lookup_family_order = ipv6_only", A record is being lookup up.

<snip>

(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sssm_ldap_id_init] (7): Service name for discovery set to ldap
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [fo_new_service] (3): Creating new service 'LDAP'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_service_init] (6): Added URI ldap://pluto.sssdad.com
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [fo_add_server] (3): Adding new server 'pluto.sssdad.com', to service 'LDAP'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0xc1f7a40

(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0xc1f7ba0

(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [ldb] (9): tevent: Destroying timer event 0xc1f7ba0 "ltdb_timeout"

(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [ldb] (9): tevent: Ending timer event 0xc1f7a40 "ltdb_callback"

(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [ldap_id_enumerate_set_timer] (6): Scheduling next enumeration at 1307718682.12009
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [be_process_init] (9): ID backend target successfully loaded from provider [ldap].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [load_backend_module] (5): no module name found in confdb, using [ldap].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [load_backend_module] (7): Backend [ldap] already loaded.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sssm_ldap_id_init] (8): Re-using sdap_id_ctx for this provider
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [be_process_init] (9): AUTH backend target successfully loaded from provider [ldap].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [load_backend_module] (5): no module name found in confdb, using [permit].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [be_process_init] (9): ACCESS backend target successfully loaded from provider [permit].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [load_backend_module] (5): no module name found in confdb, using [ldap].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [load_backend_module] (7): Backend [ldap] already loaded.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sssm_ldap_id_init] (8): Re-using sdap_id_ctx for this provider
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sssm_ldap_chpass_init] (9): ldap_chpass_uri and ldap_chpass_dns_service_name not set, using ldap_uri.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [be_process_init] (9): CHPASS backend target successfully loaded from provider [ldap].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [main] (1): Backend provider (ADtest) started!
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): dbus conn: C1F12C0
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): dbus conn: C1F12C0
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_id_op_connect_step] (9): beginning to connect
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [get_server_status] (7): Status of server 'pluto.sssdad.com' is 'name not resolved'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [get_server_status] (4): Hostname resolution expired, reseting the server status of 'pluto.sssdad.com'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [set_server_common_status] (4): Marking server 'pluto.sssdad.com' as 'name not resolved'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [get_port_status] (7): Port status of port 389 for server 'pluto.sssdad.com' is 'neutral'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [get_server_status] (7): Status of server 'pluto.sssdad.com' is 'name not resolved'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [resolv_gethostbyname_send] (4): Trying to resolve AAAA record of 'pluto.sssdad.com'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [schedule_timeout_watcher] (9): Scheduling DNS timeout watcher
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [set_server_common_status] (4): Marking server 'pluto.sssdad.com' as 'resolving name'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1f1910/0xc1dad20 (20), R/- (disabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1f1910/0xc1f11e0 (20), -/W (enabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1f1910/0xc1dad20 (20), R/- (enabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1f1910/0xc1f11e0 (20), -/W (disabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_remove_timeout] (8): 0xc1f1120
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): dbus conn: C1F12C0
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): Dispatching.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [id_callback] (4): Got id ack and version (1) from Monitor
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_server_init_new_connection] (5): Entering.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_server_init_new_connection] (5): Adding connection 0xc1f9d10.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_init_connection] (5): Adding connection C1F9D10
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_add_watch] (8): 0xc1fa5d0/0xc1f1c90 (23), -/W (disabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fa5d0/0xc1f6590 (23), R/- (enabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_server_init_new_connection] (5): Got a connection
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [be_client_init] (4): Set-up Backend ID timeout [0xc1fa840]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): dbus conn: C1F9D10
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_server_init_new_connection] (5): Entering.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_server_init_new_connection] (5): Adding connection 0xc1fadb0.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_init_connection] (5): Adding connection C1FADB0
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_add_watch] (8): 0xc1fb350/0xc1fa6c0 (24), -/W (disabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fb350/0xc1fa710 (24), R/- (enabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_server_init_new_connection] (5): Got a connection
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [be_client_init] (4): Set-up Backend ID timeout [0xc1fb5c0]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): dbus conn: C1FADB0
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fa5d0/0xc1f6590 (23), R/- (disabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fa5d0/0xc1f1c90 (23), -/W (enabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fb350/0xc1fa710 (24), R/- (disabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fb350/0xc1fa6c0 (24), -/W (enabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fa5d0/0xc1f6590 (23), R/- (enabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fa5d0/0xc1f1c90 (23), -/W (disabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fb350/0xc1fa710 (24), R/- (enabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_toggle_watch] (8): 0xc1fb350/0xc1fa6c0 (24), -/W (disabled)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [unschedule_timeout_watcher] (9): Unscheduling DNS timeout watcher
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [set_server_common_status] (4): Marking server 'pluto.sssdad.com' as 'name resolved'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [be_resolve_server_done] (4): Found address for server pluto.sssdad.com: [10.65.201.48]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_uri_callback] (6): Constructed uri 'ldap://pluto.sssdad.com'
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_rootdse_send] (9): Getting rootdse
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(objectclass=*)][].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [*]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [altServer]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [namingContexts]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedControl]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedExtension]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedFeatures]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedLDAPVersion]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedSASLMechanisms]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [defaultNamingContext]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [lastUSN]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (7): Requesting attrs: [highestCommittedUSN]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_ldap_connect_callback_add] (9): New LDAP connection to [ldap://pluto.sssdad.com:389] with fd [22].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_send] (8): ldap_search_ext called, msgid = 1
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): dbus conn: C1F9D10
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): Dispatching.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_message_handler] (9): Received SBUS method [RegisterService]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [client_registration] (4): Cancel DP ID timeout [0xc1fa840]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [client_registration] (4): Added Frontend client [NSS]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): dbus conn: C1FADB0
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_dispatch] (9): Dispatching.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sbus_message_handler] (9): Received SBUS method [RegisterService]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [client_registration] (4): Cancel DP ID timeout [0xc1fb5c0]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [client_registration] (4): Added Frontend client [PAM]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_process_result] (8): Trace: sh[0xc1f8020], connected[1], ops[0xc2071c0], ldap[0xc1f8090]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_parse_entry] (9): OriginalDN: [].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_process_result] (8): Trace: sh[0xc1f8020], connected[1], ops[0xc2071c0], ldap[0xc1f8090]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_get_rootdse_done] (9): Got rootdse
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_control_create] (3): Server does not support the requested control [1.3.6.1.4.1.42.2.27.8.5.1].
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [simple_bind_send] (4): Executing simple bind as: cn=Administrator,cn=Users,dc=sssdad,dc=com
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [simple_bind_send] (8): ldap simple bind sent, msgid = 2
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_process_result] (8): Trace: sh[0xc1f8020], connected[1], ops[0xc206250], ldap[0xc1f8090]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_process_result] (8): Trace: ldap_result found nothing!
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [sdap_process_result] (8): Trace: sh[0xc1f8020], connected[1], ops[0xc206250], ldap[0xc1f8090]
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [simple_bind_done] (5): Server returned no controls.
(Fri Jun 10 20:41:22 2011) [sssd[be[ADtest]]] [simple_bind_done] (3): Bind result: Success(0), (null)

</snip>

Expected results:
"lookup_family_order = ipv6_only" should not lookup A records.

Additional info:
# cat /etc/sssd/sssd.conf
[sssd]
config_file_version = 2
reconnection_retries = 3
sbus_timeout = 30
services = nss, pam
domains = ADtest
#debug_timestamps = false
debug_level = 9

[nss]
filter_groups = root
filter_users = root
reconnection_retries = 3
debug_level = 9
#debug_timestamps = false

[pam]
reconnection_retries = 3
debug_level = 9
#debug_timestamps = false

[domain/ADtest]
debug_level = 9
id_provider = ldap
ldap_uri = ldap://pluto.sssdad.com
ldap_default_bind_dn = cn=Administrator,cn=Users,dc=sssdad,dc=com
ldap_default_authtok = XXXXXXX
ldap_force_upper_case_realm = True
ldap_user_object_class = person
ldap_user_principal = userPrincipalName
ldap_group_name = cn
ldap_search_base = dc=sssdad,dc=com
lookup_family_order = ipv6_only
enumerate = true

Comment 1 Jakub Hrozek 2011-06-10 15:54:17 UTC

I brought it up upstream - it seems that this behaviour was intentional in c-ares and I'd like to know why. My opinion is that the fallback should not happen, but I'd like to hear their reasoning.

Comment 2 Jakub Hrozek 2011-08-15 11:46:03 UTC

Upstream accepted our fix (upstream git bb4096effef7f0001339669a4abf9448ec1f8743)

Comment 3 RHEL Program Management 2012-06-12 01:32:12 UTC

This request was evaluated by Red Hat Product Management for
inclusion in the current release of Red Hat Enterprise Linux.
Because the affected component is not scheduled to be updated in the
current release, Red Hat is unfortunately unable to address this
request at this time. Red Hat invites you to ask your support
representative to propose this request, if appropriate and relevant,
in the next release of Red Hat Enterprise Linux.

Comment 4 Jakub Hrozek 2013-11-06 15:47:54 UTC

This Bugzilla has been reviewed by Red Hat and is not planned on being addressed in Red Hat Enterprise Linux 5, and therefore will be closed. If this bug is critical to production systems, please contact your Red Hat support representative and provide sufficient business justification. Issue is already fixed in RHEL-6 and RHEL-7.