test: catch the JRuby resume stall on CI (do not merge)

.github/workflows/debug-resume-stall.yml

@@ -0,0 +1,64 @@
+name: Debug resume stall
+on:
+  pull_request:
+
+jobs:
+  debug:
+    name: Debug (attempt ${{ matrix.attempt }})
+    strategy:
+      fail-fast: false
+      matrix:
+        attempt: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10]
+    runs-on: ubuntu-latest
+    timeout-minutes: 30
+    env:
+      FERRUM_PROCESS_TIMEOUT: 25
+      FERRUM_DEFAULT_TIMEOUT: 15
+      FERRUM_CHROME_DOCKERIZE: true
+      FERRUM_STALL_DEBUG: 1
+    steps:
+      - uses: actions/checkout@v4
+
+      - uses: actions/setup-java@v4
+        with:
+          distribution: temurin
+          java-version: 21
+
+      - uses: ruby/setup-ruby@v1
+        with:
+          ruby-version: jruby
+          bundler-cache: true
+
+      - uses: browser-actions/setup-chrome@latest
+        with:
+          chrome-version: stable
+
+      - name: Full suite
+        timeout-minutes: 15
+        continue-on-error: true
+        run: |
+          mkdir -p /tmp/ferrum
+          bundle exec rake
+
+      - name: The example alone, 10 times
+        timeout-minutes: 10
+        continue-on-error: true
+        run: |
+          set +e
+          mkdir -p /tmp/stall-debug
+          for i in $(seq 1 10); do
+            echo "=== isolated run $i" | tee -a /tmp/stall-debug/stall-debug.log
+            bundle exec rspec spec/client_spec.rb -e "keeps the connection" || echo "isolated run $i FAILED" | tee -a /tmp/stall-debug/stall-debug.log
+          done
+
+      - name: Stall log
+        if: always()
+        run: cat /tmp/stall-debug/stall-debug.log || true
+
+      - uses: actions/upload-artifact@v4
+        if: always()
+        with:
+          name: stall-debug-${{ matrix.attempt }}
+          path: |
+            /tmp/stall-debug/
+            /tmp/ferrum/

spec/client_spec.rb

@@ -104,7 +104,10 @@ def evaluate_in_background(page, expression, timeout:)
 
       it "times out a command waiting to be sent and keeps the connection", :launch do
         page = remote.create_page
+        StallDebug.chrome_pid = remote.process.pid if defined?(StallDebug)
+        StallDebug.log("--- example start") if defined?(StallDebug)
         Process.kill("STOP", remote.process.pid)
+        StallDebug.log("STOP") if defined?(StallDebug)
 
         sender = evaluate_in_background(page, larger_than_socket_buffers, timeout: 10)
         sleep(0.2)
@@ -113,7 +116,11 @@ def evaluate_in_background(page, expression, timeout:)
         expect(waiting.join(2)).to eq(waiting), "the command was still blocked after 2s"
         expect(waiting.value).to be_a(Ferrum::TimeoutError)
 
+        StallDebug.log("waiting: #{waiting.value.class}") if defined?(StallDebug)
         Process.kill("CONT", remote.process.pid)
+        StallDebug.log("CONT") if defined?(StallDebug)
+        StallDebug.log("sender: #{sender.value.inspect[0, 200]}") if defined?(StallDebug)
+        expect(sender.value).not_to be_a(Exception), -> { "the stalled command failed: #{sender.value.inspect}" }
         expect(sender.value.dig("result", "value")).to eq(16 * 1024 * 1024)
         expect(page.evaluate("1 + 1")).to eq(2)
       end

spec/spec_helper.rb

@@ -18,6 +18,7 @@
 require "ferrum"
 require "support/server"
 require "support/global_helpers"
+require "support/stall_debug" if ENV["FERRUM_STALL_DEBUG"]
 
 # GA servers are slow it's better to increase
 ENV["FERRUM_NEW_WINDOW_WAIT"] ||= "0.8" if ENV["CI"]

spec/support/stall_debug.rb

@@ -0,0 +1,74 @@
+# frozen_string_literal: true
+
+module StallDebug
+  LOG_PATH = "/tmp/stall-debug/stall-debug.log"
+  MUTEX = Mutex.new
+
+  class << self
+    attr_accessor :chrome_pid
+
+    def log(message)
+      line = format("%<t>.3f [%<thread>s] %<message>s", t: Process.clock_gettime(Process::CLOCK_MONOTONIC),
+                                                        thread: Thread.current.object_id, message: message)
+      MUTEX.synchronize do
+        FileUtils.mkdir_p(File.dirname(LOG_PATH))
+        File.open(LOG_PATH, "a") { |f| f.puts(line) }
+      end
+    end
+
+    def snapshot(port)
+      log("loadavg #{File.read('/proc/loadavg').strip}") if File.exist?("/proc/loadavg")
+      log("chrome #{`ps -o pid=,stat=,pcpu=,nlwp= -p #{chrome_pid} 2>&1`.strip}") if chrome_pid
+      `ss -tmioe '( sport = :#{port} or dport = :#{port} )' 2>&1`.each_line { |l| log("ss #{l.rstrip}") }
+    rescue StandardError => e
+      log("snapshot failed #{e.class}: #{e.message}")
+    end
+
+    def dump_threads
+      Thread.list.each do |thread|
+        log("thread #{thread.inspect}\n    #{Array(thread.backtrace).first(8).join("\n    ")}")
+      end
+    end
+  end
+end
+
+Ferrum::Client::WebSocket.prepend(Module.new do
+  def write_frame(data)
+    return super if data.bytesize < 1_000_000
+
+    port = @sock.local_address.ip_port
+    StallDebug.log("frame start #{data.bytesize}B port=#{port} write_timeout=#{@write_timeout}")
+    0.step(data.bytesize - 1, Ferrum::Client::WebSocket::WRITE_CHUNK_SIZE) do |offset|
+      started = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+      sampler = Thread.new do
+        sleep 0.5
+        loop do
+          StallDebug.log("chunk at #{offset} stuck for #{(Process.clock_gettime(Process::CLOCK_MONOTONIC) - started).round(2)}s")
+          StallDebug.snapshot(port)
+          sleep 0.5
+        end
+      end
+      watchdog = if @write_timeout
+                   Concurrent::ScheduledTask.execute(@write_timeout) do
+                     StallDebug.log("WATCHDOG fired at offset #{offset}")
+                     StallDebug.snapshot(port)
+                     StallDebug.dump_threads
+                     abandon_stalled_write
+                   end
+                 end
+      begin
+        @sock.write(data.byteslice(offset, Ferrum::Client::WebSocket::WRITE_CHUNK_SIZE))
+      rescue StandardError => e
+        StallDebug.log("chunk at #{offset} raised #{e.class}: #{e.message}")
+        raise
+      end
+      took = Process.clock_gettime(Process::CLOCK_MONOTONIC) - started
+      StallDebug.log(format("chunk at %<offset>d done in %<took>.3fs", offset: offset, took: took)) if took > 0.2
+    ensure
+      sampler&.kill
+      cancelled = watchdog&.cancel
+      StallDebug.log("watchdog cancel returned #{cancelled.inspect} at offset #{offset}") if watchdog && !cancelled
+    end
+    StallDebug.log("frame done")
+  end
+end)