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 @@ def call(env)
 
         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 @@
 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?

lib/puma/launcher.rb

@@ -205,6 +205,17 @@ def close_binder_listeners
       @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 @@ 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 "<no backtrace available>"
-        end
-      end
-    end
-
     def set_process_title
       Process.respond_to?(:setproctitle) ? Process.setproctitle(title) : $0 = title
     end
@@ -457,7 +453,10 @@ def setup_signals
 
       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 @@ 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,

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

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

test/test_launcher.rb

@@ -57,10 +57,9 @@ def test_puma_wild_location_is_an_absolute_path
   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