Bug 1477367

Summary: ipa-server-upgrade timeouts on wait_for_open ports expecting IPA services listening on IPv6 ports
Product: Red Hat Enterprise Linux 7 Reporter: Marc Sauton <msauton>
Component: ipaAssignee: IPA Maintainers <ipa-maint>
Status: CLOSED ERRATA QA Contact: ipa-qe <ipa-qe>
Severity: urgent Docs Contact:
Priority: urgent    
Version: 7.4CC: abokovoy, aheverle, atolani, cobrown, ddas, ekeck, gparente, jstephen, ksiddiqu, minyu, mkosek, ndehadra, pasik, pvoborni, rcritten, robert, tscherf
Target Milestone: rcKeywords: Regression, ZStream
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: ipa-4.5.0-21.el7.2.2 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1493410 (view as bug list) Environment:
Last Closed: 2018-04-10 16:43:55 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: 1493410    

Description Marc Sauton 2017-08-01 22:11:51 UTC
Description of problem:

failed "yum ipa-*" from RHEL-7.3 to new 7.4

I was about to complete an upgrade test when I lost access to my test environment, at this point I need to log in a bz those customer logs for review and references.
there are 2 customer cases at this moment, it seem like there is some difficulties around the dogtag services, the start from
/bin/systemctl start pki-tomcatd
may not have happened correctly:

2017-08-01T15:33:23Z DEBUG wait_for_open_ports: localhost [8080, 8443] timeout 300
2017-08-01T15:38:23Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
2017-08-01T15:38:23Z DEBUG   File "/usr/lib/python2.7/site-packages/ipapython/admintool.py", line 172, in execute
    return_value = self.run()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ipa_server_upgrade.py", line 46, in run
    server.upgrade()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py", line 1913, in upgrade
    upgrade_configuration()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py", line 1646, in upgrade_configuration
    upgrade_pki(ca, fstore)
  File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/installutils.py", line 1134, in stopped_service
    service_obj.start(instance_name)
  File "/usr/lib/python2.7/site-packages/ipaplatform/redhat/services.py", line 211, in start
    instance_name, capture_output=capture_output, wait=wait)
  File "/usr/lib/python2.7/site-packages/ipaplatform/base/services.py", line 300, in start
    self.wait_for_open_ports(self.service_instance(instance_name))
  File "/usr/lib/python2.7/site-packages/ipaplatform/base/services.py", line 270, in wait_for_open_ports
    self.api.env.startup_timeout)
  File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 1227, in wait_for_open_ports
    raise socket.timeout("Timeout exceeded")

2017-08-01T15:38:23Z DEBUG The ipa-server-upgrade command failed, exception: timeout: Timeout exceeded
2017-08-01T15:38:23Z ERROR Timeout exceeded



case 01901713 has a sosreport

but the dogtag debug log is empty, at
https://fubar.gsslab.rdu2.redhat.com/01901713/10-sosreport-ipaserver1.dlcportal.de-20170801082748.tar.xz/sosreport-ipaserver1.dlcportal.de-20170801082748/var/log/pki/pki-tomcat/ca/

so it is not clear what happened.
then, there are quite some errors, and also from custodia, at
https://fubar.gsslab.rdu2.redhat.com/01901713/10-sosreport-ipaserver1.dlcportal.de-20170801082748.tar.xz/sosreport-ipaserver1.dlcportal.de-20170801082748/var/log/messages

Aug  1 08:25:28 ipaserver1 systemd: Starting The Apache HTTP Server...
Aug  1 08:25:28 ipaserver1 ipa-httpd-kdcproxy: ipa         : INFO     KDC proxy enabled
Aug  1 08:25:29 ipaserver1 systemd: Started The Apache HTTP Server.
Aug  1 08:26:02 ipaserver1 systemd: Starting IPA Custodia Service...
Aug  1 08:26:02 ipaserver1 ipa-custodia: Traceback (most recent call last):
Aug  1 08:26:02 ipaserver1 ipa-custodia: File "/usr/libexec/ipa/ipa-custodia", line 6, in <module>
Aug  1 08:26:02 ipaserver1 ipa-custodia: main()
Aug  1 08:26:02 ipaserver1 ipa-custodia: File "/usr/lib/python2.7/site-packages/ipaserver/secrets/service.py", line 26, in main
Aug  1 08:26:02 ipaserver1 ipa-custodia: return custodia.server.main(argparser)
Aug  1 08:26:02 ipaserver1 ipa-custodia: File "/usr/lib/python2.7/site-packages/custodia/server/__init__.py", line 211, in main
Aug  1 08:26:02 ipaserver1 ipa-custodia: _load_plugins(config, cfgparser)
Aug  1 08:26:02 ipaserver1 ipa-custodia: File "/usr/lib/python2.7/site-packages/custodia/server/__init__.py", line 191, in _load_plugins
Aug  1 08:26:02 ipaserver1 ipa-custodia: raise RuntimeError(menu, name, e)
Aug  1 08:26:02 ipaserver1 ipa-custodia: RuntimeError: ('authorizers', 'kemkeys', ValueError(u'Invalid format for "handler" option [ImportError(\'No module named secrets.kem\',)]: ipapython.secrets.kem.IPAKEMKeys',))
Aug  1 08:26:02 ipaserver1 systemd: ipa-custodia.service: main process exited, code=exited, status=1/FAILURE
Aug  1 08:26:02 ipaserver1 systemd: Failed to start IPA Custodia Service.


Version-Release number of selected component (if applicable):
custodia-0.3.1-4.el7.noarch                                 Tue Aug  1 05:36:02 2017
ipa-server-4.5.0-20.el7.x86_64                              Tue Aug  1 05:36:39 2017
redhat-release-server-7.4-18.el7.x86_64                     Tue Aug  1 05:34:46 2017


How reproducible:
N/A (unreachable test enviroment in remote lab)

Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 14 Petr Vobornik 2017-08-02 16:08:46 UTC
Upstream ticket:
https://pagure.io/freeipa/issue/7083

Comment 15 Petr Vobornik 2017-08-02 16:41:36 UTC
If theory behind incorrect changes in host_port_open function is correct then this PR might fix the issue: https://github.com/freeipa/freeipa/pull/955/files

Comment 35 Tomas Krizek 2017-09-20 10:57:39 UTC
Fixed upstream
ipa-4-6:
https://pagure.io/freeipa/c/f05afa4813f425e9fc9960f63100431a78310638

Comment 36 Rob Crittenden 2017-09-25 14:09:36 UTC
*** Bug 1493116 has been marked as a duplicate of this bug. ***

Comment 38 Nikhil Dehadrai 2017-11-22 13:32:31 UTC
IPA-server version: ipa-server-4.5.4-4.el7.x86_64

Verified the bug on the basis of following steps:
1) Disable IPV6 in /etc/sysctl.conf and run 'sysctl -p'. Use 'ifconfig | grep inet6' to confirm IPv6 is disabled.

2) When IPA server having IPAv6 disabled and is upgraded to latest version ( in my case RHEL 7.5), the upgrade fails with following message:

ERROR IPv6 stack is enabled in the kernel but there is no interface that has ::1 address assigned. Add ::1 address resolution to 'lo' interface. You might need to enable IPv6 on the interface 'lo' in sysctl.conf.

Console:
----------
[root@cloud-qe-17 ~]# rpm -q ipa-server selinux-policy
ipa-server-4.5.4-4.el7.x86_64
selinux-policy-3.13.1-180.el7.noarch

[root@cloud-qe-17 ~]# tail -1 /var/log/ipaupgrade.log 
2017-11-22T13:20:27Z ERROR The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information

[root@cloud-qe-17 ~]# cat /var/log/ipaupgrade.log | grep IPv6
2017-11-22T13:20:27Z ERROR IPv6 stack is enabled in the kernel but there is no interface that has ::1 address assigned. Add ::1 address resolution to 'lo' interface. You might need to enable IPv6 on the interface 'lo' in sysctl.conf.

Thus on the basis of above observations, marking status of bug to "VERIFIED".

Comment 41 errata-xmlrpc 2018-04-10 16:43:55 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2018:0918