Bug 730695

Summary: c-ares falls back to IPv4 when IPv6 doesn't exist.
Product: Red Hat Enterprise Linux 6 Reporter: Jakub Hrozek <jhrozek>
Component: c-aresAssignee: Jakub Hrozek <jhrozek>
Status: CLOSED ERRATA QA Contact: Petr Sklenar <psklenar>
Severity: unspecified Docs Contact:
Priority: low    
Version: 6.2CC: azelinka, dpal, grajaiya, jgalipea, kbanerje, psklenar, sgallagh
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: c-ares-1.7.0-6.el6 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 712434 Environment:
Last Closed: 2012-06-20 14:27:59 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 712434    
Bug Blocks: 750334    
Attachments:
Description Flags
a test case none

Description Jakub Hrozek 2011-08-15 11:53:56 UTC 
+++ This bug was initially created as a clone of Bug #712434 +++

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

--- Additional comment from jhrozek on 2011-06-10 11:54:17 EDT ---

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.

--- Additional comment from jhrozek on 2011-08-15 07:46:03 EDT ---

Upstream accepted our fix (upstream git bb4096effef7f0001339669a4abf9448ec1f8743)
Comment 2 RHEL Program Management 2011-08-15 12:27:50 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. If you would like it considered as an
exception in the current release, please ask your support
representative.
Comment 4 Jakub Hrozek 2011-12-11 18:59:59 UTC 
An upstream fix is available in commit bb4096effef7f0001339669a4abf9448ec1f8743
Comment 7 Jakub Hrozek 2012-03-06 11:56:57 UTC 
Created attachment 567924 [details]
a test case

This testcase can be used to verify the bug. To compile it:
gcc ares_aaaa.c -lcares -o ares_aaaa

To run it:
./ares_aaaa <some-ipv4-only-address>

For example:
./ares_aaaa www.redhat.com
should return ENODATA with the new packages, but (incorrectly) fall back to IPv4 searches with the old packages and return the IP address.

You can also use this case to verify that other address families are not broken. Include the address family as the second parameter:
./ares_aaaa www.redhat.com  0 -- 0=AF_UNSPEC -- Should succeed by falling back to IPv4 search
./ares_aaaa www.redhat.com  2 -- 2=AF_INET -- Should succeed, www.redhat.com does have an A record
./ares_aaaa www.redhat.com  10 -- 10=AF_INET6 -- Should fail, www.redhat.com does not have a AAAA record and c-ares should not perform a fallback
Comment 12 errata-xmlrpc 2012-06-20 14:27:59 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2012-0922.html