search

puppetlabs / puppetserver

Server automation framework and application
https://tickets.puppetlabs.com/browse/SERVER
Apache License 2.0
292 stars 235 forks source link

Puppetserver CA API race-condition(?) #2851

Closed anders-larsson closed 3 months ago

anders-larsson commented 4 months ago

Describe the Bug

Puppetserver CA API gets into a race-condition sometimes when the Certificate Status endpoint is used to first revoke and afterwards clean the certificate. When this occurs puppetserver will start throwing ERROR [p.r.core] Internal Server Error: java.io.FileNotFoundException: /path/to/cert.pem (No such file or directory) when attempts to revoke/clean said certificate occurs.

We have not seen this bug in 7.13.0 and earlier versions. First time it occurred was after updating to 8.4.0.

Expected Behavior

Certificate is successfully revoked and cleaned and can be re-used.

Steps to Reproduce

Steps to reproduce the behavior:

As stated earlier. This does not always happen.

Environment

Additional Context

It seems to help to have the node reach out to the CA and have a new certificate request recreated and then use API to sign it. Afterwards it works again as expected.

https://github.com/puppetlabs/puppetserver-ca-cli/issues/120 migh be related.

Example logs:

19/Apr/2024:11:33:35 +0000 "GET /puppet-ca/v1/certificate_status/client.domain.tld HTTP/1.1" 200 932 10.0.8.41 10.0.8.41 8140 18
2024-04-19 11:33:36,062 INFO  [p.p.certificate-authority] Entity revoker.domain.tld revoked 1 certificate: client.domain.tld.
19/Apr/2024:11:33:36 +0000 "PUT /puppet-ca/v1/certificate_status/client.domain.tld HTTP/1.1" 204 0 10.0.8.41 10.0.8.41 8140 48
2024-04-19 11:33:36,073 WARN  [p.p.certificate-authority] No certificate request for client.domain.tld at expected path /etc/puppetlabs/puppetserver/ca/requests/client.domain.tld.pem
19/Apr/2024:11:33:36 +0000 "DELETE /puppet-ca/v1/certificate_status/client.domain.tld HTTP/1.1" 204 162 10.0.8.41 10.0.8.41 8140 5
2024-04-19 11:33:36,315 INFO  [o.e.j.u.s.SslContextFactory] x509=X509@5e09380f(private key,h=[puppet, puppet.domain.tld, puppetca, puppetca.domain.tld],a=[],w=[]) for InternalSslContextFactory@56114dcd[provider=null,keyStore=null,trustStore=null]
2024-04-19 11:34:34,070 ERROR [p.r.core] Internal Server Error: java.io.FileNotFoundException: /etc/puppetlabs/puppetserver/ca/requests/client.domain.tld.pem (No such file or directory)
    at java.base/java.io.FileInputStream.open0(Native Method)
    at java.base/java.io.FileInputStream.open(FileInputStream.java:216)
    at java.base/java.io.FileInputStream.<init>(FileInputStream.java:157)
    at clojure.java.io$fn__11617.invokeStatic(io.clj:229)
    at clojure.java.io$fn__11617.invoke(io.clj:229)
    at clojure.java.io$fn__11569$G__11523__11576.invoke(io.clj:69)
    at clojure.java.io$fn__11629.invokeStatic(io.clj:258)
    at clojure.java.io$fn__11629.invoke(io.clj:254)
    at clojure.java.io$fn__11569$G__11523__11576.invoke(io.clj:69)
    at clojure.java.io$fn__11591.invokeStatic(io.clj:165)
    at clojure.java.io$fn__11591.invoke(io.clj:165)
    at clojure.java.io$fn__11530$G__11519__11537.invoke(io.clj:69)
    at clojure.java.io$reader.invokeStatic(io.clj:102)
    at clojure.java.io$reader.doInvoke(io.clj:86)
    at clojure.lang.RestFn.invoke(RestFn.java:410)
    at puppetlabs.ssl_utils.core$fn__21975$pem__GT_csr__21980$fn__21981.invoke(core.clj:727)
    at puppetlabs.ssl_utils.core$fn__21975$pem__GT_csr__21980.invoke(core.clj:721)
    at puppetlabs.puppetserver.certificate_authority$fn__39741$get_cert_or_csr_status__39746$fn__39750.invoke(certificate_authority.clj:2062)
    at puppetlabs.puppetserver.certificate_authority$fn__39741$get_cert_or_csr_status__39746.invoke(certificate_authority.clj:2051)
    at puppetlabs.services.ca.certificate_authority_core$certificate_status$fn__42391$fn__42408.invoke(certificate_authority_core.clj:471)
    at liberator.core$run_handler.invokeStatic(core.clj:176)
    at liberator.core$run_handler.invoke(core.clj:131)
    at liberator.core$handle_ok.invokeStatic(core.clj:224)
    at liberator.core$handle_ok.invoke(core.clj:224)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$multiple_representations_QMARK_.invokeStatic(core.clj:232)
    at liberator.core$multiple_representations_QMARK_.invoke(core.clj:232)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$put_to_existing_QMARK_.invokeStatic(core.clj:305)
    at liberator.core$put_to_existing_QMARK_.invoke(core.clj:305)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$post_to_existing_QMARK_.invokeStatic(core.clj:308)
    at liberator.core$post_to_existing_QMARK_.invoke(core.clj:308)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$method_patch_QMARK_.invokeStatic(core.clj:315)
    at liberator.core$method_patch_QMARK_.invoke(core.clj:315)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$method_delete_QMARK_.invokeStatic(core.clj:317)
    at liberator.core$method_delete_QMARK_.invoke(core.clj:317)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$if_modified_since_exists_QMARK_.invokeStatic(core.clj:337)
    at liberator.core$if_modified_since_exists_QMARK_.invoke(core.clj:337)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$if_none_match_exists_QMARK_.invokeStatic(core.clj:355)
    at liberator.core$if_none_match_exists_QMARK_.invoke(core.clj:355)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$if_unmodified_since_exists_QMARK_.invokeStatic(core.clj:375)
    at liberator.core$if_unmodified_since_exists_QMARK_.invoke(core.clj:375)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$if_match_exists_QMARK_.invokeStatic(core.clj:389)
    at liberator.core$if_match_exists_QMARK_.invoke(core.clj:389)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$exists_QMARK_.invokeStatic(core.clj:392)
    at liberator.core$exists_QMARK_.invoke(core.clj:392)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$processable_QMARK_.invokeStatic(core.clj:395)
    at liberator.core$processable_QMARK_.invoke(core.clj:395)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$accept_encoding_exists_QMARK_.invokeStatic(core.clj:416)
    at liberator.core$accept_encoding_exists_QMARK_.invoke(core.clj:416)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$accept_charset_exists_QMARK_.invokeStatic(core.clj:429)
    at liberator.core$accept_charset_exists_QMARK_.invoke(core.clj:429)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$accept_language_exists_QMARK_.invokeStatic(core.clj:443)
    at liberator.core$accept_language_exists_QMARK_.invoke(core.clj:443)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$accept_exists_QMARK_.invokeStatic(core.clj:456)
    at liberator.core$accept_exists_QMARK_.invoke(core.clj:456)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$is_options_QMARK_.invokeStatic(core.clj:473)
    at liberator.core$is_options_QMARK_.invoke(core.clj:473)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$valid_entity_length_QMARK_.invokeStatic(core.clj:476)
    at liberator.core$valid_entity_length_QMARK_.invoke(core.clj:476)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$known_content_type_QMARK_.invokeStatic(core.clj:479)
    at liberator.core$known_content_type_QMARK_.invoke(core.clj:479)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$valid_content_header_QMARK_.invokeStatic(core.clj:481)
    at liberator.core$valid_content_header_QMARK_.invoke(core.clj:481)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$allowed_QMARK_.invokeStatic(core.clj:484)
    at liberator.core$allowed_QMARK_.invoke(core.clj:484)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$authorized_QMARK_.invokeStatic(core.clj:487)
    at liberator.core$authorized_QMARK_.invoke(core.clj:487)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$malformed_QMARK_.invokeStatic(core.clj:490)
    at liberator.core$malformed_QMARK_.invoke(core.clj:490)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$method_allowed_QMARK_.invokeStatic(core.clj:493)
    at liberator.core$method_allowed_QMARK_.invoke(core.clj:493)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$uri_too_long_QMARK_.invokeStatic(core.clj:496)
    at liberator.core$uri_too_long_QMARK_.invoke(core.clj:496)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$known_method_QMARK_.invokeStatic(core.clj:499)
    at liberator.core$known_method_QMARK_.invoke(core.clj:499)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$service_available_QMARK_.invokeStatic(core.clj:502)
    at liberator.core$service_available_QMARK_.invoke(core.clj:502)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$initialize_context.invokeStatic(core.clj:504)
    at liberator.core$initialize_context.invoke(core.clj:504)
    at liberator.core$run_resource.invokeStatic(core.clj:595)
    at liberator.core$run_resource.invoke(core.clj:593)
    at puppetlabs.services.ca.certificate_authority_core$certificate_status$fn__42391.invoke(certificate_authority_core.clj:409)
    at compojure.response$fn__17255.invokeStatic(response.clj:33)
    at compojure.response$fn__17255.invoke(response.clj:21)
    at compojure.response$fn__17228$G__17223__17235.invoke(response.clj:6)
    at puppetlabs.services.ca.certificate_authority_core$fn__42441$web_routes__42446$fn__42447$fn__42448.invoke(certificate_authority_core.clj:548)
    at bidi.ring$fn__17042.invokeStatic(ring.cljc:25)
    at bidi.ring$fn__17042.invoke(ring.cljc:21)
    at bidi.ring$fn__17027$G__17022__17036.invoke(ring.cljc:16)
    at puppetlabs.comidi$make_handler$fn__18958.invoke(comidi.clj:245)
    at puppetlabs.trapperkeeper.authorization.ring_middleware$fn__25846$wrap_authorization_check__25851$fn__25852$fn__25853.invoke(ring_middleware.clj:293)
    at puppetlabs.ring_middleware.core$fn__23328$wrap_bad_request__23337$fn__23340$fn__23346.invoke(core.clj:187)
    at puppetlabs.puppetserver.ringutils$fn__36917$wrap_with_trapperkeeper_or_client_whitelist_authorization__36922$fn__36923$fn__36927.invoke(ringutils.clj:131)
    at puppetlabs.i18n.core$locale_negotiator$fn__4728.invoke(core.clj:361)
    at puppetlabs.ring_middleware.core$fn__23426$wrap_uncaught_errors__23435$fn__23438$fn__23443.invoke(core.clj:233)
    at puppetlabs.puppetserver.ringutils$wrap_with_puppet_version_header$fn__36906.invoke(ringutils.clj:90)
    at puppetlabs.ring_middleware.core$fn__23025$wrap_response_logging__23030$fn__23031$fn__23032.invoke(core.clj:53)
    at puppetlabs.trapperkeeper.services.webserver.jetty10_core$ring_handler$fn__29347.invoke(jetty10_core.clj:533)
    at puppetlabs.trapperkeeper.services.webserver.jetty10_core.proxy$org.eclipse.jetty.server.handler.HandlerWrapper$ff19274a.handle(Unknown Source)
    at jdk.internal.reflect.GeneratedMethodAccessor16.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:167)
    at clojure.lang.Reflector.invokeInstanceMethod(Reflector.java:102)
    at puppetlabs.trapperkeeper.services.webserver.normalized_uri_helpers$fn__28883$normalize_uri_handler__28888$fn__28889$fn__28890.invoke(normalized_uri_helpers.clj:73)
    at puppetlabs.trapperkeeper.services.webserver.normalized_uri_helpers.proxy$org.eclipse.jetty.server.handler.HandlerWrapper$ff19274a.handle(Unknown Source)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:192)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:141)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
    at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:822)
    at com.puppetlabs.trapperkeeper.services.webserver.jetty10.utils.MDCRequestLogHandler.handle(MDCRequestLogHandler.java:48)
    at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:173)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
    at org.eclipse.jetty.server.Server.handle(Server.java:563)
    at org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598)
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:558)
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:379)
    at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:146)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
    at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:421)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:390)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:277)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:199)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
    at java.base/java.lang.Thread.run(Thread.java:840)

19/Apr/2024:11:34:34 +0000 "GET /puppet-ca/v1/certificate_status/client.domain.tld HTTP/1.1" 500 163 10.0.8.41 10.0.8.41 8140 18
2024-04-19 11:34:46,538 ERROR [p.r.core] Internal Server Error: java.io.FileNotFoundException: /etc/puppetlabs/puppetserver/ca/requests/client.domain.tld.pem (No such file or directory)
    at java.base/java.io.FileInputStream.open0(Native Method)
    at java.base/java.io.FileInputStream.open(FileInputStream.java:216)
    at java.base/java.io.FileInputStream.<init>(FileInputStream.java:157)
    at clojure.java.io$fn__11617.invokeStatic(io.clj:229)
    at clojure.java.io$fn__11617.invoke(io.clj:229)
    at clojure.java.io$fn__11569$G__11523__11576.invoke(io.clj:69)
    at clojure.java.io$fn__11629.invokeStatic(io.clj:258)
    at clojure.java.io$fn__11629.invoke(io.clj:254)
    at clojure.java.io$fn__11569$G__11523__11576.invoke(io.clj:69)
    at clojure.java.io$fn__11591.invokeStatic(io.clj:165)
    at clojure.java.io$fn__11591.invoke(io.clj:165)
    at clojure.java.io$fn__11530$G__11519__11537.invoke(io.clj:69)
    at clojure.java.io$reader.invokeStatic(io.clj:102)
    at clojure.java.io$reader.doInvoke(io.clj:86)
    at clojure.lang.RestFn.invoke(RestFn.java:410)
    at puppetlabs.ssl_utils.core$fn__21975$pem__GT_csr__21980$fn__21981.invoke(core.clj:727)
    at puppetlabs.ssl_utils.core$fn__21975$pem__GT_csr__21980.invoke(core.clj:721)
    at puppetlabs.puppetserver.certificate_authority$fn__39741$get_cert_or_csr_status__39746$fn__39750.invoke(certificate_authority.clj:2062)
    at puppetlabs.puppetserver.certificate_authority$fn__39741$get_cert_or_csr_status__39746.invoke(certificate_authority.clj:2051)
    at puppetlabs.services.ca.certificate_authority_core$certificate_status$fn__42391$fn__42408.invoke(certificate_authority_core.clj:471)
    at liberator.core$run_handler.invokeStatic(core.clj:176)
    at liberator.core$run_handler.invoke(core.clj:131)
    at liberator.core$handle_ok.invokeStatic(core.clj:224)
    at liberator.core$handle_ok.invoke(core.clj:224)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$multiple_representations_QMARK_.invokeStatic(core.clj:232)
    at liberator.core$multiple_representations_QMARK_.invoke(core.clj:232)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$put_to_existing_QMARK_.invokeStatic(core.clj:305)
    at liberator.core$put_to_existing_QMARK_.invoke(core.clj:305)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$post_to_existing_QMARK_.invokeStatic(core.clj:308)
    at liberator.core$post_to_existing_QMARK_.invoke(core.clj:308)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$method_patch_QMARK_.invokeStatic(core.clj:315)
    at liberator.core$method_patch_QMARK_.invoke(core.clj:315)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$method_delete_QMARK_.invokeStatic(core.clj:317)
    at liberator.core$method_delete_QMARK_.invoke(core.clj:317)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$if_modified_since_exists_QMARK_.invokeStatic(core.clj:337)
    at liberator.core$if_modified_since_exists_QMARK_.invoke(core.clj:337)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$if_none_match_exists_QMARK_.invokeStatic(core.clj:355)
    at liberator.core$if_none_match_exists_QMARK_.invoke(core.clj:355)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$if_unmodified_since_exists_QMARK_.invokeStatic(core.clj:375)
    at liberator.core$if_unmodified_since_exists_QMARK_.invoke(core.clj:375)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$if_match_exists_QMARK_.invokeStatic(core.clj:389)
    at liberator.core$if_match_exists_QMARK_.invoke(core.clj:389)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$exists_QMARK_.invokeStatic(core.clj:392)
    at liberator.core$exists_QMARK_.invoke(core.clj:392)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$processable_QMARK_.invokeStatic(core.clj:395)
    at liberator.core$processable_QMARK_.invoke(core.clj:395)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$accept_encoding_exists_QMARK_.invokeStatic(core.clj:416)
    at liberator.core$accept_encoding_exists_QMARK_.invoke(core.clj:416)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$accept_charset_exists_QMARK_.invokeStatic(core.clj:429)
    at liberator.core$accept_charset_exists_QMARK_.invoke(core.clj:429)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$accept_language_exists_QMARK_.invokeStatic(core.clj:443)
    at liberator.core$accept_language_exists_QMARK_.invoke(core.clj:443)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$accept_exists_QMARK_.invokeStatic(core.clj:456)
    at liberator.core$accept_exists_QMARK_.invoke(core.clj:456)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$is_options_QMARK_.invokeStatic(core.clj:473)
    at liberator.core$is_options_QMARK_.invoke(core.clj:473)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$valid_entity_length_QMARK_.invokeStatic(core.clj:476)
    at liberator.core$valid_entity_length_QMARK_.invoke(core.clj:476)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$known_content_type_QMARK_.invokeStatic(core.clj:479)
    at liberator.core$known_content_type_QMARK_.invoke(core.clj:479)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$valid_content_header_QMARK_.invokeStatic(core.clj:481)
    at liberator.core$valid_content_header_QMARK_.invoke(core.clj:481)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$allowed_QMARK_.invokeStatic(core.clj:484)
    at liberator.core$allowed_QMARK_.invoke(core.clj:484)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$authorized_QMARK_.invokeStatic(core.clj:487)
    at liberator.core$authorized_QMARK_.invoke(core.clj:487)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$malformed_QMARK_.invokeStatic(core.clj:490)
    at liberator.core$malformed_QMARK_.invoke(core.clj:490)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$method_allowed_QMARK_.invokeStatic(core.clj:493)
    at liberator.core$method_allowed_QMARK_.invoke(core.clj:493)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$uri_too_long_QMARK_.invokeStatic(core.clj:496)
    at liberator.core$uri_too_long_QMARK_.invoke(core.clj:496)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$known_method_QMARK_.invokeStatic(core.clj:499)
    at liberator.core$known_method_QMARK_.invoke(core.clj:499)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$service_available_QMARK_.invokeStatic(core.clj:502)
    at liberator.core$service_available_QMARK_.invoke(core.clj:502)
    at liberator.core$decide.invokeStatic(core.clj:87)
    at liberator.core$decide.invoke(core.clj:74)
    at liberator.core$initialize_context.invokeStatic(core.clj:504)
    at liberator.core$initialize_context.invoke(core.clj:504)
    at liberator.core$run_resource.invokeStatic(core.clj:595)
    at liberator.core$run_resource.invoke(core.clj:593)
    at puppetlabs.services.ca.certificate_authority_core$certificate_status$fn__42391.invoke(certificate_authority_core.clj:409)
    at compojure.response$fn__17255.invokeStatic(response.clj:33)
    at compojure.response$fn__17255.invoke(response.clj:21)
    at compojure.response$fn__17228$G__17223__17235.invoke(response.clj:6)
    at puppetlabs.services.ca.certificate_authority_core$fn__42441$web_routes__42446$fn__42447$fn__42448.invoke(certificate_authority_core.clj:548)
    at bidi.ring$fn__17042.invokeStatic(ring.cljc:25)
    at bidi.ring$fn__17042.invoke(ring.cljc:21)
    at bidi.ring$fn__17027$G__17022__17036.invoke(ring.cljc:16)
    at puppetlabs.comidi$make_handler$fn__18958.invoke(comidi.clj:245)
    at puppetlabs.trapperkeeper.authorization.ring_middleware$fn__25846$wrap_authorization_check__25851$fn__25852$fn__25853.invoke(ring_middleware.clj:293)
    at puppetlabs.ring_middleware.core$fn__23328$wrap_bad_request__23337$fn__23340$fn__23346.invoke(core.clj:187)
    at puppetlabs.puppetserver.ringutils$fn__36917$wrap_with_trapperkeeper_or_client_whitelist_authorization__36922$fn__36923$fn__36927.invoke(ringutils.clj:131)
    at puppetlabs.i18n.core$locale_negotiator$fn__4728.invoke(core.clj:361)
    at puppetlabs.ring_middleware.core$fn__23426$wrap_uncaught_errors__23435$fn__23438$fn__23443.invoke(core.clj:233)
    at puppetlabs.puppetserver.ringutils$wrap_with_puppet_version_header$fn__36906.invoke(ringutils.clj:90)
    at puppetlabs.ring_middleware.core$fn__23025$wrap_response_logging__23030$fn__23031$fn__23032.invoke(core.clj:53)
    at puppetlabs.trapperkeeper.services.webserver.jetty10_core$ring_handler$fn__29347.invoke(jetty10_core.clj:533)
    at puppetlabs.trapperkeeper.services.webserver.jetty10_core.proxy$org.eclipse.jetty.server.handler.HandlerWrapper$ff19274a.handle(Unknown Source)
    at jdk.internal.reflect.GeneratedMethodAccessor16.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:167)
    at clojure.lang.Reflector.invokeInstanceMethod(Reflector.java:102)
    at puppetlabs.trapperkeeper.services.webserver.normalized_uri_helpers$fn__28883$normalize_uri_handler__28888$fn__28889$fn__28890.invoke(normalized_uri_helpers.clj:73)
    at puppetlabs.trapperkeeper.services.webserver.normalized_uri_helpers.proxy$org.eclipse.jetty.server.handler.HandlerWrapper$ff19274a.handle(Unknown Source)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:192)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:141)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
    at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:822)
    at com.puppetlabs.trapperkeeper.services.webserver.jetty10.utils.MDCRequestLogHandler.handle(MDCRequestLogHandler.java:48)
    at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:173)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
    at org.eclipse.jetty.server.Server.handle(Server.java:563)
    at org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598)
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:558)
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:379)
    at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:146)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
    at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:421)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:390)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:277)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:199)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
    at java.base/java.lang.Thread.run(Thread.java:840)

19/Apr/2024:11:34:46 +0000 "GET /puppet-ca/v1/certificate_status/client.domain.tld HTTP/1.1" 500 163 10.0.8.41 10.0.8.41 8140 16
anders-larsson commented 3 months ago

Example when executed on the CA server itself:

curl --tlsv1 \
  --cacert /etc/puppetlabs/puppet/ssl/certs/ca.pem \
  --cert /etc/puppetlabs/puppet/ssl/certs/puppet.pem \
  --key /etc/puppetlabs/puppet/ssl/private_keys/puppet.pem  \
  -k https://localhost:8140/puppet-ca/v1/certificate_status/client.domain.tld
Internal Server Error: java.io.FileNotFoundException: /etc/puppetlabs/puppetserver/ca/requests/client.domain.tld.pem (No such file or directory)

The system in question has had a certificate previously but no longer does. Neither a certificate or a certificate request file exists for the system on the CA. For other non-existing nodes it correctly returns Resource not found. if the resource does not exist.

One workaround seems to be having the node connect to the CA and hence generating a new CSR file. However, revoking PUT /puppet-ca/v1/certificate_status/client.domain.tld and cleaning it DELETE /puppet-ca/v1/certificate_status/client.domain.tld causes the problem to show itself again. Same thing happens regardless if a certificate or a CSR is going through this process.

As mentioned earlier this only happens sometimes and after it has started to happen it is persistent for that particular subject DN.

The CA is also much slower to process CSRs -> Cert (as also mentioned in linked issue).

jonathannewman commented 3 months ago

Thanks for your report. The issue is a simple logic problem that I will resolve shortly.

anders-larsson commented 3 months ago

@jonathannewman @justinstoller Hi, when will there be a release which includes this fix? Thanks.