Bug 1456043 - During FreeIPA upgrade process (Fedora 25 to Fedora 26), named-pkcs11 tries several times to contact KDC before it is started
Summary: During FreeIPA upgrade process (Fedora 25 to Fedora 26), named-pkcs11 tries s...
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Fedora
Classification: Fedora
Component: freeipa
Version: 26
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: IPA Maintainers
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: 1456038
TreeView+ depends on / blocked
 
Reported: 2017-05-26 20:14 UTC by Adam Williamson
Modified: 2017-06-26 06:46 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-06-26 06:46:38 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
journal file (use journalctl --file system.journal -b-1 to see messages from the upgrade boot) (1.90 MB, application/octet-stream)
2017-05-26 21:54 UTC, Adam Williamson
no flags Details
ipaupgrade.log from the upgrade attempt (4.75 MB, text/plain)
2017-05-26 21:56 UTC, Adam Williamson
no flags Details

Description Adam Williamson 2017-05-26 20:14:25 UTC
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.

Comment 1 Adam Williamson 2017-05-26 21:54:40 UTC
Created attachment 1282778 [details]
journal file (use journalctl --file system.journal -b-1 to see messages from the upgrade boot)

Comment 2 Adam Williamson 2017-05-26 21:56:22 UTC
Created attachment 1282779 [details]
ipaupgrade.log from the upgrade attempt

Comment 3 Standa Laznicka 2017-06-13 15:12:03 UTC
Upstream ticket:
https://pagure.io/freeipa/issue/7018

Comment 4 Martin Bašti 2017-06-19 15:54:15 UTC
There are many restarts of named in upgrade, I don't see this as issue because at the end of upgrade named is working

Comment 5 Standa Laznicka 2017-06-23 07:21:55 UTC
I agree with Martin Bašti, since the upgrade eventually gets to a successful end, I propose not fixing this, at least for now.

Comment 6 Adam Williamson 2017-06-23 19:18:54 UTC
I don't really object, as mentioned above, I just reported it in case it would be considered a problem.

Comment 7 Standa Laznicka 2017-06-26 06:46:38 UTC
Thank you, Adam. I will close this as WONTFIX for now, then.


Note You need to log in before you can comment on or make changes to this bug.