Bug 1365669

Summary: The ipa-server-upgrade command failed when named-pkcs11 does not happen to run during dnf upgrade
Product: [Fedora] Fedora Reporter: Jan Pazdziora <jpazdziora>
Component: freeipaAssignee: Petr Spacek <pspacek>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 24CC: abokovoy, ipa-maint, jcholast, jhrozek, jpazdziora, mbabinsk, mbasti, mkosek, pspacek, pvoborni, rcritten, ssorce
Target Milestone: ---Keywords: Regression, Reopened
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: freeipa-4.3.2-2.fc24 freeipa-4.4.2-1.fc25 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1367022 (view as bug list) Environment:
Last Closed: 2016-11-19 21:01:20 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1367022    

Description Jan Pazdziora 2016-08-09 19:45:28 UTC
Description of problem:

When freeipa-server-4.3.1-1.fc24.x86_64 gets upgraded to freeipa-server-4.3.2-1.fc24.x86_64 and named-pkcs11 service is not running in the posttrans (?), error

DNS query for ipa.example.test. A failed: The DNS operation timed out after 30.0009489059 seconds
Upgrade failed with The DNS operation timed out after 30.0009489059 seconds
IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
('IPA upgrade failed.', 1)
The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information

is shown.

Version-Release number of selected component (if applicable):

freeipa-server-4.3.2-1.fc24.x86_64

How reproducible:

Deterministic.

Steps to Reproduce:
1. Install Freeipa 4.3.1, configure it with ipa-server-install --setup-dns.
2. Run dnf upgrade --downloadonly --enablerepo updates-testing freeipa-server.
3. Run systemctl stop named-pkcs11
4. Run dnf upgrade --enablerepo updates-testing freeipa-server

Actual results:

  Upgrading   : freeipa-common-4.3.2-1.fc24.noarch           1/20 
  Upgrading   : freeipa-client-common-4.3.2-1.fc24.noarch    2/20 
  Upgrading   : freeipa-server-common-4.3.2-1.fc24.noarch    3/20 
  Upgrading   : python2-ipalib-4.3.2-1.fc24.noarch           4/20 
  Upgrading   : python2-ipaclient-4.3.2-1.fc24.noarch        5/20 
  Upgrading   : freeipa-client-4.3.2-1.fc24.x86_64           6/20 
Could not load host key: /etc/ssh/ssh_host_dsa_key
  Upgrading   : python2-ipaserver-4.3.2-1.fc24.noarch        7/20 
  Upgrading   : freeipa-admintools-4.3.2-1.fc24.noarch       8/20 
  Upgrading   : freeipa-server-4.3.2-1.fc24.x86_64           9/20 
  Upgrading   : freeipa-server-dns-4.3.2-1.fc24.noarch      10/20 
  Cleanup     : freeipa-server-dns-4.3.1-1.fc24.noarch      11/20 
  Cleanup     : freeipa-server-4.3.1-1.fc24.x86_64          12/20 
  Cleanup     : python2-ipaserver-4.3.1-1.fc24.noarch       13/20 
  Cleanup     : freeipa-client-4.3.1-1.fc24.x86_64          14/20 
  Cleanup     : python2-ipaclient-4.3.1-1.fc24.noarch       15/20 
  Cleanup     : freeipa-admintools-4.3.1-1.fc24.noarch      16/20 
  Cleanup     : python2-ipalib-4.3.1-1.fc24.noarch          17/20 
  Cleanup     : freeipa-server-common-4.3.1-1.fc24.noarch   18/20 
  Cleanup     : freeipa-client-common-4.3.1-1.fc24.noarch   19/20 
  Cleanup     : freeipa-common-4.3.1-1.fc24.noarch          20/20 
DNS query for ipa.example.test. A failed: The DNS operation timed out after 30.0009489059 seconds
Upgrade failed with The DNS operation timed out after 30.0009489059 seconds
IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
('IPA upgrade failed.', 1)
The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information
  Verifying   : freeipa-server-4.3.2-1.fc24.x86_64           1/20 
  Verifying   : freeipa-admintools-4.3.2-1.fc24.noarch       2/20 

Expected results:

No error.

Additional info:

The /var/log/ipaupgrade.log ends with

2016-08-09T19:37:05Z DEBUG dnsconfig_show(rights=False, all=True, raw=False, version=u'2.164')
2016-08-09T19:37:05Z DEBUG Executing upgrade plugin: update_dnsforward_emptyzones
2016-08-09T19:37:05Z DEBUG raw: update_dnsforward_emptyzones
2016-08-09T19:37:05Z DEBUG raw: dnsconfig_show(all=True, version=u'2.164')
2016-08-09T19:37:05Z DEBUG dnsconfig_show(rights=False, all=True, raw=False, version=u'2.164')
2016-08-09T19:37:05Z DEBUG Updating forwarding policies in LDAP to avoid conflicts with automatic empty zones
2016-08-09T19:37:05Z DEBUG raw: dnsconfig_mod(ipadnsversion=2, version=u'2.164')
2016-08-09T19:37:05Z DEBUG dnsconfig_mod(ipadnsversion=2, rights=False, all=False, raw=False, version=u'2.164')
2016-08-09T19:37:05Z DEBUG raw: dnsforwardzone_find(None, all=True, raw=True, version=u'2.164')
2016-08-09T19:37:05Z DEBUG dnsforwardzone_find(None, all=True, raw=True, version=u'2.164', pkey_only=False)
2016-08-09T19:37:35Z ERROR DNS query for ipa.example.test. A failed: The DNS operation timed out after 30.0009489059 seconds
2016-08-09T19:37:35Z DEBUG Destroyed connection context.ldap2_140607877043344
2016-08-09T19:37:35Z ERROR Upgrade failed with The DNS operation timed out after 30.0009489059 seconds
2016-08-09T19:37:35Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ipaserver/install/upgradeinstance.py", line 216, in __upgrade
    self.modified = (ld.update(self.files) or self.modified)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ldapupdate.py", line 918, in update
    self._run_updates(all_updates)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ldapupdate.py", line 890, in _run_updates
    self._run_update_plugin(update['plugin'])
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ldapupdate.py", line 863, in _run_update_plugin
    restart_ds, updates = self.api.Updater[plugin_name]()
  File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 1404, in __call__
    return self.execute(**options)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/plugins/dns.py", line 492, in execute
    if dnsutil.has_empty_zone_addresses(self.api.env.host):
  File "/usr/lib/python2.7/site-packages/ipapython/dnsutil.py", line 278, in has_empty_zone_addresses
    ip_addresses = resolve_ip_addresses(hostname)
  File "/usr/lib/python2.7/site-packages/ipapython/dnsutil.py", line 328, in resolve_ip_addresses
    rrsets = resolve_rrsets(fqdn, ['A', 'AAAA'])
  File "/usr/lib/python2.7/site-packages/ipapython/dnsutil.py", line 305, in resolve_rrsets
    answer = dns.resolver.query(fqdn, rdtype)
  File "/usr/lib/python2.7/site-packages/dns/resolver.py", line 1029, in query
    raise_on_no_answer, source_port)
  File "/usr/lib/python2.7/site-packages/dns/resolver.py", line 949, in query
    timeout = self._compute_timeout(start)
  File "/usr/lib/python2.7/site-packages/dns/resolver.py", line 770, in _compute_timeout
    raise Timeout(timeout=duration)
Timeout: The DNS operation timed out after 30.0009489059 seconds

2016-08-09T19:37:35Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 447, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 437, in run_step
    method()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/upgradeinstance.py", line 224, in __upgrade
    raise RuntimeError(e)
RuntimeError: The DNS operation timed out after 30.0009489059 seconds

2016-08-09T19:37:35Z DEBUG   [error] RuntimeError: The DNS operation timed out after 30.0009489059 seconds
2016-08-09T19:37:35Z DEBUG   [cleanup]: stopping directory server
2016-08-09T19:37:35Z DEBUG Starting external process
2016-08-09T19:37:35Z DEBUG args=/bin/systemctl stop dirsrv
2016-08-09T19:37:37Z DEBUG Process finished, return code=0
2016-08-09T19:37:37Z DEBUG stdout=
2016-08-09T19:37:37Z DEBUG stderr=
2016-08-09T19:37:37Z DEBUG   duration: 1 seconds
2016-08-09T19:37:37Z DEBUG   [cleanup]: restoring configuration
2016-08-09T19:37:37Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2016-08-09T19:37:37Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2016-08-09T19:37:37Z DEBUG Saving StateFile to '/var/lib/ipa/sysrestore/sysrestore.state'
2016-08-09T19:37:37Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2016-08-09T19:37:37Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2016-08-09T19:37:37Z DEBUG Saving StateFile to '/var/lib/ipa/sysrestore/sysrestore.state'
2016-08-09T19:37:37Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2016-08-09T19:37:37Z DEBUG   duration: 0 seconds
2016-08-09T19:37:37Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
2016-08-09T19:37:37Z DEBUG   File "/usr/lib/python2.7/site-packages/ipapython/admintool.py", line 171, in execute
    return_value = self.run()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ipa_server_upgrade.py", line 50, in run
    raise admintool.ScriptError(str(e))

2016-08-09T19:37:37Z DEBUG The ipa-server-upgrade command failed, exception: ScriptError: ('IPA upgrade failed.', 1)
2016-08-09T19:37:37Z ERROR ('IPA upgrade failed.', 1)
2016-08-09T19:37:37Z ERROR The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information

Comment 1 Jan Pazdziora 2016-08-09 19:47:28 UTC
While this might seem like theoretical exercise, it actually happens in container installations where after running the container from new image, we need to run ipa-server-upgrade as soon as possible, before all the services are running. And indeed, new named with new DS might not even start before schema and everything is upgraded, so we cannot blindly start named-pkcs11.

Comment 2 Jan Pazdziora 2016-08-09 20:11:01 UTC
This really is a regression -- previous versions of FreeIPA did not expect services to be in some state.

Comment 3 Petr Spacek 2016-08-11 11:44:54 UTC
Upstream ticket:
https://fedorahosted.org/freeipa/ticket/6205

Comment 8 Fedora Update System 2016-08-19 15:59:15 UTC
freeipa-4.3.2-2.fc24 has been submitted as an update to Fedora 24. https://bodhi.fedoraproject.org/updates/FEDORA-2016-92a3655b70

Comment 9 Fedora Update System 2016-08-19 23:21:14 UTC
freeipa-4.3.2-2.fc24 has been pushed to the Fedora 24 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-92a3655b70

Comment 10 Fedora Update System 2016-08-29 18:53:55 UTC
freeipa-4.3.2-2.fc24 has been pushed to the Fedora 24 stable repository. If problems still persist, please make note of it in this bug report.

Comment 11 Jan Pazdziora 2016-09-07 08:30:35 UTC
Upgrading from 4.3.1-1.fc24 to 4.3.2-2.fc24 still complains:

  Upgrading   : freeipa-common-4.3.2-2.fc24.noarch                         1/20 
  Upgrading   : freeipa-client-common-4.3.2-2.fc24.noarch                  2/20 
  Upgrading   : freeipa-server-common-4.3.2-2.fc24.noarch                  3/20 
  Upgrading   : python2-ipalib-4.3.2-2.fc24.noarch                         4/20 
  Upgrading   : python2-ipaclient-4.3.2-2.fc24.noarch                      5/20 
  Upgrading   : freeipa-client-4.3.2-2.fc24.x86_64                         6/20 
Could not load host key: /etc/ssh/ssh_host_dsa_key
  Upgrading   : python2-ipaserver-4.3.2-2.fc24.noarch                      7/20 
  Upgrading   : freeipa-admintools-4.3.2-2.fc24.noarch                     8/20 
  Upgrading   : freeipa-server-4.3.2-2.fc24.x86_64                         9/20 
  Upgrading   : freeipa-server-dns-4.3.2-2.fc24.noarch                    10/20 
  Cleanup     : freeipa-server-dns-4.3.1-1.fc24.noarch                    11/20 
  Cleanup     : freeipa-server-4.3.1-1.fc24.x86_64                        12/20 
  Cleanup     : python2-ipaserver-4.3.1-1.fc24.noarch                     13/20 
  Cleanup     : freeipa-client-4.3.1-1.fc24.x86_64                        14/20 
  Cleanup     : python2-ipaclient-4.3.1-1.fc24.noarch                     15/20 
  Cleanup     : freeipa-admintools-4.3.1-1.fc24.noarch                    16/20 
  Cleanup     : python2-ipalib-4.3.1-1.fc24.noarch                        17/20 
  Cleanup     : freeipa-server-common-4.3.1-1.fc24.noarch                 18/20 
  Cleanup     : freeipa-client-common-4.3.1-1.fc24.noarch                 19/20 
  Cleanup     : freeipa-common-4.3.1-1.fc24.noarch                        20/20
MARK-LWD-LOOP -- 2016-09-07 04:15:09 --
 
DNS query for ipa.example.test. A failed: The DNS operation timed out after 30.0014810562 seconds
Skipping update of global DNS forwarder in LDAP: Unable to determine if local server is using an IP address belonging to an automatic empty zone. Consider changing forwarding policy to "only". DNS exception: The DNS operation timed out after 30.0014810562 seconds
DNS query for ipa.example.test. A failed: The DNS operation timed out after 30.0013720989 seconds
IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
Unexpected error - see /var/log/ipaupgrade.log for details:
Timeout: The DNS operation timed out after 30.0013720989 seconds
The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information
  Verifying   : freeipa-server-4.3.2-2.fc24.x86_64                         1/20 
  Verifying   : freeipa-admintools-4.3.2-2.fc24.noarch                     2/20 
  Verifying   : freeipa-client-4.3.2-2.fc24.x86_64                         3/20 
  Verifying   : freeipa-common-4.3.2-2.fc24.noarch                         4/20 

and the log shows

2016-09-07T08:16:44Z INFO [Checking global forwarding policy in named.conf to avoid conflicts with automatic empty zones]
2016-09-07T08:16:44Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2016-09-07T08:16:44Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2016-09-07T08:16:44Z DEBUG Saving StateFile to '/var/lib/ipa/sysupgrade/sysupgrade.state'
2016-09-07T08:17:14Z ERROR DNS query for ipa.example.test. A failed: The DNS operation timed out after 30.0013720989 seconds
2016-09-07T08:17:14Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
2016-09-07T08:17:14Z DEBUG   File "/usr/lib/python2.7/site-packages/ipapython/admintool.py", line 171, in execute
    return_value = self.run()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ipa_server_upgrade.py", line 48, in run
    server.upgrade()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py", line 1781, in upgrade
    upgrade_configuration()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py", line 1671, in upgrade_configuration
    named_update_global_forwarder_policy(),
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py", line 817, in named_update_global_forwarder_policy
    if not dnsutil.has_empty_zone_addresses(api.env.host):
  File "/usr/lib/python2.7/site-packages/ipapython/dnsutil.py", line 278, in has_empty_zone_addresses
    ip_addresses = resolve_ip_addresses(hostname)
  File "/usr/lib/python2.7/site-packages/ipapython/dnsutil.py", line 328, in resolve_ip_addresses
    rrsets = resolve_rrsets(fqdn, ['A', 'AAAA'])
  File "/usr/lib/python2.7/site-packages/ipapython/dnsutil.py", line 305, in resolve_rrsets
    answer = dns.resolver.query(fqdn, rdtype)
  File "/usr/lib/python2.7/site-packages/dns/resolver.py", line 1029, in query
    raise_on_no_answer, source_port)
  File "/usr/lib/python2.7/site-packages/dns/resolver.py", line 858, in query
    timeout = self._compute_timeout(start)
  File "/usr/lib/python2.7/site-packages/dns/resolver.py", line 770, in _compute_timeout
    raise Timeout(timeout=duration)

2016-09-07T08:17:14Z DEBUG The ipa-server-upgrade command failed, exception: Timeout: The DNS operation timed out after 30.0013720989 seconds
2016-09-07T08:17:14Z ERROR Unexpected error - see /var/log/ipaupgrade.log for details:
Timeout: The DNS operation timed out after 30.0013720989 seconds
2016-09-07T08:17:14Z ERROR The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information
+ code=0

Comment 14 Fedora Update System 2016-10-14 21:54:47 UTC
freeipa-4.4.2-1.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-d89b3f7913

Comment 15 Fedora Update System 2016-11-19 21:01:20 UTC
freeipa-4.4.2-1.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.