Skip to content

Commit

Permalink
Avoid calling $evm.backtrace over DRb to prevent DRb-level mutex locks
Browse files Browse the repository at this point in the history
Moves dynamic method building into DrbRemoteInvoker since it isn't
needed at all in MiqAeService.  Once in DrbRemoteInvoker, we can use
the dynamic preamble to inform the generated ruby method body of things
like the number of preamble lines and the name of the method for
backtrace filtering purposes.
  • Loading branch information
Fryguy authored and jrafanie committed Mar 29, 2018
1 parent d90c694 commit 3da93b0
Show file tree
Hide file tree
Showing 5 changed files with 136 additions and 128 deletions.
49 changes: 36 additions & 13 deletions lib/miq_automation_engine/engine/drb_remote_invoker.rb
Original file line number Diff line number Diff line change
Expand Up @@ -8,13 +8,11 @@ def initialize(workspace)
@num_methods = 0
end

def with_server(inputs, body)
def with_server(inputs, body, method_name)
setup if num_methods == 0
self.num_methods += 1
svc = MiqAeMethodService::MiqAeService.new(@workspace, inputs, body)
svc.preamble = method_preamble(drb_uri, svc.object_id)

yield [svc.preamble, svc.body, RUBY_METHOD_POSTSCRIPT]
svc = MiqAeMethodService::MiqAeService.new(@workspace, inputs)
yield build_method_content(body, method_name, svc.object_id)
ensure
svc.destroy # Reset inputs to empty to avoid storing object references
self.num_methods -= 1
Expand All @@ -36,10 +34,6 @@ def self.workspace

# invocation

def drb_uri
drb_server.uri
end

def setup
require 'drb/timeridconv'
global_id_conv = DRb::TimerIdConv.new(drb_cache_timeout)
Expand Down Expand Up @@ -73,11 +67,25 @@ def drb_cache_timeout

# code building

def method_preamble(miq_uri, miq_id)
"MIQ_URI = '#{miq_uri}'\nMIQ_ID = #{miq_id}\n" << RUBY_METHOD_PREAMBLE
def build_method_content(body, method_name, miq_ae_service_token)
[
dynamic_preamble(method_name, miq_ae_service_token),
RUBY_METHOD_PREAMBLE,
body,
RUBY_METHOD_POSTSCRIPT
].join("\n")
end

def dynamic_preamble(method_name, miq_ae_service_token)
<<-RUBY.chomp
MIQ_URI = '#{drb_server.uri}'
MIQ_ID = #{miq_ae_service_token}
RUBY_METHOD_NAME = '#{method_name}'
RUBY_METHOD_PREAMBLE_LINES = #{RUBY_METHOD_PREAMBLE_LINES + 4}
RUBY
end

RUBY_METHOD_PREAMBLE = <<-RUBY.freeze
RUBY_METHOD_PREAMBLE = <<-RUBY.chomp.freeze
class AutomateMethodException < StandardError
end
Expand Down Expand Up @@ -122,9 +130,22 @@ class AutomateMethodException < StandardError
end
class Exception
def filter_backtrace(callers)
return callers unless callers.respond_to?(:collect)
callers.collect do |c|
file, line, context = c.split(':')
if file == "-"
[RUBY_METHOD_NAME, line.to_i - RUBY_METHOD_PREAMBLE_LINES, context].join(':')
else
c
end
end
end
def backtrace_with_evm
value = backtrace_without_evm
value ? $evm.backtrace(value) : value
value ? filter_backtrace(value) : value
end
alias backtrace_without_evm backtrace
Expand All @@ -134,6 +155,8 @@ def backtrace_with_evm
begin
RUBY

RUBY_METHOD_PREAMBLE_LINES = RUBY_METHOD_PREAMBLE.lines.count

RUBY_METHOD_POSTSCRIPT = <<-RUBY.freeze
rescue Exception => err
unless err.kind_of?(SystemExit)
Expand Down
4 changes: 2 additions & 2 deletions lib/miq_automation_engine/engine/miq_ae_method.rb
Original file line number Diff line number Diff line change
Expand Up @@ -113,7 +113,7 @@ def self.verbose_rc(rc)
end
private_class_method :verbose_rc

def self.run_ruby_method(*code)
def self.run_ruby_method(code)
ActiveRecord::Base.connection_pool.release_connection
Bundler.with_clean_env do
ActiveSupport::Dependencies.interlock.permit_concurrent_loads do
Expand Down Expand Up @@ -154,7 +154,7 @@ def self.ruby_method_runnable?(aem)
def self.invoke_inline_ruby(aem, obj, inputs)
if ruby_method_runnable?(aem)
obj.workspace.invoker ||= MiqAeEngine::DrbRemoteInvoker.new(obj.workspace)
obj.workspace.invoker.with_server(inputs, aem.data) do |code|
obj.workspace.invoker.with_server(inputs, aem.data, aem.fqname) do |code|
$miq_ae_logger.info("<AEMethod [#{aem.fqname}]> Starting ")
rc, msg = run_ruby_method(code)
$miq_ae_logger.info("<AEMethod [#{aem.fqname}]> Ending")
Expand Down
59 changes: 1 addition & 58 deletions lib/miq_automation_engine/engine/miq_ae_service.rb
Original file line number Diff line number Diff line change
Expand Up @@ -51,13 +51,10 @@ def self.destroy(obj)
@@current.delete(obj)
end

def initialize(ws, inputs = {}, body = nil, logger = $miq_ae_logger)
def initialize(ws, inputs = {}, _body = nil, logger = $miq_ae_logger)
@drb_server_references = []
@inputs = inputs
@workspace = ws
@preamble_lines = 0
@body = []
self.body = body if body
@persist_state_hash = ws.persist_state_hash
@logger = logger
self.class.add(self)
Expand All @@ -78,60 +75,6 @@ def destroy
self.class.destroy(self)
end

def body=(data)
@body_raw = data
@body = begin
lines = []
@body_raw.each_line { |l| lines << l.rstrip }
lines
end
end

def body
@body_raw
end

def preamble
@preamble_raw
end

def preamble=(data)
@preamble_raw = data
@preamble = begin
lines = []
@preamble_raw.each_line { |l| lines << l.rstrip }
lines
end
@preamble_lines = @preamble.length
end

def method_body(options = {})
if options[:line_numbers]
line_number = 0
@body.collect do |line|
line_number += 1
"#{format "%03d" % line_number}: #{line}"
end
else
@body
end
end

def backtrace(callers)
return callers unless callers.respond_to?(:collect)

callers.collect do |c|
file, line, context = c.split(':')
if file == "-"
line_adjusted_for_preamble = line.to_i - @preamble_lines
file = @body[line_adjusted_for_preamble - 1].to_s.strip
"<code: #{file}>:#{line_adjusted_for_preamble}:#{context}"
else
c
end
end
end

def disconnect_sql
ActiveRecord::Base.connection_pool.release_connection
end
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@ module DrbRemoteInvokerSpec

timer_thread = nil

invoker.with_server([], "") do
invoker.with_server([], "", "") do
timer_thread = Thread.list.each do |t|
first = t.backtrace_locations.first
if first && first.path.include?("timeridconv.rb")
Expand Down
150 changes: 96 additions & 54 deletions spec/lib/miq_automation_engine/engine/miq_ae_method_spec.rb
Original file line number Diff line number Diff line change
@@ -1,69 +1,111 @@
describe MiqAeEngine::MiqAeMethod do
context ".invoke_inline_ruby(private)" do
it "writes to the logger immediately" do
script = <<-EOS
puts 'Hi from puts'
STDOUT.puts 'Hi from STDOUT.puts'
$stdout.puts 'Hi from $stdout.puts'
STDERR.puts 'Hi from STDERR.puts'
$stderr.puts 'Hi from $stderr.puts'
$evm.logger.sleep
EOS

workspace = Class.new do
describe ".invoke_inline_ruby (private)" do
let(:workspace) do
Class.new do
attr_accessor :invoker
# rubocop:disable Style/SingleLineMethods, Style/EmptyLineBetweenDefs
def persist_state_hash; end
def disable_rbac; end
def current_method; "/my/automate/method"; end
# rubocop:enable Style/SingleLineMethods, Style/EmptyLineBetweenDefs
end.new
end

def persist_state_hash
end
let(:aem) { double("AEM", :data => script, :fqname => "/my/automate/method") }
let(:obj) { double("OBJ", :workspace => workspace) }
let(:inputs) { [] }

def disable_rbac
end
end.new
subject { described_class.send(:invoke_inline_ruby, aem, obj, inputs) }

logger_klass = Class.new do
attr_reader :expected_messages

def initialize
@expected_messages = [
"Method STDOUT: Hi from puts",
"Method STDOUT: Hi from STDOUT.puts",
"Method STDOUT: Hi from $stdout.puts",
"Method STDERR: Hi from STDERR.puts",
"Method STDERR: Hi from $stderr.puts",
]
end

def sleep
# Raise if all messages have not already been written before a method like sleep runs.
raise unless expected_messages == []
end

def verify_next_message(message)
expected = @expected_messages.shift
return if message == expected
puts "Expected: #{expected.inspect}, Got: #{message.inspect}"
context "with a script that raises" do
let(:script) do
<<-RUBY
puts 'Hi from puts'
raise
end
alias_method :error, :verify_next_message
alias_method :info, :verify_next_message
RUBY
end

it "logs the error with file and line numbers changed in the stacktrace, and raises an exception" do
allow($miq_ae_logger).to receive(:error).and_call_original
expect($miq_ae_logger).to receive(:error).with("Method STDERR: /my/automate/method:2:in `<main>': unhandled exception").at_least(:once)

expect { subject }.to raise_error(MiqAeException::UnknownMethodRc)
end
end

aem = double("AEM", :data => script, :fqname => "fqname")
inputs = []
logger_stub = logger_klass.new
obj = double("OBJ", :workspace => workspace)
svc = MiqAeMethodService::MiqAeService.new(workspace, inputs, aem.data, logger_stub)
context "with a script that raises in a nested method" do
let(:script) do
<<-RUBY
def my_method
raise
end
expect(MiqAeMethodService::MiqAeService).to receive(:new).with(workspace, inputs, aem.data).and_return(svc)
puts 'Hi from puts'
my_method
RUBY
end

expect($miq_ae_logger).to receive(:info).with("<AEMethod [fqname]> Starting ").ordered
expect(logger_stub).to receive(:sleep).and_call_original.ordered
expect($miq_ae_logger).to receive(:info).with("<AEMethod [fqname]> Ending").ordered
expect($miq_ae_logger).to receive(:info).with("Method exited with rc=MIQ_OK").ordered
it "logs the error with file and line numbers changed in the stacktrace, and raises an exception" do
allow($miq_ae_logger).to receive(:error).and_call_original
expect($miq_ae_logger).to receive(:error).with("Method STDERR: /my/automate/method:2:in `my_method': unhandled exception").at_least(:once)
expect($miq_ae_logger).to receive(:error).with("Method STDERR: \tfrom /my/automate/method:6:in `<main>'").at_least(:once)

expect(described_class.send(:invoke_inline_ruby, aem, obj, inputs)).to eq(0)
expect { subject }.to raise_error(MiqAeException::UnknownMethodRc)
end
end

expect(logger_stub.expected_messages).to eq([])
context "with a script that does I/O" do
let(:script) do
<<-RUBY
puts 'Hi from puts'
STDOUT.puts 'Hi from STDOUT.puts'
$stdout.puts 'Hi from $stdout.puts'
STDERR.puts 'Hi from STDERR.puts'
$stderr.puts 'Hi from $stderr.puts'
$evm.logger.sleep
RUBY
end

it "writes to the logger synchronously" do
logger_stub = Class.new do
attr_reader :expected_messages

def initialize
@expected_messages = [
"Method STDOUT: Hi from puts",
"Method STDOUT: Hi from STDOUT.puts",
"Method STDOUT: Hi from $stdout.puts",
"Method STDERR: Hi from STDERR.puts",
"Method STDERR: Hi from $stderr.puts",
]
end

def sleep
# Raise if all messages have not already been written before a method like sleep runs.
raise unless expected_messages == []
end

def verify_next_message(message)
expected = expected_messages.shift
return if message == expected
puts "Expected: #{expected.inspect}, Got: #{message.inspect}"
raise
end
alias_method :error, :verify_next_message
alias_method :info, :verify_next_message
end.new

svc = MiqAeMethodService::MiqAeService.new(workspace, [], nil, logger_stub)
expect(MiqAeMethodService::MiqAeService).to receive(:new).with(workspace, []).and_return(svc)

expect($miq_ae_logger).to receive(:info).with("<AEMethod [/my/automate/method]> Starting ").ordered
expect(logger_stub).to receive(:sleep).and_call_original.ordered
expect($miq_ae_logger).to receive(:info).with("<AEMethod [/my/automate/method]> Ending").ordered
expect($miq_ae_logger).to receive(:info).with("Method exited with rc=MIQ_OK").ordered

expect(subject).to eq(0)
expect(logger_stub.expected_messages).to eq([])
end
end
end
end

0 comments on commit 3da93b0

Please sign in to comment.