[CI investigation] Ruby 4.0.6 hang: A/B test 4.0.5 vs 4.0.6 — do not merge

.github/workflows/ci.yml

@@ -8,20 +8,14 @@ jobs:
     strategy:
       fail-fast: false
       matrix:
-        os: [ubuntu-latest, macos-latest, windows-latest]
+        os: [ubuntu-latest, macos-latest]
         gemfile:
           - Gemfile
-          - gemfiles/Gemfile-rails-8-0
-          - gemfiles/Gemfile-rails-main
-        ruby: ["3.3", "3.4", "4.0"]
-        include:
-          - gemfile: "gemfiles/Gemfile-rails-main"
-            experimental: true
+        ruby: ["4.0.6"]
     runs-on: ${{ matrix.os }}
     timeout-minutes: 25
     env:
       BUNDLE_GEMFILE: ${{ github.workspace }}/${{ matrix.gemfile }}
-    continue-on-error: ${{ !!matrix.experimental }}
     name: Ruby ${{ matrix.ruby }} on ${{ matrix.os }} with ${{matrix.gemfile}}
     steps:
       - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 # v7.0.1
@@ -31,47 +25,125 @@ jobs:
         run: "rm -Rf ${{ matrix.gemfile }}.lock"
 
       - name: Set up Ruby
-        uses: ruby/setup-ruby@d45b1a4e94b71acab930e56e79c6aa188764e7f9 # v1.316.0
+        uses: ruby/setup-ruby@95ef2b042f9d7a56d8268cba8559e2842e2ad01b # v1.321.0
         with:
           bundler: latest
           ruby-version: ${{ matrix.ruby }}
           bundler-cache: true
           cache-version: 8
 
+      # Run the suite verbosely so the log shows which test is executing.
+      # If the suite hangs (Ruby 4.0.6 + Rails 8.1 hang under investigation),
+      # attach a debugger to every live ruby process (the test process and the
+      # `rails runner` server subprocesses) and dump native backtraces of all
+      # threads, so we can tell whether the parent or the child is deadlocked
+      # and where. Then SIGINT for a Ruby-level backtrace, then SIGKILL.
       - name: Run tests
+        shell: bash
         run: |
           bundle exec rails db:setup
-          bundle exec rake
-  lint:
-    runs-on: ubuntu-latest
+          bundle exec rake TESTOPTS="--verbose" &
+          TEST_PID=$!
+          (
+            sleep 900
+            echo "=== Watchdog: test suite hung; dumping native backtraces of all ruby processes ==="
+            ps -ef | grep -i ruby | grep -v grep || true
+            if ! command -v gdb >/dev/null && [ "$(uname)" = "Linux" ]; then
+              sudo apt-get update >/dev/null 2>&1 || true
+              sudo apt-get install -y gdb >/dev/null 2>&1 || true
+            fi
+            for pid in $(pgrep -x ruby || true); do
+              echo "--- ruby process $pid: $(ps -o args= -p "$pid" | head -c 300)"
+              if command -v gdb >/dev/null; then
+                sudo gdb -p "$pid" -batch \
+                  -ex 'set pagination off' \
+                  -ex 'thread apply all bt' 2>&1 || true
+              elif command -v lldb >/dev/null; then
+                sudo lldb -p "$pid" --batch \
+                  -o 'thread backtrace all' -o 'detach' 2>&1 || true
+              fi
+            done
+            echo "=== Watchdog: sending SIGINT to test process ==="
+            kill -INT "$TEST_PID" 2>/dev/null
+            sleep 60
+            echo "=== Watchdog: test process did not exit after SIGINT, sending SIGKILL ==="
+            kill -KILL "$TEST_PID" 2>/dev/null
+          ) &
+          WATCHDOG_PID=$!
+          set +e
+          wait "$TEST_PID"
+          STATUS=$?
+          set -e
+          kill "$WATCHDOG_PID" 2>/dev/null || true
+          exit "$STATUS"
+
+  # Boots the runner server through the full LSP addon activation path (the
+  # same code path the feature tests use) 120 times in a row, with nothing
+  # else in between — a focused reproducer for the intermittent Ruby 4.0.6
+  # boot deadlock. The in-process watchdog in boot_stress.rb dumps Ruby-level
+  # backtraces of every thread after 120s of no progress; the shell watchdog
+  # below adds native (gdb/lldb) backtraces of parent and children.
+  stress:
+    strategy:
+      fail-fast: false
+      matrix:
+        os: [ubuntu-latest, macos-latest]
+        ruby: ["4.0.6"]
+    runs-on: ${{ matrix.os }}
+    timeout-minutes: 25
+    env:
+      BUNDLE_GEMFILE: ${{ github.workspace }}/Gemfile
+    name: Boot stress Ruby ${{ matrix.ruby }} on ${{ matrix.os }}
     steps:
       - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 # v7.0.1
 
+      - name: Remove Gemfile.lock
+        shell: bash
+        run: "rm -Rf Gemfile.lock"
+
       - name: Set up Ruby
-        uses: ruby/setup-ruby@d45b1a4e94b71acab930e56e79c6aa188764e7f9 # v1.316.0
+        uses: ruby/setup-ruby@95ef2b042f9d7a56d8268cba8559e2842e2ad01b # v1.321.0
         with:
           bundler: latest
+          ruby-version: ${{ matrix.ruby }}
           bundler-cache: true
           cache-version: 8
 
-      - name: Typecheck
-        run: bundle exec srb tc
-
-      - name: Lint Ruby files
-        run: bin/rubocop
-
-  summary:
-    runs-on: ubuntu-latest
-    needs: [test, lint]
-    if: always()
-    steps:
-      - name: Check test matrix status
-        if: needs.test.result != 'success'
-        run: exit 1
-
-      - name: Check lint status
-        if: needs.lint.result != 'success'
-        run: exit 1
-
-      - name: All checks passed
-        run: echo "All checks passed successfully!"
+      - name: Boot the runner server repeatedly through the LSP
+        shell: bash
+        run: |
+          bundle exec rails db:setup
+          bundle exec ruby -Itest test/stress/boot_stress.rb &
+          TEST_PID=$!
+          (
+            sleep 900
+            echo "=== Watchdog: stress run hung; dumping native backtraces of all ruby processes ==="
+            ps -ef | grep -i ruby | grep -v grep || true
+            if ! command -v gdb >/dev/null && [ "$(uname)" = "Linux" ]; then
+              sudo apt-get update >/dev/null 2>&1 || true
+              sudo apt-get install -y gdb >/dev/null 2>&1 || true
+            fi
+            for pid in $(pgrep -x ruby || true); do
+              echo "--- ruby process $pid: $(ps -o args= -p "$pid" | head -c 300)"
+              if command -v gdb >/dev/null; then
+                sudo gdb -p "$pid" -batch \
+                  -ex 'set pagination off' \
+                  -ex 'thread apply all bt' 2>&1 || true
+              elif command -v lldb >/dev/null; then
+                sudo lldb -p "$pid" --batch \
+                  -o 'thread backtrace all' -o 'detach' 2>&1 || true
+              fi
+            done
+            echo "=== Watchdog: sending SIGINT to stress process ==="
+            kill -INT "$TEST_PID" 2>/dev/null
+            sleep 60
+            echo "=== Watchdog: stress process did not exit after SIGINT, sending SIGKILL ==="
+            kill -KILL "$TEST_PID" 2>/dev/null
+          ) &
+          WATCHDOG_PID=$!
+          set +e
+          wait "$TEST_PID"
+          STATUS=$?
+          set -e
+          kill "$WATCHDOG_PID" 2>/dev/null || true
+          exit "$STATUS"

lib/ruby_lsp/ruby_lsp_rails/runner_client.rb

@@ -3,20 +3,65 @@
 
 require "json"
 require "open3"
+require "io/wait"
 
 module RubyLsp
   module Rails
     class RunnerClient
+      # Seconds to wait for the server to boot and answer the initialization handshake before killing it and
+      # retrying. Booting can hang forever (e.g. intermittent boot deadlock on Ruby 4.0.6, see PR #726), so we
+      # must not block indefinitely
+      BOOT_TIMEOUT = Integer(ENV.fetch("RUBY_LSP_RAILS_BOOT_TIMEOUT", "30")) #: Integer
+      # How many times create_client attempts to boot the server before giving up and returning a NullClient
+      MAX_BOOT_ATTEMPTS = 3 #: Integer
+
       class << self
         #: (Thread::Queue outgoing_queue, RubyLsp::GlobalState global_state) -> RunnerClient
         def create_client(outgoing_queue, global_state)
-          if File.exist?("bin/rails")
-            new(outgoing_queue, global_state)
+          # Experiment diagnostics (PR #726): trace every path through this method on stderr, because the outgoing
+          # queue messages are not printed in the test logs
+          warn("Ruby LSP Rails create_client start (pid=#{Process.pid}, cwd=#{Dir.pwd})")
+
+          # Check for bin/rails under the workspace path rather than the current working directory. The working
+          # directory is process global state and other threads may change it concurrently (e.g. RuboCop's config
+          # loader switches to a gem's directory while evaluating configurations inherited with inherit_gem),
+          # which would make a relative check fail even though the application is there
+          workspace_path = global_state.workspace_path
+
+          if File.exist?(File.join(workspace_path, "bin", "rails"))
+            attempts = 1
+
+            client = begin
+              new(outgoing_queue, global_state)
+            rescue InitializationError => e
+              # Experiment diagnostics (PR #726): surface the boot failure reason directly on stderr, because the
+              # outgoing queue messages are not printed in the test logs
+              warn("Ruby LSP Rails server boot attempt #{attempts} failed. Error:\n#{e.message}")
+
+              raise if attempts >= MAX_BOOT_ATTEMPTS
+
+              attempts += 1
+
+              unless outgoing_queue.closed?
+                outgoing_queue << RubyLsp::Notification.window_log_message(
+                  "Ruby LSP Rails server boot attempt failed (#{e.message.to_s.lines.first&.chomp}). " \
+                    "Retrying (attempt #{attempts} of #{MAX_BOOT_ATTEMPTS})",
+                  type: RubyLsp::Constant::MessageType::WARNING,
+                )
+              end
+
+              retry
+            end
+
+            warn("Ruby LSP Rails create_client booted the server successfully (attempt #{attempts})")
+            client
           else
+            warn("Ruby LSP Rails create_client: bin/rails NOT found (workspace=#{workspace_path}, cwd=#{Dir.pwd})")
+
             unless outgoing_queue.closed?
               outgoing_queue << RubyLsp::Notification.window_log_message(
                 <<~MESSAGE.chomp,
-                  Ruby LSP Rails failed to locate bin/rails in the current directory: #{Dir.pwd}
+                  Ruby LSP Rails failed to locate bin/rails in the workspace: #{workspace_path}
                   Server dependent features will not be available
                 MESSAGE
                 type: RubyLsp::Constant::MessageType::WARNING,
@@ -26,6 +71,10 @@ def create_client(outgoing_queue, global_state)
             NullClient.new
           end
         rescue StandardError => e
+          # Experiment diagnostics (PR #726): surface the final boot failure reason directly on stderr, because the
+          # outgoing queue messages are not printed in the test logs
+          warn("Ruby LSP Rails giving up booting the server. Error:\n#{e.full_message}")
+
           unless outgoing_queue.closed?
             outgoing_queue << RubyLsp::Notification.window_log_message(
               <<~MESSAGE.chomp,
@@ -37,6 +86,11 @@ def create_client(outgoing_queue, global_state)
           end
 
           NullClient.new
+        rescue Exception => e # rubocop:disable Lint/RescueException
+          # Experiment diagnostics (PR #726): non-StandardError exceptions kill the boot thread silently, so log
+          # them before letting them propagate
+          warn("Ruby LSP Rails create_client saw non-standard exception #{e.class}:\n#{e.full_message}")
+          raise
         end
       end
 
@@ -55,6 +109,9 @@ def initialize(outgoing_queue, global_state)
         log_message("Ruby LSP Rails booting server")
 
         stdin, stdout, stderr, wait_thread = Bundler.with_original_env do
+          # Spawn the server with an explicit working directory. Relying on the inherited working directory is racy:
+          # it is process global state and other threads may change it concurrently (e.g. RuboCop's config loader
+          # switches to a gem's directory while evaluating configurations inherited with inherit_gem)
           Open3.popen3(
             { "RUBY_LSP_RAILS_RUNNER" => "true" },
             "bundle",
@@ -64,6 +121,7 @@ def initialize(outgoing_queue, global_state)
             "#{__dir__}/server.rb",
             "start",
             server_relevant_capabilities(global_state),
+            { chdir: global_state.workspace_path },
           )
         end
 
@@ -80,6 +138,13 @@ def initialize(outgoing_queue, global_state)
         @stdout.binmode
         @stderr.binmode
 
+        # Wait for the server to finish booting and reply to the handshake with a timeout, rather than blocking
+        # indefinitely: the boot can hang forever (e.g. intermittent boot deadlock on Ruby 4.0.6, see PR #726).
+        # On timeout, the rescue below kills the server process and create_client retries with a fresh one
+        unless @stdout.wait_readable(BOOT_TIMEOUT)
+          raise InitializationError, "Timed out after #{BOOT_TIMEOUT} seconds waiting for the server to boot"
+        end
+
         initialize_response = read_response #: as !nil
         @rails_root = initialize_response[:root] #: String
         log_message("Finished booting Ruby LSP Rails server")
@@ -93,8 +158,30 @@ def initialize(outgoing_queue, global_state)
             @outgoing_queue << notification unless @outgoing_queue.closed?
           end
         end #: Thread
-      rescue StandardError
-        raise InitializationError, @stderr.read
+      rescue StandardError => e
+        # Make sure a stuck server process doesn't outlive us. Killing it also guarantees that reading its stderr
+        # below sees EOF instead of blocking forever. The instance variables may be unset if Open3.popen3 itself
+        # failed
+        if instance_variable_defined?(:@wait_thread) && @wait_thread.alive?
+          begin
+            Process.kill(:KILL, @wait_thread.pid)
+          rescue Errno::ESRCH, Errno::EPERM
+            # The process is already gone
+          end
+
+          @wait_thread.join(5)
+        end
+
+        message = e.is_a?(InitializationError) ? e.message : e.full_message
+
+        if instance_variable_defined?(:@stderr)
+          # The server's stderr usually contains the actual boot failure reason (e.g. a crash report), so include it
+          stderr_output = @stderr.read
+          message = "#{message}\nServer stderr:\n#{stderr_output}" unless stderr_output.to_s.empty?
+          [@stdin, @stdout, @stderr].each { |io| io.close unless io.closed? }
+        end
+
+        raise InitializationError, message
       end
 
       #: (String server_addon_path) -> void

test/ruby_lsp_rails/runner_client_test.rb

@@ -101,7 +101,7 @@ class RunnerClientTest < ActiveSupport::TestCase
           log = pop_log_notification(outgoing_queue, RubyLsp::Constant::MessageType::WARNING)
 
           assert_instance_of(RubyLsp::Notification, log)
-          assert_match("Ruby LSP Rails failed to locate bin/rails in the current directory", log.params.message)
+          assert_match("Ruby LSP Rails failed to locate bin/rails in the workspace", log.params.message)
         ensure
           outgoing_queue.close
           FileUtils.mv("bin/rails_backup", "bin/rails")