Issue #7436: ipa: Please log something after restarting the KDC - freeipa

freeipa

#7436 ipa: Please log something after restarting the KDC

Closed: fixed Apr 28, 2018 Opened Mar 7, 2018 by fbarreto.

Ticket was cloned from Red Hat Bugzilla (product Red Hat Enterprise Linux 7): Bug 1547641

Created attachment 1398903
tarball of /var/log
During an `ipa-server-install -N`, the installer appears to hang on "Restarting
the KDC" for about a full minute.
However, per ipaserver-install.log, it has already finished this:
2018-02-21T16:16:40Z DEBUG Restarting the KDC
2018-02-21T16:16:40Z DEBUG Starting external process
2018-02-21T16:16:40Z DEBUG args=/bin/systemctl restart krb5kdc.service
2018-02-21T16:16:40Z DEBUG Process finished, return code=0
2018-02-21T16:16:40Z DEBUG stdout=
2018-02-21T16:16:40Z DEBUG stderr=
2018-02-21T16:16:40Z DEBUG Starting external process
2018-02-21T16:16:40Z DEBUG args=/bin/systemctl is-active krb5kdc.service
2018-02-21T16:16:40Z DEBUG Process finished, return code=0
2018-02-21T16:16:40Z DEBUG stdout=active
And is instead doing... something else?
2018-02-21T16:16:40Z DEBUG stderr=
2018-02-21T16:16:40Z DEBUG Loading StateFile from
'/var/lib/ipa/sysrestore/sysrestore.state'
2018-02-21T16:16:40Z DEBUG raw: server_find(None, version=u'2.228',
no_members=False)
2018-02-21T16:16:40Z DEBUG server_find(None, all=False, raw=False,
version=u'2.228', no_members=False, pkey_only=False)
2018-02-21T16:16:40Z DEBUG flushing
ldapi://%2fvar%2frun%2fslapd-TESTIUM-BIZ.socket from SchemaCache
2018-02-21T16:16:40Z DEBUG retrieving schema for SchemaCache
url=ldapi://%2fvar%2frun%2fslapd-TESTIUM-BIZ.socket
conn=<ldap.ldapobject.SimpleLDAPObject instance at 0x827ea28>
2018-02-21T16:16:40Z DEBUG raw: topologysuffix_find(None, all=True, raw=True,
version=u'2.228')
2018-02-21T16:16:40Z DEBUG topologysuffix_find(None, all=True, raw=True,
version=u'2.228', pkey_only=False)
2018-02-21T16:16:40Z DEBUG raw: server_role_find(None,
server_server=u'freeipa.testium.biz', status=u'enabled', version=u'2.228')
2018-02-21T16:16:40Z DEBUG server_role_find(None,
server_server=u'freeipa.testium.biz', status=u'enabled', all=False, raw=False,
version=u'2.228')
2018-02-21T16:16:40Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:16:45Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:16:50Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:16:55Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:00Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:05Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:10Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:15Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:20Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:25Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:30Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:35Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:40Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:45Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:50Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:17:55Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:18:00Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:18:05Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:18:10Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:18:15Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:18:20Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:18:25Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:18:30Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:18:35Z DEBUG The DNS query name does not exist:
freeipa.testium.biz.
2018-02-21T16:18:40Z ERROR unable to resolve host name freeipa.testium.biz. to
IP address, ipa-ca DNS record will be incomplete
After logging the ERROR, the CLI logs
ipa         : ERROR    unable to resolve host name freeipa.testium.biz. to IP
address, ipa-ca DNS record will be incomplete
prints some information about the installation, and declares it complete.
Thanks!
[root@freeipa ~]# rpm -qa | egrep 'krb|ipa|cert|389|sssd' | sort
389-ds-base-1.3.6.1-16.el7.x86_64
389-ds-base-libs-1.3.6.1-16.el7.x86_64
ca-certificates-2017.2.14-71.el7.noarch
certmonger-0.78.4-3.el7.x86_64
ipa-client-4.5.0-20.el7.x86_64
ipa-client-common-4.5.0-20.el7.noarch
ipa-common-4.5.0-20.el7.noarch
ipa-server-4.5.0-20.el7.x86_64
ipa-server-common-4.5.0-20.el7.noarch
krb5-libs-1.15.1-8.el7.x86_64
krb5-pkinit-1.15.1-8.el7.x86_64
krb5-server-1.15.1-8.el7.x86_64
krb5-workstation-1.15.1-8.el7.x86_64
libipa_hbac-1.15.2-50.el7.x86_64
libsss_certmap-1.15.2-50.el7.x86_64
python2-ipaclient-4.5.0-20.el7.noarch
python2-ipalib-4.5.0-20.el7.noarch
python2-ipaserver-4.5.0-20.el7.noarch
python-iniparse-0.4-9.el7.noarch
python-ipaddress-1.0.16-2.el7.noarch
python-libipa_hbac-1.15.2-50.el7.x86_64
python-rhsm-certificates-1.19.9-1.el7.x86_64
python-sssdconfig-1.15.2-50.el7.noarch
sssd-1.15.2-50.el7.x86_64
sssd-ad-1.15.2-50.el7.x86_64
sssd-client-1.15.2-50.el7.x86_64
sssd-common-1.15.2-50.el7.x86_64
sssd-common-pac-1.15.2-50.el7.x86_64
sssd-dbus-1.15.2-50.el7.x86_64
sssd-ipa-1.15.2-50.el7.x86_64
sssd-krb5-1.15.2-50.el7.x86_64
sssd-krb5-common-1.15.2-50.el7.x86_64
sssd-ldap-1.15.2-50.el7.x86_64
sssd-proxy-1.15.2-50.el7.x86_64
[root@freeipa ~]#

Metadata Update from @fbarreto:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1547641

Mar 7, 2018

Metadata Update from @fbarreto:
- Issue tagged with: easyfix

Mar 7, 2018

amitkumar25nov commented Mar 9, 2018

I believe
service.print_msg("Restarting the KDC")
service print messages => sys.stdout.write(msg + "\n")
are intended to provide brief of what service would be doing next.

But root_logger.debug('Starting external process')
debug messages => def debug(self, level, _format, args, *kwargs):
""" Debug log using debug level [1..debug_max].
There are additional debugx functions according to debug_max
would come in debug files only.

This may depend some operation takes less|more times, But categorically debugs would be more but we can include 1 or 2 more service.print_msg while KDC restarts.
But to me It looks fine.

rharwood commented Mar 9, 2018

But to me It looks fine.

If by this you mean that the current state of affairs is fine, I have to disagree. It's totally fine to provide brief descriptions of what the service would be doing next, as you say, but there's still a problem - that whatever the IPA installer does after restarting the KDC is missing a log message.

Doesn't really matter to me which way we go, so long as it's easy to see what is happening at any given time.

Metadata Update from @rcritten:
- Issue assigned to rcritten

Apr 27, 2018

rcritten commented Apr 27, 2018

https://github.com/freeipa/freeipa/pull/1872

cheimes commented Apr 28, 2018

master:

6856a9f46cf7418b4188dbc27bc8c20841739542 Log service start/stop/restart message

cheimes commented Apr 28, 2018

ipa-4-6:

c500dbc15c2bedc7f1185d1d06f9aeeba900a9d7 Log service start/stop/restart message

Metadata Update from @cheimes:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

Apr 28, 2018

Metadata

Assignee

rcritten

Tags

Blocking

None

Depending on

None

Priority

None

rhbz

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

freeipa

#7436 ipa: Please log something after restarting the KDC Closed: fixed Apr 28, 2018 Opened Mar 7, 2018 by fbarreto.

Metadata

easyfix

#7436 ipa: Please log something after restarting the KDC

Closed: fixed Apr 28, 2018 Opened Mar 7, 2018 by fbarreto.