[Bug]: Long delay in cleaning certificates - java.util.concurrent.TimeoutException

[dotconfig404]

Is this a critical security issue?

• This is not a security issue.

Describe the Bug

When deleting/ cleaning certificates it takes about 30s instead of 1s. This seems to be a openvox related issue, as it does not happen using non-openvox packages. Tested on several distros and several versions, including 8.8.1, 8.8.0, 7.18.2

It appears to be some sort of timeout, perhaps it is related to #24 ?

This timeout happens also when a node creates a CSR, so it is not related to the puppetserver CLI.

Expected Behavior

Should clean and generate certificates in less than a second.

Steps to Reproduce

Install openvox-server package for ubuntu: 8.8.1-1+ubuntu24.04
Configure puppet.conf:

[server]
dns_alt_names = mainstation
autosign = true
ca_server = mainstation

Run puppetserver ca setup
Start puppetserver using puppetserver foreground
Generate a certificate using puppetserver ca generate --certname asdf
Clean certificate using puppetserver ca clean --certname asdf

Environment

puppetserver 8.8.1, 8.8.0, 7.18.2
Ubuntu 24.04
Rocky 8

Additional Context

Full debug log after calling puppetserver ca clean
https://pastebin.com/pPXjKvfk

Relevant log output

-1},g=HttpGenerator@24365f32{s=START}]=>HttpChannelOverHttp@5fb5a6a5{s=HttpChannelState@207803f3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}]}}
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:170)
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:112)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
2025-06-28T14:51:34.623+02:00 DEBUG [Connector-Scheduler-52e9c5b1-1] [o.e.j.i.s.SslConnection] onFillableFail SslConnection@44b1abcc::SocketChannelEndPoint@27d518ad[{l=/127.0.1.1:8140,r=/127.0.0.1:52624,OPEN,fill=-,flush=-,to=30002/30000}{io=1/1,kio=1,kro=1}]->[SslConnection@44b1abcc{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>{l=/127.0.1.1:8140,r=/127.0.0.1:52624,OPEN,fill=FI,flush=-,to=30002/30000}=>HttpConnection@2f676721[p=HttpParser{s=START,0 of -1},g=HttpGenerator@24365f32{s=START}]=>HttpChannelOverHttp@5fb5a6a5{s=HttpChannelState@207803f3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}]
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:170)
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:112)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
2025-06-28T14:51:34.623+02:00 DEBUG [Connector-Scheduler-52e9c5b1-1] [o.e.j.i.FillInterest] onFail FillInterest@307c7afa{ReadCallback@1b8d7d81{HttpConnection@2f676721::DecryptedEndPoint@71dd1c1e[{l=/127.0.1.1:8140,r=/127.0.0.1:52624,OPEN,fill=FI,flush=-,to=30002/30000}]}}
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:170)
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:112)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
2025-06-28T14:51:34.623+02:00 DEBUG [Connector-Scheduler-52e9c5b1-1] [o.e.j.h.HttpParser] close HttpParser{s=START,0 of -1}
2025-06-28T14:51:34.623+02:00 DEBUG [Connector-Scheduler-52e9c5b1-1] [o.e.j.h.HttpParser] START --> CLOSE
2025-06-28T14:51:34.623+02:00 DEBUG [Connector-Scheduler-52e9c5b1-1] [o.e.j.i.AbstractConnection] HttpConnection@2f676721::DecryptedEndPoint@71dd1c1e[{l=/127.0.1.1:8140,r=/127.0.0.1:52624,OPEN,fill=-,flush=-,to=30002/30000}] onFillInterestedFailed {}
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:170)
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:112)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)

[bastelfreak]

Hey, thanks for raising this issue. Have you tried to disable dropsonde? You can do that in /etc/puppetlabs/puppetserver/conf.d/puppetserver.conf and add:

dropsonde: {
    enabled: false
}

[dotconfig404]

Hi, yes, unfortunately that doesn't seem to change anything.

[dotconfig404]

also tried to disable some other stuff to no avail:

http-client: {
    metrics-enabled: false
}
profiler: {
    enabled: false
}

[bastelfreak]

I don't have a system to test right now. Can you try to disable the whole analytics stuff by removing puppetlabs.services.analytics.analytics-service/analytics-service from the puppetserver config file (like we proposed it in #9)?

[bastelfreak]

I'm able to reproduce your error:

bootstrap:

dnf install https://yum.voxpupuli.org/openvox8-release-el-9.noarch.rpm
dnf install openvox-server

packages:

root@pe ~ # rpm -qa | grep openvox
openvox8-release-1-1.el9.noarch
openvox-agent-8.19.2-1.el9.x86_64
openvox-server-8.8.1-1.el9.noarch
root@pe ~ # 

increased debug logging:

diff --git a/logback.xml b/etc/puppetlabs/puppetserver/logback.xml
index d8a5cee..c587357 100644
--- a/logback.xml
+++ b/etc/puppetlabs/puppetserver/logback.xml
@@ -44,9 +44,9 @@
         <appender-ref ref="STATUS"/>
     </logger>
 
-    <logger name="org.eclipse.jetty" level="INFO"/>
-    <logger name="org.apache.http" level="INFO"/>
-    <logger name="jruby" level="info"/>
+    <logger name="org.eclipse.jetty" level="DEBUG"/>
+    <logger name="org.apache.http" level="DEBUG"/>
+    <logger name="jruby" level="debug"/>
 
     <root level="info">
         <!--<appender-ref ref="STDOUT"/>-->

lower jruby instances to have less debug logs:

sed -i 's/#max-active-instances: 1/max-active-instances: 1/g' /etc/puppetlabs/puppetserver/conf.d/puppetserver.conf

start server:

systemctl start puppetserver

Generate certificate:

root@pe ~ # puppetserver ca generate --certname foobar.local
Successfully saved private key for foobar.local to /etc/puppetlabs/puppet/ssl/private_keys/foobar.local.pem
Successfully saved public key for foobar.local to /etc/puppetlabs/puppet/ssl/public_keys/foobar.local.pem
Successfully submitted certificate request for foobar.local
Error:
    Signed certificate foobar.local could not be found on the CA
Successfully signed certificate request for foobar.local
Successfully saved certificate for foobar.local to /etc/puppetlabs/puppet/ssl/certs/foobar.local.pem
root@pe ~ # 

revoke it:

root@pe ~ # time puppetserver ca clean --certname foobar.local
Certificate for foobar.local has been revoked
Cleaned files related to foobar.local

real	0m30.613s
user	0m0.380s
sys	0m0.049s

root@pe ~ # 

the generated logs are quite long: https://p.bastelfreak.de/6lR/

I'm a bit surprised that dropsonde is still working:

root@pe ~ # grep dropsonde /var/log/puppetlabs/puppetserver/puppetserver.log 
2025-06-28T18:37:37.378Z INFO  [3bd961eb-caaa-49a9-a88a-d58dbcf830f0_Worker-4] [p.s.a.dropsonde] Successfully submitted module metrics via Dropsonde.
2025-06-28T18:39:05.559Z INFO  [8f515501-8888-4596-8f8a-df79930c8f1b_Worker-4] [p.s.a.dropsonde] Successfully submitted module metrics via Dropsonde.
2025-06-28T18:44:28.613Z INFO  [ebdc14a1-de5b-42e7-9fb7-4887ac4640c1_Worker-4] [p.s.a.dropsonde] Successfully submitted module metrics via Dropsonde.
2025-06-28T18:46:37.024Z INFO  [bdcf3e42-84ee-483b-a55d-42934ae41527_Worker-4] [p.s.a.dropsonde] Successfully submitted module metrics via Dropsonde.
root@pe ~ # 

disabling dropsonde:

diff --git a/puppetserver.conf b/etc/puppetlabs/puppetserver/conf.d/puppetserver.conf
index f2d875b..7518db9 100644
--- a/puppetserver.conf
+++ b/etc/puppetlabs/puppetserver/conf.d/puppetserver.conf
@@ -75,7 +75,7 @@ profiler: {
 
 # settings related to submitting module metrics via Dropsonde
 dropsonde: {
-    # enabled: true
+    enabled: false
 
     # How long, in seconds, to wait between dropsonde submissions
     # Defaults to one week.

verify it's disabled:

root@pe ~ # systemctl restart puppetserver && grep dropsonde /var/log/puppetlabs/puppetserver/puppetserver.log | tail -n1
2025-06-28T19:01:08.739Z INFO  [async-dispatch-2] [p.s.a.analytics-service] Not submitting module metrics via Dropsonde -- submission is disabled. Enable this feature by setting `dropsonde.enabled` to true in Puppet Server's config.
root@pe ~ # 

still takes too long:

root@pe ~ # time puppetserver ca clean --certname foobar3.local
Certificate for foobar3.local has been revoked
Cleaned files related to foobar3.local

real	0m30.799s
user	0m0.411s
sys	0m0.043s
root@pe ~ # 

[dotconfig404]

I don't have a system to test right now. Can you try to disable the whole analytics stuff by removing puppetlabs.services.analytics.analytics-service/analytics-service from the puppetserver config file (like we proposed it in #9)?

you probably tested it already, but this did not work unfortunately

[bastelfreak]

you probably tested it already, but this did not work unfortunately

indeed.

disabling it:

diff --git a/bootstrap.cfg b/opt/puppetlabs/server/apps/puppetserver/config/services.d/bootstrap.cfg
index b025703..e32149c 100644
--- a/bootstrap.cfg
+++ b/opt/puppetlabs/server/apps/puppetserver/config/services.d/bootstrap.cfg
@@ -14,4 +14,3 @@ puppetlabs.trapperkeeper.services.status.status-service/status-service
 puppetlabs.trapperkeeper.services.metrics.metrics-service/metrics-service
 puppetlabs.trapperkeeper.services.metrics.metrics-service/metrics-webservice
 puppetlabs.services.jruby.jruby-metrics-service/jruby-metrics-service
-puppetlabs.services.analytics.analytics-service/analytics-service

Still takes 30 seconds

[bastelfreak]

single exception:

2025-06-28T19:42:06.345Z DEBUG [qtp1372057593-49] [o.e.j.i.s.SslConnection] DecryptedEndPoint@7abd3da3[{l=/[0:0:0:0:0:0:0:1]:8140,r=/[0:0:0:0:0:0:0:1]:48264,CLOSED,fill=-,flush=-,to=165/30000}] stored flush exception
org.eclipse.jetty.io.EofException: null
        at org.eclipse.jetty.io.SocketChannelEndPoint.flush(SocketChannelEndPoint.java:116)
        at org.eclipse.jetty.io.ssl.SslConnection.networkFlush(SslConnection.java:486)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.flush(SslConnection.java:1115)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.doShutdownOutput(SslConnection.java:1338)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.doClose(SslConnection.java:1434)
        at org.eclipse.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:258)
        at org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:227)
        at org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:210)
        at org.eclipse.jetty.io.AbstractConnection.close(AbstractConnection.java:257)
        at org.eclipse.jetty.server.HttpChannelOverHttp.earlyEOF(HttpChannelOverHttp.java:262)
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1634)
        at org.eclipse.jetty.server.HttpConnection.parseRequestBuffer(HttpConnection.java:403)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:275)
        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.produce(AdaptiveExecutionStrategy.java:193)
        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)
Caused by: java.io.IOException: Connection reset by peer
        at java.base/sun.nio.ch.FileDispatcherImpl.writev0(Native Method)
        at java.base/sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:66)
        at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:217)
        at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:153)
        at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:563)
        at java.base/java.nio.channels.SocketChannel.write(SocketChannel.java:642)
        at org.eclipse.jetty.io.SocketChannelEndPoint.flush(SocketChannelEndPoint.java:110)
        ... 27 common frames omitted
2025-06-28T19:42:06.346Z DEBUG [qtp1372057593-49] [o.e.j.i.s.SslConnection] <flush null SslConnection@2640dc99::SocketChannelEndPoint@20928e08[{l=/[0:0:0:0:0:0:0:1]:8140,r=/[0:0:0:0:0:0:0:1]:48264,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=1}]->[SslConnection@2640dc99{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=IDLE,flush=IDLE}~>{l=/[0:0:0:0:0:0:0:1]:8140,r=/[0:0:0:0:0:0:0:1]:48264,CLOSED,fill=-,flush=-,to=165/30000}=>HttpConnection@2c4d0f7[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@3bad9a34{s=START}]=>HttpChannelOverHttp@3033b7a0{s=HttpChannelState@48d70855{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}]

[dotconfig404]

Is there any new insights on this issue?

I noticed that after calling puppetserver ca clean the respective certificates are revoked as they should, but not deleted.

# puppetserver ca clean --certname asdf
Certificate for asdf has been revoked
Cleaned files related to asdf
# puppetserver ca generate --certname asdf
Error:
Existing file at '/etc/puppetlabs/puppet/ssl/certs/asdf.pem'
Existing file at '/etc/puppetlabs/puppet/ssl/private_keys/asdf.pem'
Existing file at '/etc/puppetlabs/puppet/ssl/public_keys/asdf.pem'

In the log of puppetserver we can see that it revokes the certificates immediately:

2025-08-28T13:17:25.813+02:00 INFO  [qtp2033944355-87] [p.p.certificate-authority] Entity mainstation signed 1 certificate: asdf.
2025-08-28T13:17:34.397+02:00 INFO  [qtp2033944355-161] [p.p.certificate-authority] Entity mainstation revoked 1 certificate: asdf.
2025-08-28T13:17:34.605+02:00 INFO  [clojure-agent-send-off-pool-1] [o.e.j.u.s.SslContextFactory] x509=X509@557255ae(private key,h=[localhost, mainstation],a=[],w=[]) for InternalSslContextFactory@20f1a843[provider=null,keyStore=null,trustStore=null]
2025-08-28T13:18:04.426+02:00 WARN  [qtp2033944355-163] [p.p.certificate-authority] No certificate request for asdf at expected path /etc/puppetlabs/puppetserver/ca/requests/asdf.pem

This is using the newest version:

# puppetserver --version
puppetserver version: 8.11.1.SNAPSHOT.2025.08.28T0932

[dotconfig404]

Ah ops, the serverside certificate is being deleted, that was of course the clientside certificate that is not deleted. So there is a delay between revoking and deletion, but both actions are eventually done successfully.

[dotconfig404]

Hi, I left an update about this here
https://bugs.ruby-lang.org/issues/19017 and github.com/ruby/net-http/issues/233

The issue is in the client, not the server, but it's not a puppet/openvox issue.

It does not occur with the perfoce packages because by default they use JDK 11, at least the publicly available packages, and that version does not send new session tickets after the initial handshake.

It is unfortunately not really easily possible to deactivate those from being sent in JDK version until JDK 24 using the newly available system property "jdk.tls.server.newSessionTicketCount" which can be set to 0
https://bugs.openjdk.org/browse/JDK-8333581
https://www.oracle.com/java/technologies/javase/24-relnote-issues.html

I believe that is currently the most pragmatic workaround. Another way to get around this issue is to disable TLS 1.3.

[dotconfig404]

Another workaround would be to disable keep-alive connections.