From cd914052f503556843b8d7fbfc8a65e92f7c1343 Mon Sep 17 00:00:00 2001 From: Daniel Colson Date: Fri, 25 Oct 2019 21:46:12 -0400 Subject: [PATCH 1/2] Add pumactl command to print thread backtraces Completes 1 of 2 items from #1964 This commit adds an endpoint to the status app to print thread backtraces, and control cli command to call that endpoint. I tried this locally by starting a server with: ```sh bundle exec bin/puma test/rackup/hello.ru \ --control-url="unix://test.sock" \ --control-token="token" ``` and then printing the backtraces with: ```sh bundle exec bin/pumactl thread-backtraces \ --control-url="unix://test.sock" \ --control-token="token" ``` --- History.md | 2 +- lib/puma/app/status.rb | 5 +++++ lib/puma/control_cli.rb | 5 +++-- lib/puma/launcher.rb | 32 ++++++++++++++++---------------- test/test_cli.rb | 24 ++++++++++++++++++++++++ test/test_launcher.rb | 2 +- 6 files changed, 50 insertions(+), 20 deletions(-) diff --git a/History.md b/History.md index ec0adbbfb5..7440540b99 100644 --- a/History.md +++ b/History.md @@ -1,7 +1,7 @@ ## Master * Features - * Your feature goes here (#Github Number) + * Add pumactl `thread-backtraces` command to print thread backtraces (#2053) * Bugfixes * Your bugfix goes here (#Github Number) diff --git a/lib/puma/app/status.rb b/lib/puma/app/status.rb index 2e4b4e4c3e..f4ef9f2eeb 100644 --- a/lib/puma/app/status.rb +++ b/lib/puma/app/status.rb @@ -55,6 +55,11 @@ def call(env) when /\/stats$/ rack_response(200, @cli.stats) + + when /\/thread-backtraces$/ + strings = Puma::Events.strings + @cli.log_thread_status(strings) + rack_response(200, strings.stdout.string) else rack_response 404, "Unsupported action", 'text/plain' end diff --git a/lib/puma/control_cli.rb b/lib/puma/control_cli.rb index 6d4118f062..53cbd978d4 100644 --- a/lib/puma/control_cli.rb +++ b/lib/puma/control_cli.rb @@ -11,7 +11,8 @@ module Puma class ControlCLI - COMMANDS = %w{halt restart phased-restart start stats status stop reload-worker-directory gc gc-stats} + COMMANDS = %w{halt restart phased-restart start stats status stop reload-worker-directory gc gc-stats thread-backtraces} + PRINTABLE_COMMANDS = %w{gc-stats stats thread-backtraces} def initialize(argv, stdout=STDOUT, stderr=STDERR) @state = nil @@ -187,7 +188,7 @@ def send_request end message "Command #{@command} sent success" - message response.last if @command == "stats" || @command == "gc-stats" + message response.last if PRINTABLE_COMMANDS.include?(@command) end ensure server.close if server && !server.closed? diff --git a/lib/puma/launcher.rb b/lib/puma/launcher.rb index 2a0cd9be39..0c93fb7663 100644 --- a/lib/puma/launcher.rb +++ b/lib/puma/launcher.rb @@ -205,6 +205,21 @@ def close_binder_listeners @binder.close_listeners end + def log_thread_status(events) + Thread.list.each do |thread| + events.log "Thread TID-#{thread.object_id.to_s(36)} #{thread['label']}" + logstr = "Thread: TID-#{thread.object_id.to_s(36)}" + logstr += " #{thread.name}" if thread.respond_to?(:name) + events.log logstr + + if thread.backtrace + events.log thread.backtrace.join("\n") + else + events.log "" + end + end + end + private # If configured, write the pid of the current process out @@ -323,21 +338,6 @@ def graceful_stop log "- Goodbye!" end - def log_thread_status - Thread.list.each do |thread| - log "Thread TID-#{thread.object_id.to_s(36)} #{thread['label']}" - logstr = "Thread: TID-#{thread.object_id.to_s(36)}" - logstr += " #{thread.name}" if thread.respond_to?(:name) - log logstr - - if thread.backtrace - log thread.backtrace.join("\n") - else - log "" - end - end - end - def set_process_title Process.respond_to?(:setproctitle) ? Process.setproctitle(title) : $0 = title end @@ -457,7 +457,7 @@ def setup_signals begin Signal.trap "SIGINFO" do - log_thread_status + log_thread_status(@events) end rescue Exception # Not going to log this one, as SIGINFO is *BSD only and would be pretty annoying diff --git a/test/test_cli.rb b/test/test_cli.rb index d49236246a..e2e55f7b2f 100644 --- a/test/test_cli.rb +++ b/test/test_cli.rb @@ -203,6 +203,30 @@ def test_control_stop t.join if UNIX_SKT_EXIST end + def test_control_thread_backtraces + skip UNIX_SKT_MSG unless UNIX_SKT_EXIST + url = "unix://#{@tmp_path}" + + cli = Puma::CLI.new ["-b", "unix://#{@tmp_path2}", + "--control-url", url, + "--control-token", "", + "test/rackup/lobster.ru"], @events + + t = Thread.new { cli.run } + + wait_booted + + s = UNIXSocket.new @tmp_path + s << "GET /thread-backtraces HTTP/1.0\r\n\r\n" + body = s.read + s.close + + assert_match %r{Thread: TID-}, body.split("\r\n").last + ensure + cli.launcher.stop if cli + t.join if UNIX_SKT_EXIST + end + def control_gc_stats(uri, cntl) cli = Puma::CLI.new ["-b", uri, "--control-url", cntl, diff --git a/test/test_launcher.rb b/test/test_launcher.rb index 9de31b9152..46b1f721ba 100644 --- a/test/test_launcher.rb +++ b/test/test_launcher.rb @@ -57,7 +57,7 @@ def test_puma_wild_location_is_an_absolute_path end def test_prints_thread_traces - launcher.send(:log_thread_status) + launcher.log_thread_status(events) events.stdout.rewind assert_match "Thread TID", events.stdout.read From a344d7551ef48434e905bf06f4ed8c6131189428 Mon Sep 17 00:00:00 2001 From: Daniel Colson Date: Sun, 10 Nov 2019 22:57:57 -0500 Subject: [PATCH 2/2] Log threads as JSON in control app With this commit the status app sends the thread backtraces as an array of objects with `name` and `backtrace` keys, rather than as a string matching the SIGINFO output. While working on this I noticed that we logged the thread TID twice. This commit simplifies that so we only log the thread TID once, with both the label (I don't know when the label would get set) and name if they are available. --- lib/puma/app/status.rb | 9 ++++++--- lib/puma/launcher.rb | 21 ++++++++++----------- test/test_integration_cluster.rb | 2 +- test/test_integration_single.rb | 2 +- test/test_launcher.rb | 7 +++---- 5 files changed, 21 insertions(+), 20 deletions(-) diff --git a/lib/puma/app/status.rb b/lib/puma/app/status.rb index f4ef9f2eeb..19f6d877de 100644 --- a/lib/puma/app/status.rb +++ b/lib/puma/app/status.rb @@ -57,9 +57,12 @@ def call(env) rack_response(200, @cli.stats) when /\/thread-backtraces$/ - strings = Puma::Events.strings - @cli.log_thread_status(strings) - rack_response(200, strings.stdout.string) + backtraces = [] + @cli.thread_status do |name, backtrace| + backtraces << { name: name, backtrace: backtrace } + end + + rack_response(200, backtraces.to_json) else rack_response 404, "Unsupported action", 'text/plain' end diff --git a/lib/puma/launcher.rb b/lib/puma/launcher.rb index 0c93fb7663..81ba457051 100644 --- a/lib/puma/launcher.rb +++ b/lib/puma/launcher.rb @@ -205,18 +205,14 @@ def close_binder_listeners @binder.close_listeners end - def log_thread_status(events) + def thread_status Thread.list.each do |thread| - events.log "Thread TID-#{thread.object_id.to_s(36)} #{thread['label']}" - logstr = "Thread: TID-#{thread.object_id.to_s(36)}" - logstr += " #{thread.name}" if thread.respond_to?(:name) - events.log logstr + name = "Thread: TID-#{thread.object_id.to_s(36)}" + name += " #{thread['label']}" if thread['label'] + name += " #{thread.name}" if thread.respond_to?(:name) && thread.name + backtrace = thread.backtrace || [""] - if thread.backtrace - events.log thread.backtrace.join("\n") - else - events.log "" - end + yield name, backtrace end end @@ -457,7 +453,10 @@ def setup_signals begin Signal.trap "SIGINFO" do - log_thread_status(@events) + thread_status do |name, backtrace| + @events.log name + @events.log backtrace + end end rescue Exception # Not going to log this one, as SIGINFO is *BSD only and would be pretty annoying diff --git a/test/test_integration_cluster.rb b/test/test_integration_cluster.rb index 9679f274fb..a7f58f84ec 100644 --- a/test/test_integration_cluster.rb +++ b/test/test_integration_cluster.rb @@ -44,7 +44,7 @@ def test_siginfo_thread_print Process.kill :INT , @pid t.join - assert_match "Thread TID", output.join + assert_match "Thread: TID", output.join end def test_usr2_restart diff --git a/test/test_integration_single.rb b/test/test_integration_single.rb index 8325231f50..7f44fde5fb 100644 --- a/test/test_integration_single.rb +++ b/test/test_integration_single.rb @@ -99,6 +99,6 @@ def test_siginfo_thread_print Process.kill :INT , @pid t.join - assert_match "Thread TID", output.join + assert_match "Thread: TID", output.join end end diff --git a/test/test_launcher.rb b/test/test_launcher.rb index 46b1f721ba..be3a103803 100644 --- a/test/test_launcher.rb +++ b/test/test_launcher.rb @@ -57,10 +57,9 @@ def test_puma_wild_location_is_an_absolute_path end def test_prints_thread_traces - launcher.log_thread_status(events) - events.stdout.rewind - - assert_match "Thread TID", events.stdout.read + launcher.thread_status do |name, _backtrace| + assert_match "Thread: TID", name + end end def test_pid_file