#7039 FreeIPA upgrade script requires network to be up, but network is not up during upgrade when using dnf system-upgrade
Closed: fixed 6 years ago Opened 6 years ago by stlaz.

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

I've been adjusting openQA to test FreeIPA upgrades recently. I *think* I've
now got it to the point where the test is valid, but it's failing because of a
genuine bug (but this is all new stuff, so it's possible I got something
wrong).

Anyway, the test does this:

* A server VM boots from a clean Fedora 25 image and deploys itself as a
FreeIPA server (using rolectl)
* A client VM boots from the same image and enrols into the domain (using
realmd)
* The server upgrades itself to Fedora 26 (using dnf system-upgrade), then
reboots and sits there until the client is done
* The client waits for the server to be done upgrading, then also upgrades to
Fedora 26
* The client runs some client-side tests to see if things are working correctly
* Once the client is done, the server tries to cleanly decommission itself,
then the test ends

What I see happening is that one of the client side tests fails - when it runs
`kinit -k host/client003.domain.local@DOMAIN.LOCAL`, expecting success, it
fails with the error "kinit: Cannot contact any KDC for realm 'DOMAIN.LOCAL'
while getting initial credentials". Some earlier tests pass, but I don't think
any of those actually *contact* the server, they're just checking local
configuration on the client side.

When I look at the server logs, I see several failures from ns-slapd, including
one which recurs over and over:

May 19 11:26:43 ipa001.domain.local ns-slapd[1205]:
[19/May/2017:14:26:43.033212238 -0400] - ERR - cos-plugin -
cos_cache_query_attr - cos attribute krbPwdPolicyReference failed schema check
on dn: cn=dns,dc=domain,dc=local

there are various other errors, and ipa-dnskeysyncd.service keeps trying to
start up and failing, with these messages:

May 19 11:28:12 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=ipa-dnskeysyncd comm="systemd" exe="/usr/lib/systemd/systemd"
hostname=? addr=? terminal=? res=success'
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]: ipa         : INFO
LDAP bind...
May 19 11:28:14 ipa001.domain.local python2[1823]: GSSAPI client step 1
May 19 11:28:14 ipa001.domain.local python2[1823]: GSSAPI client step 1
May 19 11:28:14 ipa001.domain.local python2[1823]: GSSAPI client step 1
May 19 11:28:14 ipa001.domain.local python2[1823]: GSSAPI client step 2
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]: ipa         : INFO
Commencing sync process
May 19 11:28:14 ipa001.domain.local ns-slapd[1205]:
[19/May/2017:14:28:14.803715502 -0400] - ERR - cos-plugin -
cos_cache_query_attr - cos attribute krbPwdPolicyReference failed schema check
on dn: idnsname=domain.local.,cn=dns,dc=domain,dc=local
May 19 11:28:14 ipa001.domain.local ns-slapd[1205]:
[19/May/2017:14:28:14.806331783 -0400] - ERR - cos-plugin -
cos_cache_query_attr - cos attribute krbPwdPolicyReference failed schema check
on dn: ipk11UniqueID=562d1e30-3cbd-11e7-b9ff-525400120019,cn=keys,cn=sec,cn=dns
,dc=domain,dc=local
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:
ipa.ipapython.dnssec.keysyncer.KeySyncer: INFO     Initial LDAP dump is done,
sychronizing with ODS and BIND
May 19 11:28:14 ipa001.domain.local audit[1829]: AVC avc:  denied  {
execute_no_trans } for  pid=1829 comm="ipa-dnskeysyncd"
path="/usr/libexec/ipa/ipa-dnskeysync-replica" dev="dm-0" ino=812860
scontext=system_u:system_r:ipa_dnskey_t:s0
tcontext=system_u:object_r:ipa_dnskey_exec_t:s0 tclass=file permissive=0
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]: Traceback (most
recent call last):
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:   File
"/usr/libexec/ipa/ipa-dnskeysyncd", line 110, in <module>
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:     while
ldap_connection.syncrepl_poll(all=1, msgid=ldap_search):
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:   File
"/usr/lib64/python2.7/site-packages/ldap/syncrepl.py", line 409, in
syncrepl_poll
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:
self.syncrepl_refreshdone()
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:   File
"/usr/lib/python2.7/site-packages/ipapython/dnssec/keysyncer.py", line 115, in
syncrepl_refreshdone
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:
self.hsm_replica_sync()
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:   File
"/usr/lib/python2.7/site-packages/ipapython/dnssec/keysyncer.py", line 181, in
hsm_replica_sync
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:
ipautil.run([paths.IPA_DNSKEYSYNCD_REPLICA])
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:   File
"/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 459, in run
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:
preexec_fn=preexec_fn)
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:   File
"/usr/lib64/python2.7/subprocess.py", line 390, in __init__
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:     errread,
errwrite)
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:   File
"/usr/lib64/python2.7/subprocess.py", line 1024, in _execute_child
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]:     raise
child_exception
May 19 11:28:14 ipa001.domain.local ipa-dnskeysyncd[1823]: OSError: [Errno 13]
Permission denied
May 19 11:28:14 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=ipa-dnskeysyncd comm="systemd" exe="/usr/lib/systemd/systemd"
hostname=? addr=? terminal=? res=failed'
May 19 11:28:14 ipa001.domain.local systemd[1]: ipa-dnskeysyncd.service: Main
process exited, code=exited, status=1/FAILURE
May 19 11:28:14 ipa001.domain.local systemd[1]: ipa-dnskeysyncd.service: Unit
entered failed state.
May 19 11:28:14 ipa001.domain.local systemd[1]: ipa-dnskeysyncd.service: Failed
with result 'exit-code'.

I will attach tarballs containing the whole contents of /var/log from both
server and client ends; there are rather a lot of errors, and I'm not sure
which are significant.

Proposing as an F26 Beta blocker, as a violation of "For each one of the
release-blocking package sets, it must be possible to successfully complete a
direct upgrade from fully updated installations of the last two stable Fedora
releases with that package set installed. ...  The upgraded system must meet
all release criteria." - an upgraded Server system deployed as a FreeIPA server
doesn't meet the Alpha criterion "Release-blocking roles and the supported role
configuration interfaces must meet the core functional Role Definition
Requirements to the extent that supported roles can be successfully deployed,
started, stopped, brought to a working configuration, and queried.", as the
domain controller role does not meet its core requirements. Now I read the
criteria again, it's arguable whether this applies (I don't think FreeIPA is
actually part of the *default* Server install), but I think it's worth
considering at least.

Metadata Update from @stlaz:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1452866
- Issue set to the milestone: None

6 years ago

Regarding DS cos plugin errors:

[19/May/2017:14:28:14.803715502 -0400] - ERR - cos-plugin - cos_cache_query_attr - cos attribute krbPwdPolicyReference failed schema check on dn: idnsname=domain.local.,cn=dns,dc=domain,dc=local

This is tracked with https://pagure.io/389-ds-base/issue/49249 (bz 1437492) that is supposed to be fixed in

Fedora 26 389-ds-base-1.3.6.6-1.fc26 - https://koji.fedoraproject.org/koji/buildinfo?buildID=896118

RHEL 7.4 389-ds-base-1.3.6.1-14.el7

Metadata Update from @tbordaz:
- Custom field rhbz reset (from https://bugzilla.redhat.com/show_bug.cgi?id=1452866)

6 years ago

Metadata Update from @stlaz:
- Issue assigned to stlaz

6 years ago

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

6 years ago

Metadata Update from @tkrizek:
- Issue priority set to: major
- Issue set to the milestone: FreeIPA 4.5.3

6 years ago

master:

  • 7ef08aa8cb6e504bc38850a6bf49cb2766b3c1df Ensure network is online prior to an upgrade

ipa-4-5:

  • 3fd92a9c677f0486823c5218d087fa3703db5eab Ensure network is online prior to an upgrade

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

6 years ago

Please ignore the commits above, I accidentally pushed the code into a mirror repo instead of upstream. Sorry about that.

Metadata Update from @tkrizek:
- Issue status updated to: Open (was: Closed)

6 years ago

master:

  • a36f2ae Ensure network is online prior to an upgrade

ipa-4-5:

  • 6ca6942 Ensure network is online prior to an upgrade

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

6 years ago

Login to comment on this ticket.

Metadata