From ferrao@versatushpc.com.br Tue Sep 26 22:46:20 2023 From: =?utf-8?q?Vin=C3=ADcius_Ferr=C3=A3o?= To: freeipa-users@lists.fedorahosted.org Subject: [Freeipa-users] IPA Upgrade failure during CA phase Date: Tue, 26 Sep 2023 22:46:03 +0000 Message-ID: <2800E5C3-FEAF-4013-81AA-4D6E236CFB5A@versatushpc.com.br> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="===============1951294347846281729==" --===============1951294347846281729== Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable Hello, After running yum update on a EL7.9 system FreeIPA was unable to start asking= for manual upgrade. So I performed the required command, without success: [root(a)headnode pki]# ipa-server-upgrade=20 Upgrading IPA:. Estimated time: 1 minute 30 seconds [1/9]: saving configuration [2/9]: disabling listeners [3/9]: enabling DS global lock [4/9]: disabling Schema Compat [5/9]: starting directory server [6/9]: updating schema [7/9]: upgrading server [8/9]: stopping directory server [9/9]: restoring configuration Done. Update complete Upgrading IPA services Upgrading the configuration of the IPA services [Verifying that root certificate is published] [Migrate CRL publish directory] CRL tree already moved [Verifying that CA proxy configuration is correct] IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ip= a-server-upgrade manually. CA did not start in 300.0s The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more i= nformation Tha /var/log/ipaupgrade.log file is 75k lines long, but looking at it after s= ome hours I think the relevant data is the following: 2023-09-26T22:22:23Z DEBUG stdout=3DERROR: No kra subsystem in instance pki-t= omcat. 2023-09-26T22:22:35Z DEBUG stderr=3D 2023-09-26T22:22:35Z DEBUG Starting pki-tomcatd(a)pki-tomcat. 2023-09-26T22:22:35Z DEBUG Starting external process 2023-09-26T22:22:35Z DEBUG args=3D/bin/systemctl start pki-tomcatd(a)pki-tomc= at.service 2023-09-26T22:22:36Z DEBUG Process finished, return code=3D0 2023-09-26T22:22:36Z DEBUG stdout=3D 2023-09-26T22:22:36Z DEBUG stderr=3D 2023-09-26T22:22:36Z DEBUG Starting external process 2023-09-26T22:22:36Z DEBUG args=3D/bin/systemctl is-active pki-tomcatd(a)pki-= tomcat.service 2023-09-26T22:22:36Z DEBUG Process finished, return code=3D0 2023-09-26T22:22:36Z DEBUG stdout=3Dactive 2023-09-26T22:22:36Z DEBUG stderr=3D 2023-09-26T22:22:36Z DEBUG wait_for_open_ports: localhost [8080, 8443] timeou= t 300 2023-09-26T22:22:36Z DEBUG waiting for port: 8080 2023-09-26T22:22:36Z DEBUG Failed to connect to port 8080 tcp on ::1 2023-09-26T22:22:36Z DEBUG Failed to connect to port 8080 tcp on 127.0.0.1 2023-09-26T22:22:38Z DEBUG SUCCESS: port: 8080 2023-09-26T22:22:38Z DEBUG waiting for port: 8443 2023-09-26T22:22:38Z DEBUG SUCCESS: port: 8443 2023-09-26T22:22:38Z DEBUG Start of pki-tomcatd(a)pki-tomcat.service complete 2023-09-26T22:22:38Z DEBUG Waiting until the CA is running 2023-09-26T22:22:38Z DEBUG request POST http://DOMAIN:8080/ca/admin/ca/getSta= tus 2023-09-26T22:22:38Z DEBUG request body '' 2023-09-26T22:22:42Z DEBUG response status 500 2023-09-26T22:22:42Z DEBUG response headers Server: Apache-Coyote/1.1 2023-09-26T22:22:42Z DEBUG response body 'Apache Tomcat/7.= 0.76 - Error report

HTTP Status 500 - Subsystem unavailable

type Exception report

<= b>message Subsystem unavailable

description The se= rver encountered an internal error that prevented it from fulfilling this req= uest.

exception

javax.ws.rs.ServiceUnavailableException=
: Subsystem unavailable\n\tcom.netscape.cms.tomcat.ProxyRealm.findSecurityCon=
straints(ProxyRealm.java:145)\n\torg.apache.catalina.authenticator.Authentica=
torBase.invoke(AuthenticatorBase.java:492)\n\torg.apache.catalina.valves.Erro=
rReportValve.invoke(ErrorReportValve.java:103)\n\torg.apache.catalina.valves.=
AccessLogValve.invoke(AccessLogValve.java:962)\n\torg.apache.catalina.connect=
or.CoyoteAdapter.service(CoyoteAdapter.java:445)\n\torg.apache.coyote.http11.=
AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)\n\torg.apa=
che.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtoco=
l.java:637)\n\torg.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIo=
Endpoint.java:316)\n\tjava.util.concurrent.ThreadPoolExecutor.runWorker(Threa=
dPoolExecutor.java:1149)\n\tjava.util.concurrent.ThreadPoolExecutor$Worker.ru=
n(ThreadPoolExecutor.java:624)\n\torg.apache.tomcat.util.threads.TaskThread$W=
rappingRunnable.run(TaskThread.java:61)\n\tjava.lang.Thread.run(Thread.java:7=
50)\n

note The full stack trace of the root cause is av= ailable in the Apache Tomcat/7.0.76 logs.

Apache Tomcat/7.0.76

' 2023-09-26T22:22:42Z DEBUG The CA status is: check interrupted due to error: = Retrieving CA status failed with status 500 2023-09-26T22:22:42Z DEBUG Waiting for CA to start=E2=80=A6 So it seems that the CA is broken. On /var/log/pki; I can find this: cat pki-server-upgrade-10.5.* Upgrading PKI server configuration at Mon Sep 18 01:38:43 -03 2023. Upgrading from version 10.5.9 to 10.5.17: 1. Update audit events Upgrading from version 10.5.17 to 10.5.18: 1. Fix EC admin certificate profile Upgrading from version 10.5.18 to 10.5.18: 1. Add caAuditSigningCert profile 2. Fix the authentication for caServerKeygen_UserCert profile ERROR: [Errno 2] No such file or directory: '/var/lib/pki/pki-tomcat/ca/profi= les/ca/caServerKeygen_UserCert.cfg' Failed upgrading pki-tomcat/ca subsystem. Upgrade failed in pki-tomcat/ca: [Errno 2] No such file or directory: '/var/l= ib/pki/pki-tomcat/ca/profiles/ca/caServerKeygen_UserCert.cfg' Continue (Yes/No) [Y]? Traceback (most recent call last): File "/sbin/pki-server-upgrade", line 211, in main(sys.argv) File "/sbin/pki-server-upgrade", line 204, in main upgrader.upgrade() File "/usr/lib/python2.7/site-packages/pki/upgrade.py", line 623, in upgrade self.upgrade_version(version) File "/usr/lib/python2.7/site-packages/pki/upgrade.py", line 613, in upgrad= e_version case_sensitive=3DFalse).lower() File "/usr/lib/python2.7/site-packages/pki/__init__.py", line 142, in read_= text value =3D input(message) EOFError: EOF when reading a line But nothing more. Any ideia of what I should be looking for? Thanks. --===============1951294347846281729==-- From rcritten@redhat.com Wed Sep 27 22:20:09 2023 From: Rob Crittenden To: freeipa-users@lists.fedorahosted.org Subject: [Freeipa-users] Re: IPA Upgrade failure during CA phase Date: Wed, 27 Sep 2023 18:19:52 -0400 Message-ID: <59a6398f-092a-620d-5f91-58652218963e@redhat.com> In-Reply-To: <2800E5C3-FEAF-4013-81AA-4D6E236CFB5A@versatushpc.com.br> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="===============7743473667758418036==" --===============7743473667758418036== Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable Vin=C3=ADcius Ferr=C3=A3o via FreeIPA-users wrote: > Hello, >=20 > After running yum update on a EL7.9 system FreeIPA was unable to start aski= ng for manual upgrade. >=20 > So I performed the required command, without success: >=20 > [root(a)headnode pki]# ipa-server-upgrade=20 > Upgrading IPA:. Estimated time: 1 minute 30 seconds > [1/9]: saving configuration > [2/9]: disabling listeners > [3/9]: enabling DS global lock > [4/9]: disabling Schema Compat > [5/9]: starting directory server > [6/9]: updating schema > [7/9]: upgrading server > [8/9]: stopping directory server > [9/9]: restoring configuration > Done. > Update complete > Upgrading IPA services > Upgrading the configuration of the IPA services > [Verifying that root certificate is published] > [Migrate CRL publish directory] > CRL tree already moved > [Verifying that CA proxy configuration is correct] > IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command = ipa-server-upgrade manually. > CA did not start in 300.0s > The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more= information >=20 >=20 > Tha /var/log/ipaupgrade.log file is 75k lines long, but looking at it after= some hours I think the relevant data is the following: >=20 > 2023-09-26T22:22:23Z DEBUG stdout=3DERROR: No kra subsystem in instance pki= -tomcat. > 2023-09-26T22:22:35Z DEBUG stderr=3D > 2023-09-26T22:22:35Z DEBUG Starting pki-tomcatd(a)pki-tomcat. > 2023-09-26T22:22:35Z DEBUG Starting external process > 2023-09-26T22:22:35Z DEBUG args=3D/bin/systemctl start pki-tomcatd(a)pki-to= mcat.service > 2023-09-26T22:22:36Z DEBUG Process finished, return code=3D0 > 2023-09-26T22:22:36Z DEBUG stdout=3D > 2023-09-26T22:22:36Z DEBUG stderr=3D > 2023-09-26T22:22:36Z DEBUG Starting external process > 2023-09-26T22:22:36Z DEBUG args=3D/bin/systemctl is-active pki-tomcatd(a)pk= i-tomcat.service > 2023-09-26T22:22:36Z DEBUG Process finished, return code=3D0 > 2023-09-26T22:22:36Z DEBUG stdout=3Dactive > 2023-09-26T22:22:36Z DEBUG stderr=3D > 2023-09-26T22:22:36Z DEBUG wait_for_open_ports: localhost [8080, 8443] time= out 300 > 2023-09-26T22:22:36Z DEBUG waiting for port: 8080 > 2023-09-26T22:22:36Z DEBUG Failed to connect to port 8080 tcp on ::1 > 2023-09-26T22:22:36Z DEBUG Failed to connect to port 8080 tcp on 127.0.0.1 > 2023-09-26T22:22:38Z DEBUG SUCCESS: port: 8080 > 2023-09-26T22:22:38Z DEBUG waiting for port: 8443 > 2023-09-26T22:22:38Z DEBUG SUCCESS: port: 8443 > 2023-09-26T22:22:38Z DEBUG Start of pki-tomcatd(a)pki-tomcat.service comple= te > 2023-09-26T22:22:38Z DEBUG Waiting until the CA is running > 2023-09-26T22:22:38Z DEBUG request POST http://DOMAIN:8080/ca/admin/ca/getS= tatus > 2023-09-26T22:22:38Z DEBUG request body '' > 2023-09-26T22:22:42Z DEBUG response status 500 > 2023-09-26T22:22:42Z DEBUG response headers Server: Apache-Coyote/1.1 > 2023-09-26T22:22:42Z DEBUG response body 'Apache Tomcat/= 7.0.76 - Error report

HTTP Status 500 - Subsystem unavailable=

type Exception report

message Subsystem unavailable

description The = server encountered an internal error that prevented it from fulfilling this r= equest.

exception

javax.ws.rs.ServiceUnavailableExcepti=
on: Subsystem unavailable\n\tcom.netscape.cms.tomcat.ProxyRealm.findSecurityC=
onstraints(ProxyRealm.java:145)\n\torg.apache.catalina.authenticator.Authenti=
catorBase.invoke(AuthenticatorBase.java:492)\n\torg.apache.catalina.valves.Er=
rorReportValve.invoke(ErrorReportValve.java:103)\n\torg.apache.catalina.valve=
s.AccessLogValve.invoke(AccessLogValve.java:962)\n\torg.apache.catalina.conne=
ctor.CoyoteAdapter.service(CoyoteAdapter.java:445)\n\torg.apache.coyote.http1=
1.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)\n\torg.a=
pache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProto=
col.java:637)\n\torg.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(J=
IoEndpoint.java:316)\n\tjava.util.concurrent.ThreadPoolExecutor.runWorker(Thr=
eadPoolExecutor.java:1149)\n\tjava.util.concurrent.ThreadPoolExecutor$Worker.=
run(ThreadPoolExecutor.java:624)\n\torg.apache.tomcat.util.threads.TaskThread=
$WrappingRunnable.run(TaskThread.java:61)\n\tjava.lang.Thread.run(Thread.java=
:750)\n

note The full stack trace of the root cause is = available in the Apache Tomcat/7.0.76 logs.

Apache Tomcat/7.0.76

' > 2023-09-26T22:22:42Z DEBUG The CA status is: check interrupted due to error= : Retrieving CA status failed with status 500 > 2023-09-26T22:22:42Z DEBUG Waiting for CA to start=E2=80=A6 >=20 >=20 >=20 > So it seems that the CA is broken. >=20 > On /var/log/pki; I can find this: >=20 > cat pki-server-upgrade-10.5.* > Upgrading PKI server configuration at Mon Sep 18 01:38:43 -03 2023. > Upgrading from version 10.5.9 to 10.5.17: > 1. Update audit events >=20 > Upgrading from version 10.5.17 to 10.5.18: > 1. Fix EC admin certificate profile >=20 > Upgrading from version 10.5.18 to 10.5.18: > 1. Add caAuditSigningCert profile > 2. Fix the authentication for caServerKeygen_UserCert profile > ERROR: [Errno 2] No such file or directory: '/var/lib/pki/pki-tomcat/ca/pro= files/ca/caServerKeygen_UserCert.cfg' > Failed upgrading pki-tomcat/ca subsystem. >=20 > Upgrade failed in pki-tomcat/ca: [Errno 2] No such file or directory: '/var= /lib/pki/pki-tomcat/ca/profiles/ca/caServerKeygen_UserCert.cfg' >=20 > Continue (Yes/No) [Y]? Traceback (most recent call last): > File "/sbin/pki-server-upgrade", line 211, in > main(sys.argv) > File "/sbin/pki-server-upgrade", line 204, in main > upgrader.upgrade() > File "/usr/lib/python2.7/site-packages/pki/upgrade.py", line 623, in upgr= ade > self.upgrade_version(version) > File "/usr/lib/python2.7/site-packages/pki/upgrade.py", line 613, in upgr= ade_version > case_sensitive=3DFalse).lower() > File "/usr/lib/python2.7/site-packages/pki/__init__.py", line 142, in rea= d_text > value =3D input(message) > EOFError: EOF when reading a line >=20 >=20 >=20 > But nothing more. >=20 >=20 >=20 >=20 > Any ideia of what I should be looking for? I'd suggest looking at the pki debug log and/or selftests.log. This may not be related to the upgrade, you're just noticing because the services restarted. rob --===============7743473667758418036==--