#7018 During FreeIPA upgrade process (Fedora 25 to Fedora 26), named-pkcs11 tries several times to contact KDC before it is started
Closed: wontfix 2 years ago by rcritten. Opened 3 years ago by stlaz.

Ticket was cloned from Red Hat Bugzilla (product Fedora): Bug 1456043

I'm currently testing upgrades of Fedora 25 FreeIPA servers to Fedora 26, and
noticing several problems. One is that, during the update process,
named-pkcs11.service seems to start up and try to contact the KDC before the
KDC itself is started:

May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: starting BIND
9.11.0-P5-RedHat-9.11.0-8.P5.fc26 <id:ad4fb79>
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: running on Linux
x86_64 4.10.17-200.fc25.x86_64 #1 SMP Mon May 22 18:12:57 UTC 2017
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: built with
'--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu'
'--program-prefix=' '--disable-dependency-tracking' '--prefix=/usr'
'--exec-prefix=/usr' '--bindir=/usr
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: running as:
named-pkcs11 -u named
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]:
----------------------------------------------------
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: BIND 9 is maintained
by Internet Systems Consortium,
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: Inc. (ISC), a
non-profit 501(c)(3) public-benefit
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: corporation.  Support
and training for BIND 9 are
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: available at
https://www.isc.org/support
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]:
----------------------------------------------------
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: adjusted limit on open
files from 4096 to 1048576
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: found 2 CPUs, using 2
worker threads
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: using 1 UDP listener
per interface
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: using up to 21000
sockets
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: loading configuration
from '/etc/named.conf'
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: reading built-in
trusted keys from file '/etc/named.iscdlv.key'
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: initializing GeoIP
Country (IPv4) (type 1) DB
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GEO-106FREE 20170502
Build 1 Copyright (c) 2017 MaxMind Inc All Rights Reserved
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP Country (IPv6)
(type 12) DB not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP City (IPv4)
(type 2) DB not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP City (IPv4)
(type 6) DB not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP City (IPv6)
(type 30) DB not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP City (IPv6)
(type 31) DB not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP Region (type 3)
DB not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP Region (type 7)
DB not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP ISP (type 4) DB
not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP Org (type 5) DB
not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP AS (type 9) DB
not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP Domain (type 11)
DB not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: GeoIP NetSpeed (type
10) DB not available
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: using default UDP/IPv4
port range: [32768, 60999]
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: using default UDP/IPv6
port range: [32768, 60999]
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: listening on IPv6
interfaces, port 53
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: listening on IPv4
interface lo, 127.0.0.1#53
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: listening on IPv4
interface eth0, 10.0.2.100#53
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: generating session key
for dynamic DNS
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: sizing zone task pool
based on 6 zones
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: zone
'localhost.localdomain' allows updates by IP address, which is insecure
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: zone 'localhost'
allows updates by IP address, which is insecure
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: zone
'1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa'
allows updates by IP address, which is insecure
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: zone
'1.0.0.127.in-addr.arpa' allows updates by IP address, which is insecure
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: zone '0.in-addr.arpa'
allows updates by IP address, which is insecure
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: 'max-cache-size 90%' -
setting to 1799MB (out of 1999MB)
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: set up managed keys
zone for view _default, file '/var/named/dynamic/managed-keys.bind'
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: loading DynDB instance
'ipa' driver '/usr/lib64/bind/ldap.so'
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: bind-dyndb-ldap
version 11.1 compiled at 13:01:09 Mar 13 2017, compiler 7.0.1 20170225 (Red Hat
7.0.1-0.10)
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: Failed to get initial
credentials (TGT) using principal 'DNS/ipa001.domain.local' and keytab
'FILE:/etc/named.keytab' (Cannot contact any KDC for realm 'DOMAIN.LOCAL')
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: Failed to get initial
credentials (TGT) using principal 'DNS/ipa001.domain.local' and keytab
'FILE:/etc/named.keytab' (Cannot contact any KDC for realm 'DOMAIN.LOCAL')
May 26 11:39:27 ipa001.domain.local named-pkcs11[15998]: ldap_sync_prepare()
failed, retrying in 1 second: socket is not connected

...

May 26 11:40:28 ipa001.domain.local named-pkcs11[15998]: Failed to get initial
credentials (TGT) using principal 'DNS/ipa001.domain.local' and keytab
'FILE:/etc/named.keytab' (Cannot contact any KDC for realm 'DOMAIN.LOCAL')
May 26 11:40:28 ipa001.domain.local named-pkcs11[15998]: ldap_syncrepl will
reconnect in 60 seconds

...

then it seems like the service is restarted, for some reason, still without KDC
being started, and the error happens again:

May 26 11:41:28 ipa001.domain.local named-pkcs11[15998]: exiting
May 26 11:41:28 ipa001.domain.local systemd[1]: Stopped Berkeley Internet Name
Domain (DNS) with native PKCS#11.
May 26 11:41:28 ipa001.domain.local systemd[1]: Starting Generate rndc key for
BIND (DNS)...
May 26 11:41:28 ipa001.domain.local audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
msg='unit=named-pkcs11 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=?
addr=? terminal=? res=
May 26 11:41:28 ipa001.domain.local audit[1]: SERVICE_STOP pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
msg='unit=named-pkcs11 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=?
addr=? terminal=? res=s
May 26 11:41:28 ipa001.domain.local systemd[1]: Started Generate rndc key for
BIND (DNS).
May 26 11:41:28 ipa001.domain.local audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
msg='unit=named-setup-rndc comm="systemd" exe="/usr/lib/systemd/systemd"
hostname=? addr=? terminal=?
May 26 11:41:28 ipa001.domain.local audit[1]: SERVICE_STOP pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
msg='unit=named-setup-rndc comm="systemd" exe="/usr/lib/systemd/systemd"
hostname=? addr=? terminal=? r
May 26 11:41:28 ipa001.domain.local systemd[1]: Starting Berkeley Internet Name
Domain (DNS) with native PKCS#11...
May 26 11:41:28 ipa001.domain.local bash[16165]: zone localhost.localdomain/IN:
loaded serial 0
May 26 11:41:28 ipa001.domain.local bash[16165]: zone localhost/IN: loaded
serial 0
May 26 11:41:28 ipa001.domain.local bash[16165]: zone
1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa/IN:
loaded serial 0
May 26 11:41:28 ipa001.domain.local bash[16165]: zone
1.0.0.127.in-addr.arpa/IN: loaded serial 0
May 26 11:41:28 ipa001.domain.local bash[16165]: zone 0.in-addr.arpa/IN: loaded
serial 0
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: starting BIND
9.11.0-P5-RedHat-9.11.0-8.P5.fc26 <id:ad4fb79>

...

May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: bind-dyndb-ldap
version 11.1 compiled at 13:01:09 Mar 13 2017, compiler 7.0.1 20170225 (Red Hat
7.0.1-0.10)
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: Failed to get initial
credentials (TGT) using principal 'DNS/ipa001.domain.local' and keytab
'FILE:/etc/named.keytab' (Cannot contact any KDC for realm 'DOMAIN.LOCAL')
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: Failed to get initial
credentials (TGT) using principal 'DNS/ipa001.domain.local' and keytab
'FILE:/etc/named.keytab' (Cannot contact any KDC for realm 'DOMAIN.LOCAL')
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
10.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
16.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
17.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
18.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
19.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
20.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
21.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
22.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
23.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
24.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: automatic empty zone:
25.172.IN-ADDR.ARPA
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: ldap_sync_prepare()
failed, retrying in 1 second: socket is not connected

Then the service seems to stop again, with some more errors:

May 26 11:41:28 ipa001.domain.local systemd[1]: Stopping Berkeley Internet Name
Domain (DNS) with native PKCS#11...
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: received control
channel command 'stop'
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: shutting down:
flushing changes
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: stopping command
channel on 127.0.0.1#953
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: stopping command
channel on ::1#953
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: error writing NTA file
for view '_default': permission denied
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: error writing NTA file
for view '_bind': permission denied
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: unloading DynDB
instance 'ipa'
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: LDAP configuration
synchronization failed: socket is not connected
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: no longer listening on
::#53
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: no longer listening on
127.0.0.1#53
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: no longer listening on
10.0.2.100#53
May 26 11:41:28 ipa001.domain.local named-pkcs11[16172]: exiting
May 26 11:41:28 ipa001.domain.local systemd[1]: Stopped Berkeley Internet Name
Domain (DNS) with native PKCS#11.

Then finally the KDC is started a half minute later:

May 26 11:42:09 ipa001.domain.local systemd[1]: Starting Kerberos 5 KDC...
May 26 11:42:09 ipa001.domain.local systemd[1]: Started Kerberos 5 KDC.

It then does seem like named-pkcs11 gets started *again*, and the sync seems to
work this time:

May 26 11:42:09 ipa001.domain.local systemd[1]: Starting Berkeley Internet Name
Domain (DNS) with native PKCS#11...
May 26 11:42:09 ipa001.domain.local bash[16803]: zone localhost.localdomain/IN:
loaded serial 0
May 26 11:42:09 ipa001.domain.local bash[16803]: zone localhost/IN: loaded
serial 0
May 26 11:42:09 ipa001.domain.local bash[16803]: zone
1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa/IN:
loaded serial 0
May 26 11:42:09 ipa001.domain.local bash[16803]: zone
1.0.0.127.in-addr.arpa/IN: loaded serial 0
May 26 11:42:09 ipa001.domain.local bash[16803]: zone 0.in-addr.arpa/IN: loaded
serial 0
May 26 11:42:09 ipa001.domain.local named-pkcs11[16808]: starting BIND
9.11.0-P5-RedHat-9.11.0-8.P5.fc26 <id:ad4fb79>

...

May 26 11:42:09 ipa001.domain.local named-pkcs11[16808]: all zones loaded
May 26 11:42:09 ipa001.domain.local named-pkcs11[16808]: running
May 26 11:42:09 ipa001.domain.local named-pkcs11[16808]: LDAP configuration for
instance 'ipa' synchronized
May 26 11:42:09 ipa001.domain.local named-pkcs11[16808]: GSSAPI client step 1
May 26 11:42:09 ipa001.domain.local named-pkcs11[16808]: GSSAPI client step 1
May 26 11:42:09 ipa001.domain.local named-pkcs11[16808]: GSSAPI client step 1
May 26 11:42:09 ipa001.domain.local named-pkcs11[16808]: GSSAPI client step 2
May 26 11:42:09 ipa001.domain.local named-pkcs11[16808]: LDAP data for instance
'ipa' are being synchronized, please ignore message 'all zones loaded'

So this may not be critical, but I'm not sure, and figured it should still be
reported. I'll attach the whole journal from the upgrade boot, and also the
ipaupgrade.log file.

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

3 years ago

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

3 years ago

Metadata Update from @stlaz:
- Issue assigned to stlaz

3 years ago

BZ closed with this reasoning:

There are many restarts of named in upgrade, I don't see this as issue because at the end of
upgrade named is working

Metadata Update from @rcritten:
- Issue close_status updated to: wontfix
- Issue set to the milestone: None
- Issue status updated to: Closed (was: Open)

2 years ago

Login to comment on this ticket.

Metadata