puppeteer-ruby 0.0.11で完走率が劇的に改善。ブラウザの自動操作が快適に。

puppeteer-rubyが抱えていた問題

これまでのpuppeteer-rubyでは、「なぜか自動操作が止まってしまう」「なぜかdocumentエレメントが取得できず落ちる」という事象が多発していた。ようするに、自動操作の完走率がものすごく悪く、「なんか時々止まってしまう」という最悪な状態だった。

これらの原因は、ほぼほぼWebSocketのレスポンスハンドリングの順序がなぜか前後してしまうことに起因するものだった。

見つけるたびにログを個人Slack部屋に投下してたんだけど、

実に3ヶ月以上も直せないでいた。

順番が前後するバグが直せないゆえのねじれた設計...

CDPプロトコルのハンドリング時に、SEND完了より先にRECVをハンドリングされたり...

  def handle_message(message)
    if message['id']
      if callback = @callbacks.delete(message['id'])
        callback_with_message(callback, message)
      else
        debug_puts "unknown id: #{id}. Store it into pending message"

        # RECV is often notified before SEND.
        # Wait about 10 frames before throwing an error.
        message_id = message['id']
        @pending_messages[message_id] = message
        Concurrent::Promises.schedule(0.16, message_id) do |id|
          if @pending_messages.delete(id)
            raise Error.new("unknown id: #{id}")
          end
        end

Target.attachedが attach要求よりも先に処理されたり...

  def create_session(target_info)
    result = send_message('Target.attachToTarget', targetId: target_info.target_id, flatten: true)
    session_id = result['sessionId']

    # Target.attachedToTarget is often notified after the result of Target.attachToTarget.
    # D, [2020-04-04T23:04:30.736311 #91875] DEBUG -- : RECV << {"id"=>2, "result"=>{"sessionId"=>"DA002F8A95B04710502CB40D8430B95A"}}
    # D, [2020-04-04T23:04:30.736649 #91875] DEBUG -- : RECV << {"method"=>"Target.attachedToTarget", "params"=>{"sessionId"=>"DA002F8A95B04710502CB40D8430B95A", "targetInfo"=>{"targetId"=>"EBAB949A7DE63F12CB94268AD3A9976B", "type"=>"page", "title"=>"about:blank", "url"=>"about:blank", "attached"=>true, "browserContextId"=>"46D23767E9B79DD9E589101121F6DADD"}, "waitingForDebugger"=>false}}
    # So we have to wait for "Target.attachedToTarget" a bit.
    20.times do
      if @sessions[session_id]
        return @sessions[session_id]
      end
      sleep 0.1
    end
  end

　

ともかく、「そもそも順序が正しくハンドリングできていればこんなことしなくていいんや！！！」と思いつつも、こんなねじれたロジックで回避しながら、3ヶ月以上を過ごしていたのだ。

socketry/async をトライするも...

Rubykaigi2019で作った人が紹介してたんだけど、RubyのFiberベースで非同期処理を実現するライブラリ。

github.com

WebSocketをこいつに置き換えれば、シングルスレッド操作になるので事象は改善できるんでは？？　　とおもったが、このライブラリは学習コストが高すぎた・・・・・・

いろいろ試行錯誤してみたが、WebSocketのreadでコケてみたり、デッドロックしてみたり....

なんとなくメッセージのハンドリングを同期処理にしたらなおった！

特に理由はないんだが、なんとなく

    @transport.on_message do |data|
      async_handle_message(JSON.parse(data))
    end

ここで、非同期で投げっぱなしのところを、

    @transport.on_message do |data|
      handle_message(JSON.parse(data))
    end

同期に置き換えてみた。すると、ハンドリングがシーケンシャルになるので、自動操作速度はめちゃくちゃ遅くなるが、事象が全く発生しなくなっていることに気がついた。

そう、順序が狂っている原因はここだということが特定できた。

適当にsleepさせてみたら、やはりなおった！

とはいえ同期処理ではおそすぎる。オリジナルのTypeScript実装でも、ここは非同期呼び出しだ。Rubyでだけ同期にするのはイケてない。

じゃあ、適当にsleep入れたらどうなるんだろ？

    @transport.on_message do |data|
      sleep 0.1
      handle_message(JSON.parse(data))
    end

→　・・・なおってる！！

ここでピンとくる。

JSはシングルスレッドで、(今のChromiumは知らないが) WebKitでは4msのsharedTimerがあり、setTimeoutやsetIntervalも4ms単位に丸められる。（というのを2014年頃にらくらくホンのブラウザ魔改造してたときにたまたま知っていた）

「ということは、ここで4ms待てば、とりあえずうまくいくんじゃね？？」

結果、4ms待たせるだけで、直った！！

github.com

会社の勤怠管理システムを実験台にして、10回実行してみたところ、完走率が

• 0.0.10・・・2回/10回
• 0.0.11・・・10回/10回

大幅に改善した。

使ってみてね！

rubygems.org

今までは積極的に自慢できない品質だったけど、0.0.11でだいぶ理想に近づけた。

ちょっとずつ広めていきたい。

github.com