Bug 1902173 - Uninstallation of IPA server with KRA installed displays 'ERROR: subprocess.CalledProcessError:'
Summary: Uninstallation of IPA server with KRA installed displays 'ERROR: subprocess.C...
Keywords:
Status: VERIFIED
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: ipa
Version: 8.4
Hardware: Unspecified
OS: Unspecified
high
unspecified
Target Milestone: rc
: 8.0
Assignee: Thomas Woerner
QA Contact: ipa-qe
URL:
Whiteboard:
: 1481949 1740702 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-11-27 08:36 UTC by Sudhir Menon
Modified: 2021-04-13 10:02 UTC (History)
7 users (show)

Fixed In Version: ipa-4.9.2-1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type: Bug
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github dogtagpki pki issues 2924 0 None open ipaserver uninstall in verbose mode displays "pkidestroy: ERROR.. subprocess.CalledProcessError: returned non-zero exit... 2021-02-15 20:57:28 UTC

Description Sudhir Menon 2020-11-27 08:36:11 UTC
Description of problem: Uninstallation of IPA server with KRA installed displays 'ERROR: subprocess.CalledProcessError:'


Version-Release number of selected component (if applicable):
ipa-server-4.9.0-0.1.rc1.module+el8.4.0+8830+62cd648b.x86_64
pki-server-10.10.0-0.2.beta1.module+el8.4.0+8460+91b0d519.noarch

How reproducible:
Always

Steps to Reproduce:
1. ipa-server-install --setup-dns --setup-kra
2. Ensure ipa-server is installed successfully
3. Now ipa-server-install --uninstall -U -v

Actual results:
ipa server is installed successfully but when we check the uninstall logs it displays the below error.

2020-11-27T07:20:41Z DEBUG Stop of certmonger.service complete
2020-11-27T07:20:41Z DEBUG Unconfiguring KRA
2020-11-27T07:20:41Z DEBUG Starting external process
2020-11-27T07:20:41Z DEBUG args=['/usr/sbin/pkidestroy', '-i', 'pki-tomcat', '-s', 'KRA']
2020-11-27T07:22:14Z DEBUG Process finished, return code=1
2020-11-27T07:22:14Z DEBUG stdout=Loading deployment configuration from /var/lib/pki/pki-tomcat/kra/registry/kra/deployment.cfg.
WARNING: The 'pki_ssl_server_token' in [KRA] has been deprecated. Use 'pki_sslserver_token' instead.
Uninstallation log: /var/log/pki/pki-kra-destroy.20201127022041.log
Uninstalling KRA from /var/lib/pki/pki-tomcat.

Uninstallation failed: Command failed: systemctl start pki-tomcatd@pki-tomcat.service


2020-11-27T07:22:14Z DEBUG stderr=ERROR: unable to access security domain. Continuing .. HTTPSConnectionPool(host='server1.rhel84.test', port=443): Max retries exceeded with url: /ca/rest/securityDomain/domainInfo (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fa24418bc18>: Failed to establish a new connection: [Errno 111] Connection refused',)) 
WARNING: this 'KRA' entry will NOT be deleted from security domain 'IPA'!
WARNING: security domain 'IPA' may be offline or unreachable!
ERROR: subprocess.CalledProcessError:  Command '['/usr/bin/sslget', '-n', 'subsystemCert cert-pki-ca', '-p', '4Ee~PGR>QQo;H-pa(7[eB8C4{_?WK4U9KIWXpWqOK', '-d', '/etc/pki/pki-tomcat/alias', '-e', 'name="/var/lib/pki/pki-tomcat"&type=KRA&list=kraList&host=server1.rhel84.test&sport=443&ncsport=443&adminsport=443&agentsport=443&operation=remove', '-v', '-r', '/ca/agent/ca/updateDomainXML', 'server1.rhel84.test:443']' returned non-zero exit status 6.!
Job for pki-tomcatd@pki-tomcat.service failed because a timeout was exceeded.
See "systemctl status pki-tomcatd@pki-tomcat.service" and "journalctl -xe" for details.
ERROR: CalledProcessError: Command '['systemctl', 'start', 'pki-tomcatd@pki-tomcat.service']' returned non-zero exit status 1.
  File "/usr/lib/python3.6/site-packages/pki/server/pkidestroy.py", line 261, in main
    scriptlet.destroy(deployer)
  File "/usr/lib/python3.6/site-packages/pki/server/deployment/scriptlets/finalization.py", line 90, in destroy
    instance.start()
  File "/usr/lib/python3.6/site-packages/pki/server/__init__.py", line 260, in start
    subprocess.check_call(cmd)
  File "/usr/lib64/python3.6/subprocess.py", line 311, in check_call
    raise CalledProcessError(retcode, cmd)

Expected results:
Fix the CalledProcessError.

Additional info: 
https://pagure.io/freeipa/issue/8550
Attaching the logs for reference.

Comment 1 Florence Blanc-Renaud 2020-11-27 08:49:00 UTC
Upstream ticket:
https://pagure.io/freeipa/issue/8550

Comment 2 Florence Blanc-Renaud 2020-11-27 21:04:29 UTC
Investigations:
===============
IPA uninstaller stops all the services then calls "pkidestroy -i pki-tomcat -s KRA". pkidestroy performs the removal of the subsystem and re-starts pki-tomcatd at the end of pkidestroy command (https://github.com/dogtagpki/pki/blob/61297c6f97cb0e850a76307d1200b4a7c63f001c/base/server/python/pki/server/deployment/scriptlets/finalization.py#L88). The startup of the service fails and pki-destroy exits on error.

In RHEL 7.9 the call to pkidestroy prints the same warnings and error messages but pkidestroy exits with 0 (because the restart of the pki-tomcatd service succeeds).
With RHEL 8.4 pkidestroy exits with 1. The change of behavior can be traced to RHEL 8.1 with the introduction of ipa-pki-wait-running script:
when IPA configures a CA or KRA instance, it drops a config file in /etc/systemd/system/pki-tomcatd@pki-tomcat.service.d/ipa.conf:
-----
[Service]
ExecStartPost=/usr/libexec/ipa/ipa-pki-wait-running
-----
If the script ipa-pki-wait-running fails, systemd considers pki-tomcatd unit as failed.

The intent of ipa-pki-wait-running is to ensure that other services are not started before the CA is actually up and running (it may take ~10s between the startup and the CA availabity). To do so, ipa-pki-wait-running script tries to establish a connection to pki CA subsystem, but since the all services have been stopped at the beginning of the uninstallation (httpd is not running anymore), it fails. I am not sure why pkidestroy restarts the service even if it was stopped when pkidestroy was invoked.

A possible fix would be for pkidestroy NOT to restart the service if it was not running.
@edewata, what do you think?

Comment 6 Petr Čech 2021-01-06 09:07:36 UTC
*** Bug 1481949 has been marked as a duplicate of this bug. ***

Comment 7 Petr Čech 2021-01-06 09:18:34 UTC
*** Bug 1740702 has been marked as a duplicate of this bug. ***

Comment 11 Kaleem 2021-02-18 11:42:57 UTC
Verified based on following info

(1) Following log with reproduced issue which got caught in modified test test_full_backup_reinstall_restore_with_vault in build where issue not fixed


2021-02-18T11:03:08+0000 =========================== short test summary info ============================
2021-02-18T11:03:08+0000 PASSED ipatests/test_integration/test_backup_and_restore.py::TestBackupReinstallRestoreWithKRA::test_no_error_message_with_uninstall_ipa_with_kra
2021-02-18T11:03:08+0000 FAILED ipatests/test_integration/test_backup_and_restore.py::TestBackupReinstallRestoreWithKRA::test_full_backup_reinstall_restore_with_vault
2021-02-18T11:03:08+0000 ============== 1 failed, 1 passed, 1 warning in 786.58s (0:13:06) ==============

IPA Version : 

2021-02-18T10:47:56+0000 TASK [List installed IPA packages version] *************************************
2021-02-18T10:47:56+0000 ok: [master.testrelm.test] => (item=ipa-server) => 
2021-02-18T10:47:56+0000   msg:
2021-02-18T10:47:56+0000   - arch: x86_64
2021-02-18T10:47:56+0000     epoch: null
2021-02-18T10:47:56+0000     name: ipa-server
2021-02-18T10:47:56+0000     release: 1.module+el8.4.0+9665+c9815399
2021-02-18T10:47:56+0000     source: rpm
2021-02-18T10:47:56+0000     version: 4.9.1

(2) Issue not reproduced with build where issue got fixed 

test compose used : http://artifacts.osci.redhat.com/comp/rhel-8.4.0-mbs/9973-1386-idm/ 

2021-02-18T11:23:41+0000 =========================== short test summary info ============================
2021-02-18T11:23:41+0000 PASSED ipatests/test_integration/test_backup_and_restore.py::TestBackupReinstallRestoreWithKRA::test_full_backup_reinstall_restore_with_vault
2021-02-18T11:23:41+0000 PASSED ipatests/test_integration/test_backup_and_restore.py::TestBackupReinstallRestoreWithKRA::test_no_error_message_with_uninstall_ipa_with_kra
2021-02-18T11:23:41+0000 ================== 2 passed, 1 warning in 1263.47s (0:21:03) ===================


IPA Version :

2021-02-18T11:00:23+0000 TASK [List installed IPA packages version] *************************************
2021-02-18T11:00:23+0000 ok: [master.testrelm.test] => (item=ipa-server) => 
2021-02-18T11:00:23+0000   msg:
2021-02-18T11:00:23+0000   - arch: x86_64
2021-02-18T11:00:23+0000     epoch: null
2021-02-18T11:00:23+0000     name: ipa-server
2021-02-18T11:00:23+0000     release: 1.module+el8.4.0+9973+3d202164
2021-02-18T11:00:23+0000     source: rpm
2021-02-18T11:00:23+0000     version: 4.9.2

Comment 14 Florence Blanc-Renaud 2021-02-18 15:46:51 UTC
Test added upstream in test_integration/test_backup_and_restore.py::TestBackupReinstallRestoreWithKRA::test_no_error_message_with_uninstall_ipa_with_kra

master:
https://pagure.io/freeipa/c/5e49910bcf015f14533cfd7a788364aba7a7cbd3

Comment 15 Florence Blanc-Renaud 2021-02-19 07:42:45 UTC
Fixed upstream
ipa-4-9:
https://pagure.io/freeipa/c/6b25cd3241a5609b4d903d5697b8947fab403c90

Comment 16 Kaleem 2021-02-19 10:07:04 UTC
Verified using nightly compose RHEL-8.4.0-20210218.n.0

IPA Version:
------------

2021-02-19T09:24:16+0000 TASK [List installed IPA packages version] *************************************
2021-02-19T09:24:17+0000 ok: [master.testrelm.test] => (item=ipa-server) => 
2021-02-19T09:24:17+0000   msg:
2021-02-19T09:24:17+0000   - arch: x86_64
2021-02-19T09:24:17+0000     epoch: null
2021-02-19T09:24:17+0000     name: ipa-server
2021-02-19T09:24:17+0000     release: 1.module+el8.4.0+9973+3d202164
2021-02-19T09:24:17+0000     source: rpm
2021-02-19T09:24:17+0000     version: 4.9.2

Tests summary :
---------------
2021-02-19T09:47:55+0000 ------------- generated html file: file:///tmp/wp/twd/report.html --------------
2021-02-19T09:47:55+0000 =========================== short test summary info ============================
2021-02-19T09:47:55+0000 PASSED ipatests/test_integration/test_backup_and_restore.py::TestBackupReinstallRestoreWithKRA::test_full_backup_reinstall_restore_with_vault
2021-02-19T09:47:55+0000 PASSED ipatests/test_integration/test_backup_and_restore.py::TestBackupReinstallRestoreWithKRA::test_no_error_message_with_uninstall_ipa_with_kra
2021-02-19T09:47:55+0000 ================== 2 passed, 1 warning in 1296.98s (0:21:36) ===================


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