Using IO or rescuing exceptions when setting a timeout

[dvkch]

Hello everyone :)

I've ran into a curious issue when setting a timeout at context creation. The underlying timeout detection doesn't seem to allow for rescue exceptions in attached methods, nor using IO.

Here is an example :

def download_base64(url)
      data = URI.open(url)
      data = Base64.encode64(data&.read || "")
      { data: data }
rescue => e
      { error: e.to_s }
end

js_context = MiniRacer::Context.new(timeout: 10)
js_context.attach('download64', proc { |url|
        download_base64(url)
})

begin
  result = js_context.call('download64', 'https://google.com/favicon.ico')
  puts "RESULT: #{result}"
rescue => e
  puts "ERROR: #{e}"
end

The code above ends up outputting:

ERROR: JavaScript was terminated (either by timeout or explicitly)

If I remove the rescue from the download_base64 ruby method, the output turns into :

ERROR: Terminated during callback

I have traced the error above to stop_attached inside MiniRacer.

If I remove the timeout, the result is a base64 encoded string of the Google's favicon.

I have disabled the timeout for now but would be very interesting to understand what goes on behind the scene. I have tried to go into the def timeout(&blk) method, and I am not sure why the current code there doesn't work, it doesn't seem to do anything you wouldn't expect it do it.

[tisba]

Interesting 🤔

Just to be clear: The error with the timeout is to be expected, as it is in milliseconds.

I got curious and removed the IO-related part and using just Kernel.sleep having rescue in the attached method does influence the runtime quite a bit. In the following code with mini_racer timeout at 10ms, but sleeping for 1000ms. With rescue we need ~2 seconds, without ~12.78ms (slightly above the 10ms timeout we set):

# frozen_string_literal: true

require "bundler/inline"

gemfile do
  source "https://rubygems.org"

  gem "mini_racer", "0.12.0"
end

require "libv8-node"

puts "RUBY_VERSION : #{RUBY_VERSION}"
puts "RUBY_PLATFORM: #{RUBY_PLATFORM}"
puts "MiniRacer::VERSION: #{MiniRacer::VERSION}"
puts "Libv8::Node::LIBV8_VERSION: #{Libv8::Node::LIBV8_VERSION}"
puts "=" * 80

def sleep_rescue(duration_ms)
  sleep duration_ms.to_f / 1000
  :result_a
rescue MiniRacer::ScriptTerminatedError => e
  puts "attached: TIMEOUT! #{e.class} - #{e.message}"
  :timeout
rescue => e
  puts "attached: ERROR: #{e.class} - #{e.message}"
end

def sleep_no_rescue(duration_ms)
  sleep duration_ms.to_f / 1000
  :result_b
end

js_context = MiniRacer::Context.new(timeout: 10)
js_context.attach("sleep_rescue", method(:sleep_rescue))
js_context.attach("sleep_no_rescue", method(:sleep_no_rescue))

started = Time.now
puts "sleep_rescue:"
begin
  result = js_context.call("sleep_rescue", 1000)
  puts "RESULT: #{result}"
rescue => e
  puts "ERROR: #{e.class} - #{e.message}"
end
puts "==> #{Time.now - started} sec"
puts

started = Time.now
puts "sleep_no_rescue:"
begin
  result = js_context.call("sleep_no_rescue", 1000)
  puts "RESULT: #{result}"
rescue => e
  puts "ERROR: #{e.class} - #{e.message}"
end
puts "==> #{Time.now - started} sec"

resulting in this printed:

RUBY_VERSION : 3.3.1
RUBY_PLATFORM: arm64-darwin23
MiniRacer::VERSION: 0.12.0
Libv8::Node::LIBV8_VERSION: 11.8.172.17
================================================================================
sleep_rescue:
attached: TIMEOUT! MiniRacer::ScriptTerminatedError - Terminated during callback
RESULT: timeout
==> 2.01841 sec

sleep_no_rescue:
ERROR: MiniRacer::ScriptTerminatedError - Terminated during callback
==> 0.012784 sec

[dvkch]

Thank you for such a detailed answer ! I had completely missed the fact that the timeout was in ms. I am very curious as to why the rescue would also impact such a delay, exceptions are often costly, but I wouldn't have imagined to that extent 🤔

[tisba]

I have not figured out where the time is spent exactly, but it is not in the Ruby method (added some crude debug statements in mini_racer directly). I'm suspecting this is happening in C-land somewhere, but that's out of reach for me to understand further.

That might be something @SamSaffron or @lloeki might be able to help better. IMO the huge delay is a bug.