[Maintenance]: Performance issues with ring-core 1.15.x need investigation

[nmburgan]

Overview

When updating the ring-core dependency to 1.15.x, we see a performance regression. This is not caught by openvox-server tests. All openvox-server tests (not including acceptance) have the same runtime with 1.14.2 and 1.15.x.

Several of the tests in the openvoxdb test suite slow down, but the most obvious one is the puppetlabs.puppetdb.integration.exported-resources test.

A "good" run, when ring-core was back at 1.8.2, can be seen here and a "bad" run here. In the good run, the overall test time is 16 minutes, but in the bad run, it's 39 minutes. This is very consistent when running in GitHub Actions.

In testing, 1.14.2 is fine, and 1.15.0-beta1, the very first 1.15.x release, has this issue. Release notes from that release:

• Added wrap-content-length middleware
• Fixed unnecessary flushing of string response bodies (#519)
• Fixed seq response bodies to flush after each element (#528)

Investigation paths

There are two theories about what might be going on here. I could be one or both or none of these. It has not bee definitively root caused yet.

1. 1.15.x now attempts to add the Content-Length header automatically to responses it thinks it can know the length of. Previously, it never bothered (I think) unless you explicitly added it yourself. It's possible that the Content-Length header is calculated by the middleware before the response is gzipped, if the request includes the Accept-Encoding: gzip header. If so, then the Content-Length would be wrong, the receiver is waiting for more content that doesn't exist because it's been gzipped, and times out eventually. I think generally around https://github.com/OpenVoxProject/trapperkeeper-webserver-jetty10/blob/0fdc33f13cf[…]rc/puppetlabs/trapperkeeper/services/webserver/jetty10_core.clj we're wrapping the ring handler, but I'm not really familiar with all the machinery there. It would be broken for ring to apply Content-Length when it knows the response is going to be gzipped, but it isn't clear to me if we're gzipping it ourselves outside of ring's awareness or not. Kinda seems like we are with https://github.com/OpenVoxProject/trapperkeeper-webserver-jetty10/blob/0fdc33f13cf[…]rc/puppetlabs/trapperkeeper/services/webserver/jetty10_core.clj, but I don't have a clear view of the whole chain of events in crafting the response.
2. Another thing it could be related to is Different content-length response behaviour on Java 11 vs Java 17 ring-clojure/ring#519 and the change in ring-clojure/ring@a27b98f. This specifically changes the behavior of how ring flushes data, done in relation to how Jetty handles it, and given that 1.14/1.15 is targeting Jetty 12, I suspect it just was never tested with Jetty 10 and there's some bad interaction there.

Reproduction

As mentioned above, this is not seen in openvox-server test. You will need to run the openvoxdb integration tests to observe the changes.

On the latest main, you can run bundle exec rake vox:test['int/openjdk21/pup-main/srv-main/pg-17/rich'] to run one of the integration cells that shows the issue. This test pulls down the openvox-server repo from the main branch and compiles and runs it from there. If you'd like to test on your own branch, push it to the openvox-server repo (you must have write access), and make the test spec string int/openjdk21/pup-main/srv-<your_branch_name>/pg-17/rich.

Normally this command will run the whole test suite, but if you change this to run lein with-profiles "${LEIN_PROFILES:-dev}" test :only puppetlabs.puppetdb.integration.exported-resources, it will run the test with the most obvious performance impact.

The first milestone in this test is that it will generate the certificate for the agent.

2026-01-21 02:52:27,383 INFO  [qtp1607763959-53] [o.e.j.s.RequestLog] [0:0:0:0:0:0:0:1] - - [21/Jan/2026:02:52:27 +0000] "PUT /puppet-ca/v1/certificate_request/agent-1 HTTP/1.1" 200 0 "-" "Puppet/8.24.2 Ruby/3.2.10-p266 (aarch64-linux)"

This will take a little bit of time and that's normal.

Soon after this, you will see some calls to /puppet/v3/node/agent-1 and /puppet/v3/file_metadatas. On 1.14.2 and earlier, these requests return very very quickly.

2026-01-21 02:52:57,749 DEBUG [qtp1607763959-42] [puppetserver] Puppet node supports formats: json pson yaml
2026-01-21 02:52:57,754 INFO  [qtp1607763959-42] [o.e.j.s.RequestLog] [0:0:0:0:0:0:0:1] - - [21/Jan/2026:02:52:57 +0000] "GET /puppet/v3/node/agent-1?environment=production&configured_environment=production&transaction_uuid=642dd7a9-8290-4289-83ba-5c4002230493 HTTP/1.1" 200 62 "-" "Puppet/8.24.2 Ruby/3.2.10-p266 (aarch64-linux)"
2026-01-21 02:52:57,757 DEBUG [qtp1607763959-44] [p.r.core] Processing :get /puppet/v3/file_metadatas/plugins
2026-01-21 02:52:57,759 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evaluating match for Route /^\/puppet\//
2026-01-21 02:52:57,759 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evaluating match for Route /v3/
2026-01-21 02:52:57,760 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evaluating match for Route /^\/environments$/
2026-01-21 02:52:57,760 DEBUG [qtp1607763959-44] [puppetserver] Puppet Did not match path ("/file_metadatas/plugins")
2026-01-21 02:52:57,760 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evaluating match for Route /.*/
2026-01-21 02:52:57,761 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evicting cache entry for environment :production
2026-01-21 02:52:57,761 DEBUG [qtp1607763959-44] [p.s.j.puppet-environments] Removing environment 'production' from registry
2026-01-21 02:52:57,761 DEBUG [qtp1607763959-44] [puppetserver] Puppet Deleted text domain :production: false
2026-01-21 02:52:57,763 DEBUG [qtp1607763959-44] [puppetserver] Puppet Caching environment :production (ttl = 0 sec)
2026-01-21 02:52:57,763 DEBUG [qtp1607763959-44] [p.s.j.puppet-environments] Registering environment 'production'
2026-01-21 02:52:57,769 DEBUG [qtp1607763959-44] [puppetserver] Puppet Puppet::Network::Format[msgpack]: feature msgpack is missing
2026-01-21 02:52:57,769 DEBUG [qtp1607763959-44] [puppetserver] Puppet Puppet::Network::Format[rich_data_msgpack]: feature msgpack is missing
2026-01-21 02:52:57,769 DEBUG [qtp1607763959-44] [puppetserver] Puppet file_metadata supports formats: json pson yaml
2026-01-21 02:52:57,771 INFO  [qtp1607763959-44] [o.e.j.s.RequestLog] [0:0:0:0:0:0:0:1] - - [21/Jan/2026:02:52:57 +0000] "GET /puppet/v3/file_metadatas/plugins?recurse=false&links=manage&checksum_type=sha256&source_permissions=ignore&environment=production HTTP/1.1" 200 211 "-" "Puppet/8.24.2 Ruby/3.2.10-p266 (aarch64-linux)"
2026-01-21 02:52:57,780 DEBUG [qtp1607763959-42] [p.r.core] Processing :get /puppet/v3/file_metadatas/pluginfacts
2026-01-21 02:52:57,783 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evaluating match for Route /^\/puppet\//
2026-01-21 02:52:57,783 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evaluating match for Route /v3/
2026-01-21 02:52:57,783 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evaluating match for Route /^\/environments$/
2026-01-21 02:52:57,783 DEBUG [qtp1607763959-42] [puppetserver] Puppet Did not match path ("/file_metadatas/pluginfacts")
2026-01-21 02:52:57,784 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evaluating match for Route /.*/
2026-01-21 02:52:57,784 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evicting cache entry for environment :production
2026-01-21 02:52:57,784 DEBUG [qtp1607763959-42] [p.s.j.puppet-environments] Removing environment 'production' from registry
2026-01-21 02:52:57,784 DEBUG [qtp1607763959-42] [puppetserver] Puppet Deleted text domain :production: false
2026-01-21 02:52:57,786 DEBUG [qtp1607763959-42] [puppetserver] Puppet Caching environment :production (ttl = 0 sec)
2026-01-21 02:52:57,786 DEBUG [qtp1607763959-42] [p.s.j.puppet-environments] Registering environment 'production'
2026-01-21 02:52:57,788 DEBUG [qtp1607763959-42] [puppetserver] Puppet Puppet::Network::Format[msgpack]: feature msgpack is missing
2026-01-21 02:52:57,788 DEBUG [qtp1607763959-42] [puppetserver] Puppet Puppet::Network::Format[rich_data_msgpack]: feature msgpack is missing
2026-01-21 02:52:57,789 DEBUG [qtp1607763959-42] [puppetserver] Puppet file_metadata supports formats: json pson yaml
2026-01-21 02:52:57,790 INFO  [qtp1607763959-42] [o.e.j.s.RequestLog] [0:0:0:0:0:0:0:1] - - [21/Jan/2026:02:52:57 +0000] "GET /puppet/v3/file_metadatas/pluginfacts?recurse=true&max_files=-1&ignore=.svn&ignore=CVS&ignore=.git&ignore=.hg&links=follow&checksum_type=sha256&source_permissions=use&environment=production HTTP/1.1" 200 213 "-" "Puppet/8.24.2 Ruby/3.2.10-p266 (aarch64-linux)"
2026-01-21 02:52:57,793 DEBUG [qtp1607763959-44] [p.r.core] Processing :get /puppet/v3/file_metadatas/plugins
2026-01-21 02:52:57,795 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evaluating match for Route /^\/puppet\//
2026-01-21 02:52:57,796 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evaluating match for Route /v3/
2026-01-21 02:52:57,796 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evaluating match for Route /^\/environments$/
2026-01-21 02:52:57,796 DEBUG [qtp1607763959-44] [puppetserver] Puppet Did not match path ("/file_metadatas/plugins")
2026-01-21 02:52:57,796 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evaluating match for Route /.*/
2026-01-21 02:52:57,797 DEBUG [qtp1607763959-44] [puppetserver] Puppet Evicting cache entry for environment :production
2026-01-21 02:52:57,797 DEBUG [qtp1607763959-44] [p.s.j.puppet-environments] Removing environment 'production' from registry
2026-01-21 02:52:57,797 DEBUG [qtp1607763959-44] [puppetserver] Puppet Deleted text domain :production: false
2026-01-21 02:52:57,798 DEBUG [qtp1607763959-44] [puppetserver] Puppet Caching environment :production (ttl = 0 sec)
2026-01-21 02:52:57,798 DEBUG [qtp1607763959-44] [p.s.j.puppet-environments] Registering environment 'production'
2026-01-21 02:52:57,801 DEBUG [qtp1607763959-44] [puppetserver] Puppet Puppet::Network::Format[msgpack]: feature msgpack is missing
2026-01-21 02:52:57,802 DEBUG [qtp1607763959-44] [puppetserver] Puppet Puppet::Network::Format[rich_data_msgpack]: feature msgpack is missing
2026-01-21 02:52:57,802 DEBUG [qtp1607763959-44] [puppetserver] Puppet file_metadata supports formats: json pson yaml
2026-01-21 02:52:57,804 INFO  [qtp1607763959-44] [o.e.j.s.RequestLog] [0:0:0:0:0:0:0:1] - - [21/Jan/2026:02:52:57 +0000] "GET /puppet/v3/file_metadatas/plugins?recurse=true&max_files=-1&ignore=.svn&ignore=CVS&ignore=.git&ignore=.hg&links=follow&checksum_type=sha256&source_permissions=ignore&environment=production HTTP/1.1" 200 212 "-" "Puppet/8.24.2 Ruby/3.2.10-p266 (aarch64-linux)"
2026-01-21 02:52:57,852 DEBUG [qtp1607763959-42] [p.r.core] Processing :post /puppet/v3/catalog/agent-1
2026-01-21 02:52:57,855 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evaluating match for Route /^\/puppet\//
2026-01-21 02:52:57,856 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evaluating match for Route /v3/
2026-01-21 02:52:57,856 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evaluating match for Route /^\/environments$/
2026-01-21 02:52:57,856 DEBUG [qtp1607763959-42] [puppetserver] Puppet Did not match path ("/catalog/agent-1")
2026-01-21 02:52:57,856 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evaluating match for Route /.*/
2026-01-21 02:52:57,856 DEBUG [qtp1607763959-42] [puppetserver] Puppet Evicting cache entry for environment :production
2026-01-21 02:52:57,856 DEBUG [qtp1607763959-42] [p.s.j.puppet-environments] Removing environment 'production' from registry
2026-01-21 02:52:57,857 DEBUG [qtp1607763959-42] [puppetserver] Puppet Deleted text domain :production: false
2026-01-21 02:52:57,858 DEBUG [qtp1607763959-42] [puppetserver] Puppet Caching environment :production (ttl = 0 sec)
2026-01-21 02:52:57,858 DEBUG [qtp1607763959-42] [p.s.j.puppet-environments] Registering environment 'production'
2026-01-21 02:52:57,874 DEBUG [qtp1607763959-42] [puppetserver] Facter resolving fact with user_query: networking.ip6
2026-01-21 02:52:57,875 DEBUG [qtp1607763959-42] [puppetserver] Facter Searching fact: networking.ip6 in file: networking.ip6.rb
2026-01-21 02:52:57,876 DEBUG [qtp1607763959-42] [puppetserver] Facter Searching fact: networking.ip6 in core facts and external facts
2026-01-21 02:52:57,876 DEBUG [qtp1607763959-42] [puppetserver] Facter Loading all internal facts
2026-01-21 02:52:57,877 DEBUG [qtp1607763959-42] [puppetserver] Facter List of resolvable facts: [#<Facter::SearchedFact:0x74314b9 @name="networking.ip6", @fact_class=Facts::Linux::Networking::Ip6, @type=:core, @user_query="networking.ip6", @file=nil>]
2026-01-21 02:52:57,877 DEBUG [qtp1607763959-42] [puppetserver] Facter Loading external facts
2026-01-21 02:52:57,877 DEBUG [qtp1607763959-42] [puppetserver] Facter Searching fact: networking.ip6 in all custom facts
2026-01-21 02:52:57,877 DEBUG [qtp1607763959-42] [puppetserver] Facter Loading custom facts
2026-01-21 02:52:57,933 INFO  [qtp1607763959-42] [puppetserver] Puppet 'replace_facts' command for agent-1 submitted to PuppetDB with UUID f6bf6942-2fac-44ad-bbd9-f71f39ac37a0
2026-01-21 02:52:57,936 DEBUG [qtp1607763959-42] [puppetserver] Puppet Found in cache :production (ttl = 0 sec)
2026-01-21 02:52:57,978 DEBUG [qtp1607763959-42] [puppetserver] Facter resolving fact with user_query: networking.domain
2026-01-21 02:52:57,979 DEBUG [qtp1607763959-42] [puppetserver] Facter Searching fact: networking.domain in file: networking.domain.rb
2026-01-21 02:52:57,980 DEBUG [qtp1607763959-42] [puppetserver] Facter Searching fact: networking.domain in core facts and external facts
2026-01-21 02:52:57,980 DEBUG [qtp1607763959-42] [puppetserver] Facter Loading all internal facts
2026-01-21 02:52:57,980 DEBUG [qtp1607763959-42] [puppetserver] Facter List of resolvable facts: [#<Facter::SearchedFact:0x34741f76 @name="networking.domain", @fact_class=Facts::Linux::Networking::Domain, @type=:core, @user_query="networking.domain", @file=nil>]

On 1.15.x, some of these requests sit there for 30 seconds (you can see the job scheduler just printing status updates while the rest of the system twiddles its thumbs) before returning and handling the next request. Not exactly sure where this 30 second timeout is defined, but likely either a read or write timeout by one of the components.

2026-01-21 01:27:14,504 DEBUG [qtp1876042817-43] [p.r.core] Processing :get /puppet/v3/node/agent-1
2026-01-21 01:27:14,533 DEBUG [qtp1876042817-43] [puppetserver] Puppet Evaluating match for Route /^\/puppet\//
2026-01-21 01:27:14,533 DEBUG [qtp1876042817-43] [puppetserver] Puppet Evaluating match for Route /v3/
2026-01-21 01:27:14,533 DEBUG [qtp1876042817-43] [puppetserver] Puppet Evaluating match for Route /^\/environments$/
2026-01-21 01:27:14,533 DEBUG [qtp1876042817-43] [puppetserver] Puppet Did not match path ("/node/agent-1")
2026-01-21 01:27:14,533 DEBUG [qtp1876042817-43] [puppetserver] Puppet Evaluating match for Route /.*/
2026-01-21 01:27:14,534 DEBUG [qtp1876042817-43] [puppetserver] Puppet Evicting cache entry for environment :production
2026-01-21 01:27:14,534 DEBUG [qtp1876042817-43] [p.s.j.puppet-environments] Removing environment 'production' from registry
2026-01-21 01:27:14,535 DEBUG [qtp1876042817-43] [puppetserver] Puppet Deleted text domain :production: false
2026-01-21 01:27:14,539 DEBUG [qtp1876042817-43] [puppetserver] Puppet Caching environment :production (ttl = 0 sec)
2026-01-21 01:27:14,539 DEBUG [qtp1876042817-43] [p.s.j.puppet-environments] Registering environment 'production'
2026-01-21 01:27:14,617 DEBUG [qtp1876042817-43] [puppetserver] Puppet Configuring PuppetDB terminuses with config file /tmp/code/target/puppetserver/master-conf/puppetdb.conf
2026-01-21 01:27:14,740 DEBUG [qtp1876042817-43] [puppetserver] Puppet HTTP 404 (probably normal) when connecting to localhost on 44751 at route https://localhost:44751/pdb/query/v4/nodes/agent-1/facts, error message received was 'Not Found'. Failing over to the next PuppetDB server_url in the 'server_urls' list
2026-01-21 01:27:14,793 DEBUG [qtp1876042817-43] [puppetserver] Puppet Could not find library 'msgpack' required to enable feature 'msgpack'
2026-01-21 01:27:14,794 DEBUG [qtp1876042817-43] [puppetserver] Puppet Puppet::Network::Format[msgpack]: feature msgpack is missing
2026-01-21 01:27:14,838 DEBUG [qtp1876042817-43] [puppetserver] Puppet Puppet::Network::Format[rich_data_msgpack]: feature msgpack is missing
2026-01-21 01:27:14,838 DEBUG [qtp1876042817-43] [puppetserver] Puppet node supports formats: json pson yaml
2026-01-21 01:27:14,844 INFO  [qtp1876042817-43] [o.e.j.s.RequestLog] [0:0:0:0:0:0:0:1] - - [21/Jan/2026:01:27:14 +0000] "GET /puppet/v3/node/agent-1?environment=production&configured_environment=production&transaction_uuid=daf72cc7-c848-4024-81e8-ca5d86a2c9f5 HTTP/1.1" 200 62 "-" "Puppet/8.24.2 Ruby/3.2.10-p266 (aarch64-linux)"
2026-01-21 01:27:17,845 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:17,846 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-6] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:27:17,846 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:17,847 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:17,847 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:27:17,848 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-7] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:27:17,850 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:22,851 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:22,852 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:22,852 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-8] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:27:22,852 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:22,852 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:27:22,852 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-9] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:27:22,854 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:22,854 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:22,854 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:27,860 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:27,861 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:27,861 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-10] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:27:27,861 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:27,861 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:27:27,862 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-1] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:27:27,864 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:32,866 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:32,867 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:32,867 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-2] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:27:32,867 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:32,868 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:27:32,868 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-3] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:27:32,870 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:32,870 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:37,871 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:37,872 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:37,872 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-4] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:27:37,872 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:37,872 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:27:37,873 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-5] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:27:37,876 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:37,876 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:42,877 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:42,878 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:42,878 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-6] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:27:42,878 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:27:42,878 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:27:42,880 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-7] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:27:42,882 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:27:44,859 DEBUG [qtp1876042817-48] [p.r.core] Processing :get /puppet/v3/file_metadatas/plugins

Sometimes the calls to /puppet/v3/file_metadatas after this are quick, but you will likely see them hang in a similar manner later in the test after we've got a certificate for agent-2.

2026-01-21 01:28:17,041 INFO  [qtp1876042817-67] [o.e.j.s.RequestLog] [0:0:0:0:0:0:0:1] - - [21/Jan/2026:01:28:17 +0000] "GET /puppet-ca/v1/certificate/agent-2 HTTP/1.1" 200 1536 "-" "Puppet/8.24.2 Ruby/3.2.10-p266 (aarch64-linux)"
2026-01-21 01:28:17,080 DEBUG [qtp1876042817-47] [p.r.core] Processing :get /puppet/v3/file_metadatas/plugins
2026-01-21 01:28:17,083 DEBUG [qtp1876042817-47] [puppetserver] Puppet Evaluating match for Route /^\/puppet\//
2026-01-21 01:28:17,084 DEBUG [qtp1876042817-47] [puppetserver] Puppet Evaluating match for Route /v3/
2026-01-21 01:28:17,084 DEBUG [qtp1876042817-47] [puppetserver] Puppet Evaluating match for Route /^\/environments$/
2026-01-21 01:28:17,084 DEBUG [qtp1876042817-47] [puppetserver] Puppet Did not match path ("/file_metadatas/plugins")
2026-01-21 01:28:17,084 DEBUG [qtp1876042817-47] [puppetserver] Puppet Evaluating match for Route /.*/
2026-01-21 01:28:17,084 DEBUG [qtp1876042817-47] [puppetserver] Puppet Evicting cache entry for environment :production
2026-01-21 01:28:17,084 DEBUG [qtp1876042817-47] [p.s.j.puppet-environments] Removing environment 'production' from registry
2026-01-21 01:28:17,085 DEBUG [qtp1876042817-47] [puppetserver] Puppet Deleted text domain :production: false
2026-01-21 01:28:17,087 DEBUG [qtp1876042817-47] [puppetserver] Puppet Caching environment :production (ttl = 0 sec)
2026-01-21 01:28:17,087 DEBUG [qtp1876042817-47] [p.s.j.puppet-environments] Registering environment 'production'
2026-01-21 01:28:17,089 DEBUG [qtp1876042817-47] [puppetserver] Puppet Puppet::Network::Format[msgpack]: feature msgpack is missing
2026-01-21 01:28:17,089 DEBUG [qtp1876042817-47] [puppetserver] Puppet Puppet::Network::Format[rich_data_msgpack]: feature msgpack is missing
2026-01-21 01:28:17,089 DEBUG [qtp1876042817-47] [puppetserver] Puppet file_metadata supports formats: json pson yaml
2026-01-21 01:28:17,091 INFO  [qtp1876042817-47] [o.e.j.s.RequestLog] [0:0:0:0:0:0:0:1] - - [21/Jan/2026:01:28:17 +0000] "GET /puppet/v3/file_metadatas/plugins?recurse=false&links=manage&checksum_type=sha256&source_permissions=ignore&environment=production HTTP/1.1" 200 211 "-" "Puppet/8.24.2 Ruby/3.2.10-p266 (aarch64-linux)"
2026-01-21 01:28:17,927 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:17,927 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:17,927 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-10] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:28:17,928 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:17,928 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:28:17,928 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-1] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:28:17,929 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:17,931 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:22,932 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:22,933 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:22,933 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:22,933 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-2] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:28:22,933 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:28:22,935 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-3] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:28:22,936 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:22,937 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:27,936 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:27,937 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:27,937 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-4] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:28:27,937 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:27,937 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:28:27,938 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-5] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:28:27,939 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:27,940 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:32,944 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:32,945 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:32,945 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:32,945 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-6] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:28:32,945 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:28:32,945 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-7] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:28:32,947 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:32,947 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:37,951 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:37,952 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:37,952 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:37,952 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-8] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:28:37,952 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:28:37,952 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-9] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:28:37,953 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:37,954 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:42,959 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:42,960 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:42,960 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-10] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-d450db41-740e-4c8b-bc0e-980c1675ed97
2026-01-21 01:28:42,960 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.s.PropertySettingJobFactory] Producing instance of Job 'SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22', class=puppetlabs.trapperkeeper.services.scheduler.job
2026-01-21 01:28:42,960 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 0 triggers
2026-01-21 01:28:42,961 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_Worker-1] [o.q.c.JobRunShell] Calling execute on job SCHEDULER_DEFAULT.1afc9c94c570-be62a40f-0fc1-4b6e-8c65-eb19513e9a22
2026-01-21 01:28:42,963 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:42,963 DEBUG [3bed90f6-950f-49db-bed3-2528e364a9a5_QuartzSchedulerThread] [o.q.c.QuartzSchedulerThread] batch acquisition of 1 triggers
2026-01-21 01:28:47,106 DEBUG [qtp1876042817-54] [p.r.core] Processing :get /puppet/v3/file_metadatas/pluginfacts

and it happens a few more times during the test.

Reports from the field

#195
https://voxpupuli.slack.com/archives/C088QSEH1RA/p1768901345326239
https://voxpupuli.slack.com/archives/C088QSEH1RA/p1768905757087649
https://voxpupuli.slack.com/archives/C088QSEH1RA/p1768939755171759 (agent run times went from ~100 seconds to hitting max timeouts and failing or getting stuck)

Workaround was setting idle-timeout-milliseconds: 1000 in puppetserver.conf to reduce the timeout from 30 seconds to make agent runs faster.

Acceptance Criteria for a fix

• The aformentioned integration test suite (not just the single test) runs in the expected ~16 minutes.
• The exported-resources test does not show 30 second pauses between requests to /puppet/v3/node and /puppet/v3/file_metadatas anywhere during the test, and the response should happen in the expected < 1 second.
• The fix does not cause breaking changes to any endpoints or cause any other performance regressions.
• Once the fix is implemented, all clojure projects, including org.openvoxproject subcomponents, are updated to use the latest ring-core.
• A test is implemented in the openvox-server test suite that would catch this issue.