Add pumactl command to print thread backtraces (#2054)

* 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"
```

* 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.

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)

lib/puma/app/status.rb

@@ -55,6 +55,14 @@ module Puma
 
         when /\/stats$/
           rack_response(200, @cli.stats)
+
+        when /\/thread-backtraces$/
+          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

lib/puma/control_cli.rb

@@ -11,7 +11,8 @@ require 'socket'
 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 @@ module Puma
         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?

lib/puma/launcher.rb

@@ -205,6 +205,17 @@ module Puma
       @binder.close_listeners
     end
 
+    def thread_status
+      Thread.list.each do |thread|
+        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 || ["<no backtrace available>"]
+
+        yield name, backtrace
+      end
+    end
+
     private
 
     # If configured, write the pid of the current process out
@@ -323,21 +334,6 @@ module Puma
       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 "<no backtrace available>"
-        end
-      end
-    end
-
     def set_process_title
       Process.respond_to?(:setproctitle) ? Process.setproctitle(title) : $0 = title
     end
@@ -457,7 +453,10 @@ module Puma
 
       begin
         Signal.trap "SIGINFO" do
-          log_thread_status
+          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

test/test_cli.rb

@@ -203,6 +203,30 @@ class TestCLI < Minitest::Test
     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,

test/test_integration_cluster.rb

@@ -44,7 +44,7 @@ class TestIntegrationCluster < TestIntegration
     Process.kill :INT , @pid
     t.join
 
-    assert_match "Thread TID", output.join
+    assert_match "Thread: TID", output.join
   end
 
   def test_usr2_restart

test/test_integration_single.rb

@@ -99,6 +99,6 @@ class TestIntegrationSingle < TestIntegration
     Process.kill :INT , @pid
     t.join
 
-    assert_match "Thread TID", output.join
+    assert_match "Thread: TID", output.join
   end
 end

test/test_launcher.rb

@@ -57,10 +57,9 @@ class TestLauncher < Minitest::Test
   end
 
   def test_prints_thread_traces
-    launcher.send(:log_thread_status)
-    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