Skip to content

Add readiness coordination for systemd notifications#87

Merged
corporate-gadfly merged 3 commits into
mainfrom
feature/readiness-service
Jul 11, 2026
Merged

Add readiness coordination for systemd notifications#87
corporate-gadfly merged 3 commits into
mainfrom
feature/readiness-service

Conversation

@bastelfreak

Copy link
Copy Markdown
Contributor

Short description

Checklist

I have:

@bastelfreak bastelfreak added the enhancement New feature or request label Jul 11, 2026
@bastelfreak bastelfreak force-pushed the feature/readiness-service branch 3 times, most recently from 9a248b0 to bcfdd08 Compare July 11, 2026 20:54
Signed-off-by: Tim Meusel <tim@bastelfreak.de>
@bastelfreak bastelfreak force-pushed the feature/readiness-service branch from bcfdd08 to 331ef47 Compare July 11, 2026 20:55
@bastelfreak

Copy link
Copy Markdown
Contributor Author

To test this on EL10:

dnf update
dnf install epel-release
dnf install tig podman-docker bundler git make ruby-devel gcc
dnf install https://yum.voxpupuli.org/openvox8-release-el-10.noarch.rpm # because openvox-server needs openvox-agent
git clone https://github.com/OpenVoxProject/openvox-server.git
cd openvox-server
git checkout feature/readiness-service
docker build -t ezbake-builder .
bundle config set path .vendor
bundle install
# We will build trapperkeeper-webserver as well because it has a trapperkeeper version hardcoded
DEB_PLATFORMS='' RPM_PLATFORMS='el-10' DEP_REBUILD=trapperkeeper,trapperkeeper-webserver EZBAKE_VERSION=4.0.0 DEP_REBUILD_BRANCH=feature/readiness-service bundle exec rake vox:build
dnf install output/el/10/openvox9/x86_64/openvox-server-*.el10.noarch.rpm

log from systemctl reload puppetserver; puppet agent -t when openvox-server is build against latest trapperkeeper and ezbake 4 (includes sd_notify): https://gist.github.com/bastelfreak/bd1ba144e18c9871166bc75c021142d6. important are the sd_notify log messages:

  • trapperkeeper receives the reload
  • it reloads the webserver? Or CA?
2026-07-11T18:37:55.404Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "RELOADING=1\n"
...
2026-07-11T18:37:58.209Z INFO  [async-mixed-2] [p.s.c.certificate-authority-service] Starting CA service
2026-07-11T18:37:58.210Z INFO  [async-mixed-2] [p.s.m.master-service] Puppet Server has successfully started and is now ready to handle requests
2026-07-11T18:37:58.210Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "READY=1\n"
2026-07-11T18:37:58.211Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "RELOADING=1\n"
2026-07-11T18:37:58.211Z INFO  [async-mixed-2] [p.s.c.certificate-authority-service] Stopping CA service
2026-07-11T18:37:58.212Z INFO  [async-mixed-2] [p.s.j.jruby-metrics-service] JRuby Metrics Service: stopping metrics sampler job
2026-07-11T18:37:58.212Z INFO  [async-mixed-2] [p.s.j.jruby-metrics-service] JRuby Metrics Service: stopped metrics sampler job
2026-07-11T18:37:58.212Z INFO  [async-mixed-2] [p.s.j.i.jruby-agents] Draining JRuby pool.
...
2026-07-11T18:38:01.722Z ERROR [qtp1939793682-211] [p.p.jruby-request] Error 503 on SERVER at /puppet/v3/file_metadatas/plugins: Attempted to borrow a JRubyInstance from the pool during a shutdown. Please try again.
...
2026-07-11T18:38:04.746Z INFO  [async-mixed-2] [p.s.c.certificate-authority-service] Starting CA service
2026-07-11T18:38:04.747Z INFO  [async-mixed-2] [p.s.m.master-service] Puppet Server has successfully started and is now ready to handle requests
...
2026-07-11T18:38:02.408Z INFO  [pool-6-thread-1] [p.s.j.i.jruby-internal] Creating JRubyInstance with id 1.
...
2026-07-11T18:38:04.747Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "READY=1\n"

This looks very confusing. Like trapperkeeper would iterate on services, reloads them, but sends a READY=1\n for each service. This doesn't match the list of apps/services from /opt/puppetlabs/server/apps/puppetserver/config/services.d/bootstrap.cfg:

puppetlabs.services.request-handler.request-handler-service/request-handler-service
puppetlabs.services.jruby.jruby-puppet-service/jruby-puppet-pooled-service
puppetlabs.services.jruby-pool-manager.jruby-pool-manager-service/jruby-pool-manager-service
puppetlabs.services.puppet-profiler.puppet-profiler-service/puppet-profiler-service
puppetlabs.trapperkeeper.services.webserver.jetty-service/jetty-service
puppetlabs.trapperkeeper.services.webrouting.webrouting-service/webrouting-service
puppetlabs.services.config.puppet-server-config-service/puppet-server-config-service
puppetlabs.services.master.master-service/master-service
puppetlabs.services.puppet-admin.puppet-admin-service/puppet-admin-service
puppetlabs.trapperkeeper.services.authorization.authorization-service/authorization-service
puppetlabs.services.versioned-code-service.versioned-code-service/versioned-code-service
puppetlabs.trapperkeeper.services.scheduler.scheduler-service/scheduler-service
puppetlabs.trapperkeeper.services.status.status-service/status-service
puppetlabs.trapperkeeper.services.metrics.metrics-service/metrics-service
puppetlabs.trapperkeeper.services.metrics.metrics-service/metrics-webservice
puppetlabs.services.jruby.jruby-metrics-service/jruby-metrics-service

We see the message just twice, not 16 times. Copilot claims "your bootstrap.cfg list is a single app’s service graph, not multiple apps. In normal puppetserver runtime, that usually means 1 app with many services." But if there's just one app, why the second reload?


With the fix in this PR, the reload works fine. full log: https://gist.github.com/bastelfreak/d23a4f565eb6e4565beb405243163253

The odd thing is that the amount of Starting and Stopping messages varies. Maybe that also relates to the amount of sd_notify messages?

# grep -E "(Stopping|Starting)" working.txt broken.txt
working.txt:2026-07-11T19:09:01.814Z INFO  [async-mixed-2] [p.t.internal] Starting restart for TK app=0x174a40ec
working.txt:2026-07-11T19:09:01.817Z INFO  [async-mixed-2] [p.s.c.certificate-authority-service] Stopping CA service
working.txt:2026-07-11T19:09:04.647Z INFO  [async-mixed-2] [p.s.p.puppet-admin-service] Starting Puppet Admin web app
working.txt:2026-07-11T19:09:04.649Z INFO  [async-mixed-2] [p.t.s.w.jetty-service] Starting web server(s).
working.txt:2026-07-11T19:09:04.658Z INFO  [async-mixed-2] [p.t.s.w.jetty-core] Starting web server.
working.txt:2026-07-11T19:09:04.732Z INFO  [async-mixed-2] [p.t.s.s.status-core] Starting background monitoring of cpu usage metrics
working.txt:2026-07-11T19:09:04.737Z INFO  [async-mixed-2] [p.s.c.certificate-authority-service] Starting CA service
broken.txt:2026-07-11T18:37:55.406Z INFO  [async-mixed-2] [p.s.c.certificate-authority-service] Stopping CA service
broken.txt:2026-07-11T18:37:58.046Z INFO  [async-mixed-2] [p.s.p.puppet-admin-service] Starting Puppet Admin web app
broken.txt:2026-07-11T18:37:58.130Z INFO  [async-mixed-2] [p.t.s.w.jetty-service] Starting web server(s).
broken.txt:2026-07-11T18:37:58.153Z INFO  [async-mixed-2] [p.t.s.w.jetty-core] Starting web server.
broken.txt:2026-07-11T18:37:58.203Z INFO  [async-mixed-2] [p.t.s.s.status-core] Starting background monitoring of cpu usage metrics
broken.txt:2026-07-11T18:37:58.209Z INFO  [async-mixed-2] [p.s.c.certificate-authority-service] Starting CA service
broken.txt:2026-07-11T18:37:58.211Z INFO  [async-mixed-2] [p.s.c.certificate-authority-service] Stopping CA service
broken.txt:2026-07-11T18:38:04.667Z INFO  [async-mixed-2] [p.s.p.puppet-admin-service] Starting Puppet Admin web app
broken.txt:2026-07-11T18:38:04.699Z INFO  [async-mixed-2] [p.t.s.w.jetty-service] Starting web server(s).
broken.txt:2026-07-11T18:38:04.713Z INFO  [async-mixed-2] [p.t.s.w.jetty-core] Starting web server.
broken.txt:2026-07-11T18:38:04.743Z INFO  [async-mixed-2] [p.t.s.s.status-core] Starting background monitoring of cpu usage metrics
broken.txt:2026-07-11T18:38:04.746Z INFO  [async-mixed-2] [p.s.c.certificate-authority-service] Starting CA service
# grep sd_notify working.txt broken.txt
working.txt:2026-07-11T19:09:01.815Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "RELOADING=1\n"
working.txt:2026-07-11T19:09:04.737Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "READY=1\n"
broken.txt:2026-07-11T18:37:55.404Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "RELOADING=1\n"
broken.txt:2026-07-11T18:37:58.210Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "READY=1\n"
broken.txt:2026-07-11T18:37:58.211Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "RELOADING=1\n"
broken.txt:2026-07-11T18:38:04.747Z INFO  [async-mixed-2] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "READY=1\n"

@bastelfreak bastelfreak force-pushed the feature/readiness-service branch from 331ef47 to aea14b0 Compare July 11, 2026 21:29
;; Trapperkeeper apps in the process. It can be used when connecting via nrepl
;; to allow you to do useful things, and also may be used for other things
;; (such as signal handling).
(def tk-apps (atom []))

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

maybe we need to connect with nrepl and check whats in here. maybe there are two apps?

Comment on lines +127 to +129
(defn app-log-id
[app]
(str "app=0x" (Integer/toHexString (System/identityHashCode app))))

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was intended for debugging and not that helpful. or do the apps have humand readable names somewhere?

Comment on lines +406 to +412
(defn maybe-restart-tk-apps
"Restart all TK apps unless this SIGHUP request is a rapid duplicate."
[apps]
(if (should-handle-sighup-restart?)
(restart-tk-apps apps)
(log/warn (i18n/trs "Ignoring duplicate SIGHUP restart request received within {0} ms"
min-sighup-restart-interval-ms))))

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this would be enough as a minimal workaround and we don't need the readinessservice (although I think it makes sense to have it). However, I don't know why we even receive a second SIGHUP.

@bastelfreak bastelfreak force-pushed the feature/readiness-service branch from 311467e to 7322721 Compare July 11, 2026 21:35
Comment thread project.clj Outdated
Signed-off-by: Tim Meusel <tim@bastelfreak.de>
@bastelfreak bastelfreak force-pushed the feature/readiness-service branch from 7322721 to e548da1 Compare July 11, 2026 21:39
@corporate-gadfly corporate-gadfly dismissed their stale review July 11, 2026 21:46

changes were made.

Comment thread src/puppetlabs/trapperkeeper/internal.clj
…t is ignored

Apply suggestion from @corporate-gadfly

Co-authored-by: Corporate Gadfly <corporate-gadfly@users.noreply.github.com>
Signed-off-by: Tim Meusel <tim@bastelfreak.de>
@bastelfreak bastelfreak force-pushed the feature/readiness-service branch from 0068407 to ba1c807 Compare July 11, 2026 22:16
@corporate-gadfly corporate-gadfly merged commit 463f5a8 into main Jul 11, 2026
11 checks passed
@corporate-gadfly corporate-gadfly deleted the feature/readiness-service branch July 11, 2026 22:23
@bastelfreak

Copy link
Copy Markdown
Contributor Author

whole log after the change from @corporate-gadfly

2026-07-11T22:19:06.098Z INFO  [SIGHUP handler] [p.t.internal] SIGHUP handler restarting TK apps.
2026-07-11T22:19:06.099Z INFO  [SIGHUP handler] [p.t.internal] Queueing SIGHUP restart for TK app=0x498e891a
2026-07-11T22:19:06.101Z INFO  [async-mixed-1] [p.t.internal] Starting restart for TK app=0x498e891a
2026-07-11T22:19:06.101Z INFO  [async-mixed-1] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "RELOADING=1\n"
2026-07-11T22:19:06.104Z INFO  [async-mixed-1] [p.s.c.certificate-authority-service] Stopping CA service
2026-07-11T22:19:06.110Z INFO  [async-mixed-1] [p.s.j.jruby-metrics-service] JRuby Metrics Service: stopping metrics sampler job
2026-07-11T22:19:06.110Z INFO  [async-mixed-1] [p.s.j.jruby-metrics-service] JRuby Metrics Service: stopped metrics sampler job
2026-07-11T22:19:06.115Z INFO  [async-mixed-1] [p.s.j.i.jruby-agents] Draining JRuby pool.
2026-07-11T22:19:06.119Z INFO  [async-mixed-1] [p.s.j.i.jruby-agents] Borrowed all JRuby instances, proceeding with cleanup.
2026-07-11T22:19:06.133Z WARN  [SIGHUP handler] [p.t.internal] Ignoring duplicate SIGHUP restart at 1,783,808,346,132; previous accepted restart was 1,783,808,346,097; minimum interval is 500 ms
2026-07-11T22:19:06.133Z WARN  [SIGHUP handler] [p.t.internal] Ignoring duplicate SIGHUP restart request received within 500 ms
2026-07-11T22:19:06.139Z INFO  [pool-2-thread-1] [p.s.j.i.jruby-internal] Cleaned up old JRubyInstance with id 1.
2026-07-11T22:19:06.158Z INFO  [pool-2-thread-3] [p.s.j.i.jruby-internal] Cleaned up old JRubyInstance with id 2.
2026-07-11T22:19:06.161Z INFO  [pool-2-thread-1] [p.s.j.i.jruby-internal] Cleaned up old JRubyInstance with id 3.
2026-07-11T22:19:06.161Z INFO  [pool-2-thread-2] [p.s.j.i.jruby-internal] Cleaned up old JRubyInstance with id 4.
2026-07-11T22:19:06.162Z INFO  [clojure-agent-send-pool-1] [p.s.j.i.jruby-agents] Finished draining pool.
2026-07-11T22:19:06.170Z INFO  [async-mixed-1] [p.t.s.w.jetty-service] Shutting down web server(s).
2026-07-11T22:19:06.175Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] Shutting down web server.
2026-07-11T22:19:06.176Z INFO  [async-mixed-1] [o.e.j.s.Server] Stopped oejs.Server@1b3f7062{STOPPING}[12.1.11,sto=30000]
2026-07-11T22:19:06.176Z INFO  [async-mixed-1] [o.e.j.s.Server] Shutdown oejs.Server@1b3f7062{STOPPING}[12.1.11,sto=30000]
2026-07-11T22:19:06.182Z INFO  [async-mixed-1] [o.e.j.s.AbstractConnector] Stopped oejs.ServerConnector@55e99741{SSL, (ssl, http/1.1)}{0.0.0.0:8140}
2026-07-11T22:19:06.185Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Stopped oeje10s.ServletContextHandler@4e859e7a{/status,/status,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@4a6b13b4{STOPPED}}
2026-07-11T22:19:06.185Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Stopped oeje10s.ServletContextHandler@32be2093{/puppet,/puppet,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@2ca50b8d{STOPPED}}
2026-07-11T22:19:06.186Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Stopped oeje10s.ServletContextHandler@7751fc28{/metrics/v2,/metrics/v2,b=null,a=AVAILABLE,h=oeje10s.SessionHandler@6d297c11{STOPPED}}
2026-07-11T22:19:06.186Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Stopped oeje10s.ServletContextHandler@22645c27{/puppet-admin-api,/puppet-admin-api,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@1737fdc8{STOPPED}}
2026-07-11T22:19:06.186Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Stopped oeje10s.ServletContextHandler@eb3239e{/puppet-ca,/puppet-ca,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@21b9baef{STOPPED}}
2026-07-11T22:19:06.188Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] Web server shutdown
2026-07-11T22:19:06.189Z INFO  [async-mixed-1] [p.t.s.w.filesystem-watch-service] Shutting down watcher service
2026-07-11T22:19:06.191Z INFO  [clojure-agent-send-off-pool-0] [p.t.s.w.filesystem-watch-core] Closing watcher puppetlabs.trapperkeeper.services.watcher.filesystem_watch_core.WatcherImpl@8afb5e31
2026-07-11T22:19:06.191Z INFO  [clojure-agent-send-off-pool-1] [p.t.s.w.filesystem-watch-core] Closing watcher puppetlabs.trapperkeeper.services.watcher.filesystem_watch_core.WatcherImpl@49c9db57
2026-07-11T22:19:06.192Z INFO  [async-mixed-1] [p.t.s.w.filesystem-watch-service] Done shutting down watcher service
2026-07-11T22:19:06.192Z INFO  [async-mixed-1] [p.t.s.s.scheduler-service] Shutting down Scheduler Service
2026-07-11T22:19:06.194Z INFO  [clojure-agent-send-off-pool-1] [o.q.c.QuartzScheduler] Scheduler 73b2d4fb-b033-42f2-a8ec-35a8cac7c142_$_NON_CLUSTERED shutting down.
2026-07-11T22:19:06.195Z INFO  [clojure-agent-send-off-pool-1] [o.q.c.QuartzScheduler] Scheduler 73b2d4fb-b033-42f2-a8ec-35a8cac7c142_$_NON_CLUSTERED paused.
2026-07-11T22:19:06.647Z INFO  [clojure-agent-send-off-pool-1] [o.q.c.QuartzScheduler] Scheduler 73b2d4fb-b033-42f2-a8ec-35a8cac7c142_$_NON_CLUSTERED shutdown complete.
2026-07-11T22:19:06.648Z INFO  [async-mixed-1] [p.t.s.s.scheduler-service] Scheduler Service shutdown complete.
2026-07-11T22:19:06.694Z INFO  [async-mixed-1] [p.t.s.s.scheduler-service] Initializing Scheduler Service
2026-07-11T22:19:06.697Z INFO  [async-mixed-1] [o.q.i.StdSchedulerFactory] Using default implementation for ThreadExecutor
2026-07-11T22:19:06.699Z INFO  [async-mixed-1] [o.q.c.SchedulerSignalerImpl] Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2026-07-11T22:19:06.699Z INFO  [async-mixed-1] [o.q.c.QuartzScheduler] Quartz Scheduler v2.5.2 created.
2026-07-11T22:19:06.699Z INFO  [async-mixed-1] [o.q.s.RAMJobStore] RAMJobStore initialized.
2026-07-11T22:19:06.699Z INFO  [async-mixed-1] [o.q.c.QuartzScheduler] Scheduler meta-data: Quartz Scheduler (v2.5.2) 'f5e4444a-8854-4f7d-977c-69f693f0bd8d' with instanceId 'NON_CLUSTERED'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10 threads.
  Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

2026-07-11T22:19:06.699Z INFO  [async-mixed-1] [o.q.i.StdSchedulerFactory] Quartz scheduler 'f5e4444a-8854-4f7d-977c-69f693f0bd8d' initialized from an externally provided properties instance.
2026-07-11T22:19:06.699Z INFO  [async-mixed-1] [o.q.i.StdSchedulerFactory] Quartz scheduler version: 2.5.2
2026-07-11T22:19:06.700Z INFO  [async-mixed-1] [o.q.c.QuartzScheduler] Scheduler f5e4444a-8854-4f7d-977c-69f693f0bd8d_$_NON_CLUSTERED started.
2026-07-11T22:19:06.700Z INFO  [async-mixed-1] [p.t.s.w.jetty-service] Initializing web server(s).
2026-07-11T22:19:06.705Z INFO  [async-mixed-1] [p.t.s.s.status-service] Registering status callback function for service 'puppet-profiler', version 9.0.0-SNAPSHOT
2026-07-11T22:19:06.706Z INFO  [async-mixed-1] [p.s.j.jruby-puppet-service] Initializing the JRuby service
2026-07-11T22:19:06.707Z INFO  [async-mixed-1] [p.s.j.jruby-pool-manager-service] Initializing the JRuby service
2026-07-11T22:19:06.707Z INFO  [async-mixed-1] [p.s.j.jruby-puppet-service] JRuby version info: jruby 9.4.15.0 (3.1.7) 2026-06-08 6114208a31 OpenJDK 64-Bit Server VM 25.0.3+9-LTS on 25.0.3+9-LTS +jit [x86_64-linux]
2026-07-11T22:19:06.710Z INFO  [async-mixed-1] [p.t.s.s.status-service] Registering status callback function for service 'jruby-metrics', version 9.0.0-SNAPSHOT
2026-07-11T22:19:06.710Z INFO  [pool-3-thread-1] [p.s.j.i.jruby-internal] Creating JRubyInstance with id 1.
2026-07-11T22:19:08.083Z INFO  [pool-3-thread-1] [puppetserver] Puppet Puppet settings initialized; run mode: server
2026-07-11T22:19:08.962Z INFO  [pool-3-thread-1] [p.s.j.i.jruby-agents] Finished creating JRubyInstance 1 of clojure.core$count@311c058
2026-07-11T22:19:08.963Z INFO  [pool-3-thread-3] [p.s.j.i.jruby-internal] Creating JRubyInstance with id 3.
2026-07-11T22:19:08.964Z INFO  [pool-3-thread-2] [p.s.j.i.jruby-internal] Creating JRubyInstance with id 2.
2026-07-11T22:19:08.964Z INFO  [pool-3-thread-1] [p.s.j.i.jruby-internal] Creating JRubyInstance with id 4.
2026-07-11T22:19:08.966Z INFO  [async-mixed-1] [p.s.c.puppet-server-config-core] Initializing webserver settings from core Puppet
2026-07-11T22:19:08.969Z INFO  [async-mixed-1] [p.p.certificate-authority] CA already initialized for SSL
2026-07-11T22:19:08.970Z INFO  [async-mixed-1] [p.s.c.certificate-authority-service] CA Service adding a ring handler
2026-07-11T22:19:08.973Z INFO  [async-mixed-1] [p.t.s.s.status-service] Registering status callback function for service 'ca', version 9.0.0-SNAPSHOT
2026-07-11T22:19:08.974Z INFO  [async-mixed-1] [p.s.p.puppet-admin-service] Starting Puppet Admin web app
2026-07-11T22:19:08.975Z INFO  [async-mixed-1] [p.s.v.versioned-code-service] No code-id-command set for versioned-code-service. Code-id will be nil.
2026-07-11T22:19:08.976Z INFO  [async-mixed-1] [p.s.v.versioned-code-service] No code-content-command set for versioned-code-service. Attempting to fetch code content will fail.
2026-07-11T22:19:08.976Z INFO  [async-mixed-1] [p.t.s.m.jolokia] Metrics access control using trapperkeeper-authorization is enabled.
2026-07-11T22:19:09.012Z INFO  [async-mixed-1] [p.p.certificate-authority] Master already initialized for SSL
2026-07-11T22:19:09.014Z INFO  [async-mixed-1] [p.s.m.master-service] Master Service adding ring handlers
2026-07-11T22:19:09.016Z INFO  [async-mixed-1] [p.t.s.s.status-service] Registering status callback function for service 'master', version 9.0.0-SNAPSHOT
2026-07-11T22:19:09.017Z INFO  [async-mixed-1] [p.t.s.s.status-service] Registering status callback function for service 'server', version 9.0.0-SNAPSHOT
2026-07-11T22:19:09.018Z INFO  [async-mixed-1] [p.t.s.w.jetty-service] Starting web server(s).
2026-07-11T22:19:09.019Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] webserver config overridden for key 'ssl-cert'
2026-07-11T22:19:09.019Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] webserver config overridden for key 'ssl-key'
2026-07-11T22:19:09.019Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] webserver config overridden for key 'ssl-ca-cert'
2026-07-11T22:19:09.019Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] webserver config overridden for key 'ssl-crl-path'
2026-07-11T22:19:09.028Z INFO  [async-mixed-1] [p.t.s.w.jetty-config] Enabling access logger using file /etc/puppetlabs/puppetserver/request-logging.xml
2026-07-11T22:19:09.029Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] Using specified access logging
2026-07-11T22:19:09.030Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] Server shutdown timeout set to 30,000 milliseconds
2026-07-11T22:19:09.030Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] Starting web server.
2026-07-11T22:19:09.030Z INFO  [async-mixed-1] [o.e.j.s.Server] jetty-12.1.11; built: 2026-07-02T20:57:42.640Z; git: 6c1ced3f077bc633716c54758a743b09b21328e8; jvm 25.0.3+9-LTS
2026-07-11T22:19:09.034Z INFO  [async-mixed-1] [o.e.j.s.h.ContextHandler] Started oeje10s.ServletContextHandler@1f75f491{/puppet-ca,/puppet-ca,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@4bc268f4{STARTED}}
2026-07-11T22:19:09.034Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Started oeje10s.ServletContextHandler@1f75f491{/puppet-ca,/puppet-ca,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@4bc268f4{STARTED}}
2026-07-11T22:19:09.035Z INFO  [async-mixed-1] [o.e.j.s.h.ContextHandler] Started oeje10s.ServletContextHandler@5d276c4b{/puppet-admin-api,/puppet-admin-api,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@4abf80b3{STARTED}}
2026-07-11T22:19:09.035Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Started oeje10s.ServletContextHandler@5d276c4b{/puppet-admin-api,/puppet-admin-api,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@4abf80b3{STARTED}}
2026-07-11T22:19:09.036Z INFO  [async-mixed-1] [o.e.j.s.DefaultSessionIdManager] Session workerName=node0
2026-07-11T22:19:09.037Z INFO  [async-mixed-1] [o.e.j.s.h.ContextHandler] Started oeje10s.ServletContextHandler@4bc8f7dd{/metrics/v2,/metrics/v2,b=null,a=AVAILABLE,h=oeje10s.SessionHandler@57fde02d{STARTED}}
2026-07-11T22:19:09.039Z INFO  [async-mixed-1] [p.t.s.m.jolokia] Using policy access restrictor classpath:/jolokia-access.xml
2026-07-11T22:19:09.041Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Started oeje10s.ServletContextHandler@4bc8f7dd{/metrics/v2,/metrics/v2,b=null,a=AVAILABLE,h=oeje10s.SessionHandler@57fde02d{STARTED}}
2026-07-11T22:19:09.042Z INFO  [async-mixed-1] [o.e.j.s.h.ContextHandler] Started oeje10s.ServletContextHandler@117ac34f{/puppet,/puppet,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@21cab5af{STARTED}}
2026-07-11T22:19:09.042Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Started oeje10s.ServletContextHandler@117ac34f{/puppet,/puppet,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@21cab5af{STARTED}}
2026-07-11T22:19:09.050Z INFO  [async-mixed-1] [o.e.j.u.s.SslContextFactory] x509=oejus.X509@6cfa0061(private key,h=[puppet, puppet.tim.betadots.training],a=[],w=[]) for cptswju.InternalSslContextFactory@7b8291b5[provider=null,keyStore=null,trustStore=null]
2026-07-11T22:19:09.052Z INFO  [async-mixed-1] [o.e.j.s.AbstractConnector] Started oejs.ServerConnector@278668bc{SSL, (ssl, http/1.1)}{0.0.0.0:8140}
2026-07-11T22:19:09.053Z INFO  [async-mixed-1] [o.e.j.s.Server] Started oejs.Server@6ce42244{STARTING}[12.1.11,sto=30000] @22ms
2026-07-11T22:19:09.054Z INFO  [async-mixed-1] [p.t.s.s.status-core] Starting background monitoring of cpu usage metrics
2026-07-11T22:19:09.055Z INFO  [async-mixed-1] [p.t.s.s.status-service] Registering status callback function for service 'status-service', version 1.5.0
2026-07-11T22:19:09.055Z INFO  [async-mixed-1] [p.t.s.s.status-service] Registering status service HTTP API at /status
2026-07-11T22:19:09.057Z INFO  [async-mixed-1] [o.e.j.s.h.ContextHandler] Started oeje10s.ServletContextHandler@2c392b38{/status,/status,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@53686f10{STARTED}}
2026-07-11T22:19:09.057Z INFO  [async-mixed-1] [o.e.j.e.s.ServletContextHandler] Started oeje10s.ServletContextHandler@2c392b38{/status,/status,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@53686f10{STARTED}}
2026-07-11T22:19:09.058Z INFO  [async-mixed-1] [p.s.c.certificate-authority-service] Starting CA service
2026-07-11T22:19:09.058Z INFO  [async-mixed-1] [p.s.m.master-service] Puppet Server has successfully started and is now ready to handle requests
2026-07-11T22:19:09.058Z INFO  [async-mixed-1] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "READY=1\n"
2026-07-11T22:19:09.059Z INFO  [async-mixed-1] [p.t.internal] Finished restart for TK app=0x498e891a
2026-07-11T22:19:10.533Z INFO  [pool-3-thread-1] [puppetserver] Puppet Puppet settings initialized; run mode: server
2026-07-11T22:19:10.610Z INFO  [pool-3-thread-3] [puppetserver] Puppet Puppet settings initialized; run mode: server
2026-07-11T22:19:10.637Z INFO  [pool-3-thread-2] [puppetserver] Puppet Puppet settings initialized; run mode: server
2026-07-11T22:19:10.902Z INFO  [qtp381377303-114] [puppetserver] Puppet Compiled catalog for puppet.tim.betadots.training in environment production in 0.06 seconds
2026-07-11T22:19:11.579Z INFO  [pool-3-thread-1] [p.s.j.i.jruby-agents] Finished creating JRubyInstance 4 of clojure.core$count@311c058
2026-07-11T22:19:11.674Z INFO  [pool-3-thread-3] [p.s.j.i.jruby-agents] Finished creating JRubyInstance 3 of clojure.core$count@311c058
2026-07-11T22:19:11.730Z INFO  [pool-3-thread-2] [p.s.j.i.jruby-agents] Finished creating JRubyInstance 2 of clojure.core$count@311c058

The important pieces:

root@puppet ~ # grep -E "Starting|Stopping|SIGHUP|sd_notify" working2.txt
2026-07-11T22:19:06.098Z INFO  [SIGHUP handler] [p.t.internal] SIGHUP handler restarting TK apps.
2026-07-11T22:19:06.099Z INFO  [SIGHUP handler] [p.t.internal] Queueing SIGHUP restart for TK app=0x498e891a
2026-07-11T22:19:06.101Z INFO  [async-mixed-1] [p.t.internal] Starting restart for TK app=0x498e891a
2026-07-11T22:19:06.101Z INFO  [async-mixed-1] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "RELOADING=1\n"
2026-07-11T22:19:06.104Z INFO  [async-mixed-1] [p.s.c.certificate-authority-service] Stopping CA service
2026-07-11T22:19:06.133Z WARN  [SIGHUP handler] [p.t.internal] Ignoring duplicate SIGHUP restart at 1,783,808,346,132; previous accepted restart was 1,783,808,346,097; minimum interval is 500 ms
2026-07-11T22:19:06.133Z WARN  [SIGHUP handler] [p.t.internal] Ignoring duplicate SIGHUP restart request received within 500 ms
2026-07-11T22:19:08.974Z INFO  [async-mixed-1] [p.s.p.puppet-admin-service] Starting Puppet Admin web app
2026-07-11T22:19:09.018Z INFO  [async-mixed-1] [p.t.s.w.jetty-service] Starting web server(s).
2026-07-11T22:19:09.030Z INFO  [async-mixed-1] [p.t.s.w.jetty-core] Starting web server.
2026-07-11T22:19:09.054Z INFO  [async-mixed-1] [p.t.s.s.status-core] Starting background monitoring of cpu usage metrics
2026-07-11T22:19:09.058Z INFO  [async-mixed-1] [p.s.c.certificate-authority-service] Starting CA service
2026-07-11T22:19:09.058Z INFO  [async-mixed-1] [p.t.internal] Sending sd_notify message to NOTIFY_SOCKET "/run/systemd/notify": "READY=1\n"
root@puppet ~ #


;; Debounce at the signal handler boundary to avoid back-to-back
;; restart cycles that can interrupt in-flight agent requests.
(def min-sighup-restart-interval-ms 500)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My one concern about this is that a reload cycle for a production service can take much longer than 500ms to complete.

The atom should probably track if we are :running, or :reloading, only allow one invocation of SIGHUP to swap over to :reloading, and short-circuit all other invocations until the atom is set back to :running.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

enhancement New feature or request

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants