Skip to content

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

Closed
Closed
[Maintenance]: Performance issues with ring-core 1.15.x need investigation#197
Labels
bugSomething isn't working

Description

@nmburgan
nmburgan
opened on Jan 22, 2026

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.

Activity

  1. nmburgan
    added
    bugSomething isn't working
    on Jan 22, 2026
  2. nmburgan
    changed the title [-][Bug]: Upgrading ring-core to 1.15.x causes performance regression[/-] [+][Maintenance]: Upgrading ring-core to 1.15.x causes performance regression[/+] on Jan 22, 2026
  3. nmburgan
    changed the title [-][Maintenance]: Upgrading ring-core to 1.15.x causes performance regression[/-] [+][Maintenance]: Performance issues with ring-core 1.15.x need investigation[/+] on Jan 22, 2026
  4. corporate-gadfly
    added 2 commits that reference this issue on Mar 9, 2026

    chore(deps): update dependency ring:ring-core to v1.15.3

    8e1af08

    Downgrade ring-core version from 1.15.3 to 1.14.2

    bee5b1f

  5. nmburgan commented on May 11, 2026

    @nmburgan
    nmburgan
    on May 11, 2026
    MemberAuthor

    Appears to be resolved by the upgrade to Jetty 12. See https://github.com/OpenVoxProject/openvoxdb/actions/runs/25694324788/job/75438531728 where the tests are back to the expected 16 minutes with ring-core updated to 1.15.3.

  6. corporate-gadfly commented on May 11, 2026

    @corporate-gadfly
    corporate-gadfly
    on May 11, 2026
    Contributor

    @nmburgan 1.15.4 is out.

  7. nmburgan commented on May 11, 2026

    @nmburgan
    nmburgan
    on May 11, 2026
    MemberAuthor

    Will do that update

  8. nmburgan
    closed this as completedon May 11, 2026
  9. nmburgan
    reopened this on May 13, 2026

  10. nmburgan commented on May 13, 2026

    @nmburgan
    nmburgan
    on May 13, 2026
    MemberAuthor

    Actually maybe still happening.

    https://github.com/OpenVoxProject/acceptance-pipelines/actions/runs/24481244797/job/71546062130

    Retrieving plugin facts is super speedy

    https://github.com/OpenVoxProject/acceptance-pipelines/actions/runs/25768413677/job/75686119744

    And now it takes 30 seconds. This is with Jetty 12 + logback 1.15 + ring-core 1.15.

  11. nmburgan commented on May 13, 2026

    @nmburgan
    nmburgan
    on May 13, 2026
    MemberAuthor

    Looks like we can still use ring-core 1.14.x with Jetty 12. Will probably roll back for test packages and then see about fixing it for real.

  12. nmburgan commented on May 13, 2026

    @nmburgan
    nmburgan
    on May 13, 2026
    MemberAuthor

    I think I nailed down the issues. It's pretty hairy and is mostly a bug in net-http's handling of TLSv1.3. The issue disappears if you constrain the TLS protocol to 1.2.

    1. In net-http, the begin_transport fuction has a keep-alive connection liveness check that runs before each request on a shared connection (side note, it's kind of insane that this file is 2608 lines). The wait_readable(0) function is a non-blocking check on the raw socket. If there are any bytes pending (including TLS handshake records that don't contain application data), it returns truthy.

    2. Then eof? gets called, which calls fill_rbuff, which calls self.sysread(BLOCK_SIZE). sysread calls ossl_ssl_read_internal in blocking mode, which calls SSL_read() from OpenSSL.

    3. SSL_read() processes the NewSessionTicket internally, then blocks waiting for the next TLS record. That block lasts until the server's default idle timeout of 30 second and closes the connection.

    4. In this commit in ring-core that was included in 1.15.0-RC1, they changed how they write to streams. * In 1.14.x, the string body was written through a BufferedWriter (via clojure.java.io/writer). When BufferedWriter.close() is called, it internally calls flushBuffer()  and then closes the underlying OutputStreamWriter here via that try-with-resources pattern. OutputStreamWriter.close() calls (via delegation) to StreamEncoder.implClose() which calls out.flush() on the underlying OutputStream, which is Jetty's HttpOutput , before closing it. Whew. So TL;DR, that's write -> flush -> close

    • With the change, the string body is converted to bytes and written directly to the OutputStream and then closed.
    1. The presence or absence of a flush changes which HTTP transfer encoding Jetty uses. This is decided here.
    • If HTTP/1.1 and contentLength < 0 (we don't know how long it is) and it's persistent, use chunked transfer encoding.
    • If contentLength >= 0 (we know how long it is), use the Content-Length header.
    • HttpOutput.flush() calls channelWrite(content, false), so with last=false, Jetty doesn't know the total response size and so it uses chunked transfer encoding.
    • HttpOutput.close() calls channelWrite(content, true, callback), so with last=true and this is the only write, Jetty knows the total size and uses the Content-Length header.
    1. With flush then close (1.14.x)
    • Flush sends body data with last=false. The TLS engine may have a pending NewSessionTicket which gets sent as a TLS record between the body chunks and the final chunk terminator.
    • Close sends the LAST_CHUNK terminator.
    • The sysread calls consume body data -> NewSessionTicket (processed internally during body reading) -> LAST_CHUNK terminator.
    • By the time the response is fully read, the NewSessionTicket is already consumed from the TCP buffer.
    • begin_transport calls wait_readable(0) and there is no pending TLS data, it returns nil, skips the eof? check, sends the next request immediately.
    1. With close only (1.15.x with Content-Length)
    • Close sends the entire body with last=true in one TLS record. The TLS engine has a pending NewSessionTicket, sent as a separate TLS record immediately after.
    • The client reads exactly Content-Length bytes from the first TLS record. The NewSessionTicket remains unprocessed in the TCP buffer.
    • begin_transport calls wait_readable(0), the NewSessionTicket TLS record is pending, returns truthy, calls eof?, sysread processes the NewSessionTicket and finds no application data, blocks until the timeout, and then the connection is closed.

    Evidence for this from a reproduction of the issue locally shown below. I turned on TRACE logging on the server and also did a tcpdump.

    Server Logs

    There are a few requests to the server during an agent run. In the relevant portion here, it first calls GET /puppet/v3/file_metadatas/plugins which works fine because there is no pending NewSessionTicket.

    2026-05-13T19:32:48.944Z DEBUG [qtp92579235-51] [o.e.j.i.s.SslConnection] wrap Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 395 bytesProduced = 433 sequenceNumber = 2 oeji.ArrayByteBufferPool$PooledBuffer@29b64795[433/20480,d=false,rc=1] ioDone=false/false

    The second request is to GET /puppet/v3/file_metadatas/pluginfacts which is sent on the same TLSv1.3 connection. In this case, there's a pending NewSessionTicket, shown by NEED_WRAP, followed by an 88-byte ticket at sequence 4.

    2026-05-13T19:32:48.991Z DEBUG [qtp92579235-54] [o.e.j.i.s.SslConnection] wrap Status = OK HandshakeStatus = NEED_WRAP bytesConsumed = 397 bytesProduced = 435 sequenceNumber = 3 oeji.ArrayByteBufferPool$PooledBuffer@511ff09b[435/20480,d=false,rc=1] ioDone=false/false
2026-05-13T19:32:48.991Z DEBUG [qtp92579235-54] [o.e.j.i.s.SslConnection] wrap Status = OK HandshakeStatus = FINISHED bytesConsumed = 0 bytesProduced = 88 sequenceNumber = 4 oeji.ArrayByteBufferPool$PooledBuffer@511ff09b[88/20480,d=false,rc=1] ioDone=false/false

    All of the responses use Content-Length:

    2026-05-13T19:32:48.944Z DEBUG [qtp92579235-51] [o.e.j.h.HttpGenerator] endOfContent CONTENT_LENGTH content-Length 199
2026-05-13T19:32:48.991Z DEBUG [qtp92579235-54] [o.e.j.h.HttpGenerator] endOfContent CONTENT_LENGTH content-Length 201
2026-05-13T19:33:19.068Z DEBUG [qtp92579235-59] [o.e.j.h.HttpGenerator] endOfContent CONTENT_LENGTH content-Length 200
2026-05-13T19:33:19.258Z DEBUG [qtp92579235-68] [o.e.j.h.HttpGenerator] endOfContent CONTENT_LENGTH content-Length 313
2026-05-13T19:33:19.378Z DEBUG [qtp92579235-54] [o.e.j.h.HttpGenerator] endOfContent CONTENT_LENGTH content-Length 9

    Server side processing is fast, but you can see the 30 second gap between when it's sent the response, and the next request arriving.

    2026-05-13T19:32:48.908Z DEBUG [qtp92579235-51] [o.e.j.s.i.HttpChannelState] onRequest GET{u=https://puppet:8140/puppet/v3/file_metadatas/plugins?recurse=false&links=manage&checksum_type=sha256&source_permissions=ignore&environment=production,HTTP/1.1,h=5,cl=-1,p=null} oejsi.HttpChannelState@5841146a[:handling=null,handled=false,send=SENDING,completed=false,request=null]
2026-05-13T19:32:48.944Z DEBUG [qtp92579235-51] [o.e.j.e.s.ServletChannel] onCompleted for /puppet/v3/file_metadatas/plugins written app=240 net=199
2026-05-13T19:32:48.957Z DEBUG [qtp92579235-54] [o.e.j.s.i.HttpChannelState] onRequest GET{u=https://puppet:8140/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,h=5,cl=-1,p=null} oejsi.HttpChannelState@5841146a[:handling=null,handled=false,send=SENDING,completed=false,request=null]
2026-05-13T19:32:48.991Z DEBUG [qtp92579235-54] [o.e.j.e.s.ServletChannel] onCompleted for /puppet/v3/file_metadatas/pluginfacts written app=240 net=201
2026-05-13T19:33:19.016Z DEBUG [qtp92579235-59] [o.e.j.s.i.HttpChannelState] onRequest GET{u=https://puppet:8140/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,h=5,cl=-1,p=null} oejsi.HttpChannelState@3a271b99[:handling=null,handled=false,send=SENDING,completed=false,request=null]
2026-05-13T19:33:19.068Z DEBUG [qtp92579235-59] [o.e.j.e.s.ServletChannel] onCompleted for /puppet/v3/file_metadatas/plugins written app=240 net=200

    Idle timeout fires at exactly 30 seconds on the first connection

    2026-05-13T19:33:18.999Z DEBUG [Scheduler-1233153927-1] [o.e.j.i.IdleTimeout] oeji.SocketChannelEndPoint@65b4148b[{l=/127.0.0.1:8140,r=/127.0.0.1:50770,OPEN,fill=FI,flush=-,to=30007/30000}{:io=1/1,kio=1,kro=1}]->[oejis.SslConnection@fa79632{NOT_HANDSHAKING,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>{l=/127.0.0.1:8140,r=/127.0.0.1:50770,OPEN,fill=FI,flush=-,to=30008/30000}=>oejsi.HttpConnection@10097b5[p=oejh.HttpParser{s=START,0 of -1},g=oejh.HttpGenerator@5df99d5f{s=START}]=>oejsi.HttpChannelState@5841146a[:handling=null,handled=false,send=SENDING,completed=false,request=null]] idle timeout expired

    Packet capture using tcpdump (separate reproduction run)

    19:43:06.004577 IP localhost.puppet > localhost.40824: Flags [P.], seq 2520:2953, ack 4379, win 805, options [nop,nop,TS val 505993694 ecr 505993663], length 433    # HTTP response #1
19:43:06.016207 IP localhost.40824 > localhost.puppet: Flags [P.], seq 4379:4796, ack 2953, win 725, options [nop,nop,TS val 505993706 ecr 505993694], length 417    # HTTP request #2
19:43:06.049368 IP localhost.puppet > localhost.40824: Flags [P.], seq 2953:3388, ack 4796, win 805, options [nop,nop,TS val 505993739 ecr 505993706], length 435    # HTTP response #2
19:43:06.049463 IP localhost.puppet > localhost.40824: Flags [P.], seq 3388:3476, ack 4796, win 805, options [nop,nop,TS val 505993739 ecr 505993706], length 88     # TLS NewSessionTicket
19:43:36.057671 IP localhost.puppet > localhost.40824: Flags [P.], seq 3476:3516, ack 4796, win 805, options [nop,nop,TS val 506023748 ecr 505993747], length 40     # TLS close_notify (30s later)
19:43:36.057840 IP localhost.puppet > localhost.40824: Flags [F.], seq 3516, ack 4796, win 805, options [nop,nop,TS val 506023748 ecr 506023748], length 0           # Server FIN
19:43:36.058909 IP localhost.56040 > localhost.puppet: Flags [S], seq 150489941, win 65495, options [mss 65495,sackOK,TS val 506023749 ecr 0,nop,wscale 7], length 0 # Client opens new connection

    Using curl to issue two requests on the same keep-alive connection doesn't result in any issues, showing it's the handling on the agent net-http side.

    Setting gzip-enable: false in webserver.conf still shows the problem, showing it's not the gzip compression and a mismatch with Content-Length before/after compression.

    Setting ssl-protocols: ["TLSv1.2"] in webserver.conf makes the problem disappear, since TLSv1.2 doesn't use NewSessionTickets after the handshake.

    ring-core 1.14.2 with TLSv1.3 works fine since it always uses chunked encoding, due to the flush().

    This should really be fixed in net-http, but to work around this, we'll just force Jetty to always do the flush-before-close behavior in trapperkeeper-webserver's servlet code so it always forces it down the chunked encoding path.

  13. nmburgan commented on May 13, 2026

    @nmburgan
    nmburgan
    on May 13, 2026
    MemberAuthor

    And wouldn't you know it, our good friend Josh found this 3.5 years ago and tried submitting a patch to Ruby. ruby/ruby#6423

  14. nmburgan
    added a commit that references this issue on May 13, 2026

    Force chunked transfer encoding to work around net-http bug

    cc70af6

  15. corporate-gadfly commented on May 13, 2026

    @corporate-gadfly
    corporate-gadfly
    on May 13, 2026
    Contributor

    Fascinating reading. And we also have a unit test now.

  16. nmburgan commented on May 14, 2026

    @nmburgan
    nmburgan
    on May 14, 2026
    MemberAuthor

    This is now fixed with trapperkeeper-webserver 12.0.2

  17. nmburgan
    closed this as completedon May 14, 2026

  18. corporate-gadfly commented on May 14, 2026

    @corporate-gadfly
    corporate-gadfly
    on May 14, 2026
    Contributor

    On a slightly unrelated note, do you have ideas on reproducibility of #25?

  19. Sharpie
    added
    skip-changelogExcluded from CHANGELOG
    and removed
    skip-changelogExcluded from CHANGELOG
    on Jul 14, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions