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ベースで非同期処理を実現するライブラリ。
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待たせるだけで、直った！！
会社の勤怠管理システムを実験台にして、10回実行してみたところ、完走率が
- 0.0.10・・・2回/10回
- 0.0.11・・・10回/10回
大幅に改善した。
使ってみてね！
今までは積極的に自慢できない品質だったけど、0.0.11でだいぶ理想に近づけた。
ちょっとずつ広めていきたい。
