diff --git a/.github/workflows/debug-resume-stall.yml b/.github/workflows/debug-resume-stall.yml new file mode 100644 index 00000000..ec75f99b --- /dev/null +++ b/.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/ diff --git a/spec/client_spec.rb b/spec/client_spec.rb index a5bdd309..33d52e57 100644 --- a/spec/client_spec.rb +++ b/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 diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index 3b15b70b..31c34ea5 100644 --- a/spec/spec_helper.rb +++ b/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"] diff --git a/spec/support/stall_debug.rb b/spec/support/stall_debug.rb new file mode 100644 index 00000000..15e55be5 --- /dev/null +++ b/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("%.3f [%s] %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 %d done in %.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)