diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 2523cf4a..87414c4b 100644 --- a/.github/workflows/ci.yml +++ b/.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" diff --git a/lib/ruby_lsp/ruby_lsp_rails/runner_client.rb b/lib/ruby_lsp/ruby_lsp_rails/runner_client.rb index 544dbd60..d317d83f 100644 --- a/lib/ruby_lsp/ruby_lsp_rails/runner_client.rb +++ b/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 diff --git a/test/ruby_lsp_rails/runner_client_test.rb b/test/ruby_lsp_rails/runner_client_test.rb index 967d436d..14f06285 100644 --- a/test/ruby_lsp_rails/runner_client_test.rb +++ b/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") diff --git a/test/stress/boot_stress.rb b/test/stress/boot_stress.rb new file mode 100644 index 00000000..188ed855 --- /dev/null +++ b/test/stress/boot_stress.rb @@ -0,0 +1,75 @@ +# typed: false +# frozen_string_literal: true + +require_relative "../test_helper" + +# Boots the Rails runner server through the full LSP addon activation path — +# exactly like the feature tests do — many times in a row, to reproduce the +# intermittent boot deadlock observed on Ruby 4.0.6 (see PR #726). +# +# Named boot_stress.rb (not *_test.rb) so the normal `rake test` glob skips it. +# Run with: bundle exec ruby -Itest test/stress/boot_stress.rb + +$last_progress = Time.now + +# If no boot completes for 120 seconds, assume the deadlock happened and dump +# Ruby-level backtraces of every thread. Then leave the process hanging so the +# external shell watchdog can attach gdb/lldb for native backtraces. +Thread.new do + loop do + sleep(10) + next unless Time.now - $last_progress > 120 + + $stdout.puts "=== In-process watchdog: no boot progress for 120s; dumping all thread backtraces" + + # Forensics on the Rails addon boot thread: was it never created, did it die with an exception (status nil), + # was it killed / did it finish normally (status false)? If it stored an exception, re-raise it via #value so + # we finally see WHY the boot failed + begin + addon = RubyLsp::Addon.addons.find { |a| a.is_a?(RubyLsp::Rails::Addon) } + if addon + client = addon.instance_variable_get(:@rails_runner_client) + boot_thread = addon.instance_variable_get(:@boot_thread) + $stdout.puts "--- Rails addon forensics: client=#{client.class} " \ + "boot_thread=#{boot_thread.inspect} status=#{boot_thread&.status.inspect}" + + if boot_thread && boot_thread.status.nil? + begin + boot_thread.value + rescue Exception => e # rubocop:disable Lint/RescueException + $stdout.puts "--- boot thread died with #{e.class}:\n#{e.full_message}" + end + end + else + $stdout.puts "--- Rails addon instance not found in RubyLsp::Addon.addons" + end + rescue Exception => e # rubocop:disable Lint/RescueException + $stdout.puts "--- forensics failed: #{e.class}: #{e.message}" + end + + Thread.list.each do |thread| + $stdout.puts "--- Thread #{thread.inspect} status=#{thread.status.inspect}" + $stdout.puts((thread.backtrace || [""]).join("\n")) + end + $stdout.puts "=== End of thread dump; leaving the process hung for the external watchdog" + $stdout.flush + break + end +end + +module RubyLsp + module Rails + class BootStressTest < ActiveSupport::TestCase + Integer(ENV.fetch("BOOT_STRESS_ITERATIONS", "120")).times do |i| + test "boot #{format("%03d", i)}" do + with_server("class User < ApplicationRecord; end", URI("/fake.rb")) do |_server, _uri| + addon = RubyLsp::Addon.addons.find { |a| a.is_a?(RubyLsp::Rails::Addon) } + sleep(0.1) while addon.instance_variable_get(:@rails_runner_client).is_a?(NullClient) + assert_predicate(addon.instance_variable_get(:@rails_runner_client), :connected?) + $last_progress = Time.now + end + end + end + end + end +end diff --git a/test/test_helper.rb b/test/test_helper.rb index 784be45e..931e9b2b 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -1,6 +1,10 @@ # typed: true # frozen_string_literal: true +# Flush test progress output immediately so CI logs show which test is +# running when the suite hangs (Ruby 4.0.6 investigation). +$stdout.sync = true + # Configure Rails Environment ENV["RAILS_ENV"] = "test"