freeipa / freeipa-healthcheck

Check the health of a freeIPA installation
GNU General Public License v3.0
50 stars 28 forks source link

"Internal error testing KRA clone. KRA clone problem detected" from ipa-healthceck; possibly caused by "permission denied for the resource certServer.kra.keys on operation execute" #241

Closed yrro closed 2 years ago

yrro commented 2 years ago

With pki-server-10.11.2-2.module+el8.5.0+12735+8eb38ccc.noarch, i'm seeing:

[root@ipa5 ~]# ipa-healthcheck --failures-only --source pki.server.healthcheck.clones.connectivity_and_data --check ClonesConnectivyAndDataCheck
Internal error testing KRA clone. KRA clone problem detected  Host: ipa3.ipa.example.com Port: 443
[
  {
    "source": "pki.server.healthcheck.clones.connectivity_and_data",
    "check": "ClonesConnectivyAndDataCheck",
    "result": "ERROR",
    "uuid": "2ae6452a-f022-485f-afee-8e0060506023",
    "when": "20211211114202Z",
    "duration": "5.352505",
    "kw": {
      "status": "ERROR:  pki-tomcat : Internal error testing KRA clone. Host: ipa3.ipa.example.com Port: 443"
    }
  }
]

I get exactly the same when I run the test on ipa3 as well. Those are the only two ipa servers I have at the moment.

The following is logged when the healthcheck is run:

[root@ipa3 ~]# tail -n0 -F /var/log/pki/pki-tomcat/kra/debug.2021-12-11.log
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: PKIRealm: Authenticating certificate chain:
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: PKIRealm: - CN=CA Subsystem, O=IPA.EXAMPLE.COM
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: CertUserDBAuthentication: UID CA-ipa0.ipa.example.com-443 authenticated.
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: PKIRealm: User ID: CA-ipa0.ipa.example.com-443
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: UGSubsystem: retrieving user uid=CA-ipa0.ipa.example.com-443,ou=People,o=kra,o=ipaca
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: PKIRealm: User DN: uid=CA-ipa0.ipa.example.com-443,ou=people,o=kra,o=ipaca
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: PKIRealm: Roles:
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: PKIRealm: - Trusted Managers
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: AAclAuthz: Granting login permission for certServer.kra.account
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: Creating session 4C23D7ABDF061978CA3963C70C205529
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: Principal:
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: - ID: CA-ipa0.ipa.example.com-443
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: - Full Name: CA-ipa0.ipa.example.com-443
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: - Email: 
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO: - Roles:
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-10] INFO:   - Trusted Managers
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-2] INFO: UGSubsystem: retrieving user uid=CA-ipa0.ipa.example.com-443,ou=People,o=kra,o=ipaca
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-2] SEVERE: checkPermission(): permission denied for the resource certServer.kra.keys on operation execute
2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-2] SEVERE: AAclAuthz: Authorization Failed
certServer.kra.keys does not have permission to execute
    at com.netscape.cms.authorization.AAclAuthz.checkPermission(AAclAuthz.java:538)
    at com.netscape.cms.authorization.AAclAuthz.authorize(AAclAuthz.java:849)
    at com.netscape.cmscore.authorization.AuthzSubsystem.authorize(AuthzSubsystem.java:250)
    at com.netscape.cmscore.authorization.AuthzSubsystem.authorize(AuthzSubsystem.java:255)
    at org.dogtagpki.server.rest.ACLInterceptor.filter(ACLInterceptor.java:261)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:263)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:406)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:213)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:228)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
    at sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
    at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:314)
    at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:170)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:225)
    at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:47)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:149)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:145)
    at java.security.AccessController.doPrivileged(Native Method)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:144)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
    at sun.reflect.GeneratedMethodAccessor47.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
    at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:314)
    at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:253)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:191)
    at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:47)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:149)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:145)
    at java.security.AccessController.doPrivileged(Native Method)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:144)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:666)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:678)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
    at org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:428)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1598)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)

2021-12-11 11:47:06 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-2] SEVERE: AAclAuthz: Authorization failed on resource: certServer.kra.keys, operation: execute

This is similar to #212 but in that issue there is a different message printed to stderr before the results are printed to stdout.

cc @rcritten

yrro commented 2 years ago

I wonder if this could be caused by the same thing that caused me to bump into https://github.com/dogtagpki/pki/issues/3877, i.e. the KRA related certificates in /var/lib/pki/pki-tomcat/conf/kra/CS.cfg don't match the certs stored in /etc/pki/pki-tomcat/alias.

Digging further into what's going on it looks like the certs from that NSS DB do match what I find in the directory under cn=ca_renewal,cn=ipa,cn=etc,dc=ipa,dc=example,dc=com.

So I tried to find out what is supposed to be updating /var/lib/pki/pki-tomcat/conf/kra/CS.cfg and... I can only see that path referred to (as ipaplatform.paths.paths.KRA_CS_CFG_PATH) by only a couple of files:

ipaplatform/base/paths.py:    KRA_CS_CFG_PATH = "/var/lib/pki/pki-tomcat/conf/kra/CS.cfg"
ipaserver/install/ipa_cert_fix.py:                                          paths.KRA_CS_CFG_PATH),
ipaserver/install/ipa_cert_fix.py:                                     paths.KRA_CS_CFG_PATH),
ipaserver/install/ipa_cert_fix.py:                                       paths.KRA_CS_CFG_PATH),
ipaserver/install/krainstance.py:            config=paths.KRA_CS_CFG_PATH,
ipaserver/install/server/upgrade.py:                paths.KRA_CS_CFG_PATH,

I don't see any of those paths/modules referred to by /usr/libexec/ipa/certmonger/renew_ca_cert which is set as the post-save command for the KRA certificates:

+ sudo getcert list -n 'auditSigningCert cert-pki-kra'
Number of certificates and requests being tracked: 12.
Request ID '20210518174639':
    status: MONITORING
    stuck: no
    key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-kra',token='NSS Certificate DB',pin set
    certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-kra',token='NSS Certificate DB'
    CA: dogtag-ipa-ca-renew-agent
    issuer: CN=Certificate Authority,O=IPA.EXAMPLE.COM
    subject: CN=KRA Audit,O=IPA.EXAMPLE.COM
    expires: 2023-03-31 21:42:08 UTC
    key usage: digitalSignature,nonRepudiation
    profile: caAuditSigningCert
    pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
    post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "auditSigningCert cert-pki-kra"
    track: yes
    auto-renew: yes
+ sudo getcert list -n 'storageCert cert-pki-kra'
Number of certificates and requests being tracked: 12.
Request ID '20210518174641':
    status: MONITORING
    stuck: no
    key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB',pin set
    certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB'
    CA: dogtag-ipa-ca-renew-agent
    issuer: CN=Certificate Authority,O=IPA.EXAMPLE.COM
    subject: CN=KRA Storage Certificate,O=IPA.EXAMPLE.COM
    expires: 2023-03-31 21:42:23 UTC
    key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
    eku: id-kp-clientAuth
    profile: caStorageCert
    pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
    post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "storageCert cert-pki-kra"
    track: yes
    auto-renew: yes
+ sudo getcert list -n 'transportCert cert-pki-kra'
Number of certificates and requests being tracked: 12.
Request ID '20210518174640':
    status: MONITORING
    stuck: no
    key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='transportCert cert-pki-kra',token='NSS Certificate DB',pin set
    certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='transportCert cert-pki-kra',token='NSS Certificate DB'
    CA: dogtag-ipa-ca-renew-agent
    issuer: CN=Certificate Authority,O=IPA.EXAMPLE.COM
    subject: CN=KRA Transport Certificate,O=IPA.EXAMPLE.COM
    expires: 2023-03-31 21:42:06 UTC
    key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
    eku: id-kp-clientAuth
    profile: caTransportCert
    pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
    post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "transportCert cert-pki-kra"
    track: yes
    auto-renew: yes

Bit confused now...

flo-renaud commented 2 years ago

Hi @yrro looks like you're hitting issue https://pagure.io/freeipa/issue/8582 / dogtagpki/pki#3608

yrro commented 2 years ago

I wonder if this could be caused by the same thing that caused me to bump into [...]

No, it's unrelated.

looks like you're hitting issue

Yes I think you're right. Closing this.