#1923 named fails to start after installing ipa server when short hostname preceeds fqdn in /etc/hosts.
Closed: Fixed None Opened 10 years ago by dpal.

https://bugzilla.redhat.com/show_bug.cgi?id=742875

Description of problem:
After installing ipa-server with --setup-dns, if you have the short hostname ahead of fqdn in /etc/hosts, named fails to start. sssd tries to do a GSSAPI auth with the short hostname and does not find its respective principal in kerberos. Setting `hostname -s` at the end solves this issue.

Version-Release number of selected component (if applicable):
sssd-1.5.1-53.el6.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Configure your /etc/hosts as 
[root@jetfire ]# cat /etc/hosts
127.0.0.1   localhost localhost.localdomain localhost4 localhost4.localdomain4
::1         localhost6 localhost6.localdomain6
2620:52:0:41c9:5054:ff:fea8:b669    jetfire jetfire.lab.eng.pnq.redhat.com

2. Install ipa-server
<snip>
Configuring named:
  [1/9]: adding DNS container
  [2/9]: setting up our zone
  [3/9]: setting up reverse zone
  [4/9]: setting up our own record
  [5/9]: setting up kerberos principal
  [6/9]: setting up named.conf
  [7/9]: restarting named
named service failed to start              <<<<<<<<<<<<<<
  [8/9]: configuring named to start on boot
  [9/9]: changing resolv.conf to point to ourselves
done configuring named.
</snip>

3. service named resart
# service named restart
Stopping named:                                            [  OK  ]
Starting named:                                            [FAILED]


Actual results: named fails to start. named starts successfully when I set the fqdn followed by `hostname -s` in /etc/hosts.


Expected results: named should start successfully even when `hostname -s` preceeds fqdn in /etc/hosts. In RHEL6.2 the default /etc/hosts looks like:
# cat /etc/hosts
127.0.0.1   localhost localhost.localdomain localhost4 localhost4.localdomain4
::1         localhost localhost.localdomain localhost6 localhost6.localdomain6

So, it would be quite common for users to add `hostname -s` ahead of fqdn as that is how we specify for localhost.

Additional info:

/var/log/messages:
Oct  3 03:03:06 jetfire named[15335]: starting BIND 9.7.3-P3-RedHat-9.7.3-7.P3.el6 -u named
Oct  3 03:03:06 jetfire named[15335]: built with '--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu' '--target=x86_64-redhat-linux-gnu' '--program-prefix=' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--sharedstatedir=/var/lib' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--with-libtool' '--localstatedir=/var' '--enable-threads' '--enable-ipv6' '--with-pic' '--disable-static' '--disable-openssl-version-check' '--with-dlz-ldap=yes' '--with-dlz-postgres=yes' '--with-dlz-mysql=yes' '--with-dlz-filesystem=yes' '--with-gssapi=yes' '--disable-isc-spnego' '--with-docbook-xsl=/usr/share/sgml/docbook/xsl-stylesheets' 'build_alias=x86_64-redhat-linux-gnu' 'host_alias=x86_64-redhat-linux-gnu' 'target_alias=x86_64-redhat-linux-gnu' 'CFLAGS= -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic' 'CPPFLAGS= -DDIG_SIGCHASE'
Oct  3 03:03:06 jetfire named[15335]: adjusted limit on open files from 1024 to 1048576
Oct  3 03:03:06 jetfire named[15335]: found 1 CPU, using 1 worker thread
Oct  3 03:03:06 jetfire named[15335]: using up to 4096 sockets
Oct  3 03:03:06 jetfire named[15335]: loading configuration from '/etc/named.conf'
Oct  3 03:03:06 jetfire named[15335]: using default UDP/IPv4 port range: [1024, 65535]
Oct  3 03:03:06 jetfire named[15335]: using default UDP/IPv6 port range: [1024, 65535]
Oct  3 03:03:06 jetfire named[15335]: listening on IPv6 interfaces, port 53
Oct  3 03:03:06 jetfire named[15335]: listening on IPv4 interface lo, 127.0.0.1#53
Oct  3 03:03:06 jetfire named[15335]: generating session key for dynamic DNS
===============================
Oct  3 03:03:06 jetfire sssd_be: GSSAPI Error: Unspecified GSS failure.  Minor code may provide more information (Server ldap/jetfire@LAB.ENG.PNQ.REDHAT.COM not found in Kerberos database)
Oct  3 03:03:16 jetfire named[15335]: GSSAPI Error: Unspecified GSS failure.  Minor code may provide more information (Server ldap/jetfire@LAB.ENG.PNQ.REDHAT.COM not found in Kerberos database)
===============================
Oct  3 03:03:16 jetfire named[15335]: bind to LDAP server failed: Local error
Oct  3 03:03:16 jetfire named[15335]: loading configuration: failure
Oct  3 03:03:16 jetfire named[15335]: exiting (due to fatal error)


/var/log/sssd/sssd_lab.eng.pnq.redhat.com.log:
(Mon Oct  3 03:03:05 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sbus_dispatch] (9): dbus conn: 24C3850
(Mon Oct  3 03:03:05 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sbus_dispatch] (9): Dispatching.
(Mon Oct  3 03:03:05 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sbus_message_handler] (9): Received SBUS method [ping]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sbus_dispatch] (9): dbus conn: 24D6990
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sbus_dispatch] (9): Dispatching.
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [be_get_account_info] (4): Got request for [4099][1][name=named]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [be_get_account_info] (4): Request processed. Returned 1,11,Fast reply - offline
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_op_connect_step] (9): beginning to connect
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'IPA'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [get_server_status] (7): Status of server 'jetfire.lab.eng.pnq.redhat.com' is 'name resolved'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [get_port_status] (7): Port status of port 0 for server 'jetfire.lab.eng.pnq.redhat.com' is 'not working'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [get_port_status] (4): Reseting the status of port 0 for server 'jetfire.lab.eng.pnq.redhat.com'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [get_server_status] (7): Status of server 'jetfire.lab.eng.pnq.redhat.com' is 'name resolved'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [be_resolve_server_done] (4): Found address for server jetfire.lab.eng.pnq.redhat.com: [2620:52:0:41c9:5054:ff:fea8:b669] TTL 7200
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [ipa_resolve_callback] (6): Constructed uri 'ldap://jetfire.lab.eng.pnq.redhat.com'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sss_ldap_init_send] (9): Using file descriptor [27] for LDAP connection.
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_ldap_connect_callback_add] (9): New LDAP connection to [ldap://jetfire.lab.eng.pnq.redhat.com:389/??base] with fd [27].
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_rootdse_send] (9): Getting rootdse
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (6): calling ldap_search_ext with [(objectclass=*)][].
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [*]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [altServer]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [namingContexts]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedControl]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedExtension]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedFeatures]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedLDAPVersion]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedSASLMechanisms]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [defaultNamingContext]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [lastUSN]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [highestCommittedUSN]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (8): ldap_search_ext called, msgid = 1
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: sh[0x24e6b10], connected[1], ops[0x24d9050], ldap[0x24e7890]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_parse_entry] (9): OriginalDN: [].
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: sh[0x24e6b10], connected[1], ops[0x24d9050], ldap[0x24e7890]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_rootdse_done] (9): Got rootdse
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_kinit_send] (6): Attempting kinit ((null), host/jetfire.lab.eng.pnq.redhat.com, LAB.ENG.PNQ.REDHAT.COM, 86400)
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_kinit_next_kdc] (7): Resolving next KDC for service IPA
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'IPA'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [get_server_status] (7): Status of server 'jetfire.lab.eng.pnq.redhat.com' is 'name resolved'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [get_port_status] (7): Port status of port 0 for server 'jetfire.lab.eng.pnq.redhat.com' is 'neutral'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [get_server_status] (7): Status of server 'jetfire.lab.eng.pnq.redhat.com' is 'name resolved'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [be_resolve_server_done] (4): Found address for server jetfire.lab.eng.pnq.redhat.com: [2620:52:0:41c9:5054:ff:fea8:b669] TTL 7200
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_kinit_kdc_resolved] (7): KDC resolved, attempting to get TGT...
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [create_tgt_req_send_buffer] (7): buffer size: 73
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [child_handler_setup] (8): Setting up signal handler up for pid [15334]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [child_handler_setup] (8): Signal handler set up for pid [15334]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [set_tgt_child_timeout] (6): Setting 6 seconds timeout for tgt child
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: sh[0x24e6b10], connected[1], ops[(nil)], ldap[0x24e7890]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: ldap_result found nothing!
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [write_pipe_handler] (6): All data has been sent!
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [read_pipe_handler] (6): EOF received, client finished
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_tgt_recv] (6): Child responded: 0 [FILE:/var/lib/sss/db/ccache_LAB.ENG.PNQ.REDHAT.COM], expired on [1317711786]
===============================
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sasl_bind_send] (4): Executing sasl bind mech: GSSAPI, user: host/jetfire.lab.eng.pnq.redhat.com
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sasl_bind_send] (1): ldap_sasl_bind failed (-2)[Local error]
===============================
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [child_sig_handler] (7): Waiting for child [15334].
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [child_sig_handler] (4): child [15334] finished successfully.
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [fo_set_port_status] (4): Marking port 0 of server 'jetfire.lab.eng.pnq.redhat.com' as 'not working'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_handle_release] (8): Trace: sh[0x24e6b10], connected[1], ops[(nil)], ldap[0x24e7890], destructor_lock[0], release_memory[0]
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [remove_connection_callback] (9): Successfully removed connection callback.
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_op_connect_done] (9): attempting failover retry on op #1
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_op_connect_step] (9): beginning to connect
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'IPA'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [get_server_status] (7): Status of server 'jetfire.lab.eng.pnq.redhat.com' is 'name resolved'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [get_port_status] (7): Port status of port 0 for server 'jetfire.lab.eng.pnq.redhat.com' is 'not working'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [fo_resolve_service_send] (1): No available servers for service 'IPA'
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_release_conn_data] (9): releasing unused connection
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_op_connect_done] (1): Failed to connect, going offline (5 [Input/output error])
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [be_mark_offline] (8): Going offline!
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [be_run_offline_cb] (3): Going offline. Running callbacks.
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_op_connect_done] (9): notify offline to op #1
(Mon Oct  3 03:03:06 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_release_conn_data] (9): releasing unused connection
(Mon Oct  3 03:03:07 2011) [sssd[be[lab.eng.pnq.redhat.com]]] [remove_krb5_info_files] (5): Could not remove [/var/lib/sss/pubconf/kpasswdinfo.LAB.ENG.PNQ.REDHAT.COM], [2][No such file or directory]

Martin, your patch is superior to mine, going to let you follow this up.

Patch freeipa-mkosek-140-check-hostname-resolution-sanity.patch sent for review

master:[[br]]
363c23a[[br]]
9bff6cb

ipa-2-1:[[br]]
58918c4[[br]]
93feb52

Metadata Update from @dpal:
- Issue assigned to mkosek
- Issue set to the milestone: FreeIPA 2.1.3 (bug fixing)

5 years ago

Login to comment on this ticket.

Metadata