Skip to content

[WIP] Move resource id param to logger initialize #570

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

[WIP] Move resource id param to logger initialize #570

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 1 addition & 3 deletions lib/manageiq/automation_engine/engine.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,9 +17,7 @@ def self.plugin_name
end

def self.init_loggers
# This require avoids autoload during rails boot
require 'manageiq/automation_engine/logger'
$miq_ae_logger ||= ManageIQ::AutomationEngine::Logger.create_log_wrapper
$miq_ae_logger ||= Vmdb::Loggers.create_logger("automation.log")
end

def self.apply_logger_config(config)
Expand Down
67 changes: 16 additions & 51 deletions lib/manageiq/automation_engine/logger.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,31 +1,32 @@
module ManageIQ
module AutomationEngine
class Logger < ManageIQ::Loggers::Base
attr_reader :automation_log_wrapper
attr_reader :automation_log_wrapper, :resource_id

def initialize(*args, automation_log_wrapper:, **kwargs)
def initialize(*args, automation_log_wrapper:, resource_id: nil, **kwargs)
@automation_log_wrapper = automation_log_wrapper
@resource_id = resource_id

super(*args, **kwargs)
end

def self.create_log_wrapper(io = File::NULL)
def self.create_log_wrapper(io: File::NULL, automation_log_wrapper: nil, resource_id: nil)
# We modify the interface of logger methods such as info/warn/etc. to allow the keyword argument
# resource_id. Therefore, we need to wrap all client logger calls to these methods to process the resource_id,
# cut the request_log entry and forward the remaining arguments to the logger.
new(io, :progname => "automation", :automation_log_wrapper => Vmdb::Loggers.create_logger("automation.log"))
new(io, :progname => "automation", :automation_log_wrapper => automation_log_wrapper || Vmdb::Loggers.create_logger("automation.log"), :resource_id => resource_id)
end

private def add_to_db(severity, message = nil, progname = nil, resource_id: nil)
return [severity, message, progname] unless resource_id
private

def add(severity, message = nil, progname = nil, &block)
automation_log_wrapper.add(severity, message, progname, &block)

severity ||= Logger::UNKNOWN
return true if severity < @level
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we want our level, or the level of our wrapped log?

(that is the whole automation_log_wrapper.send("#{severity}?") thing)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe we sync the :level from the wrapped logger when we build it initially? I don't want to add more call-outs to the 'hard-coded' log_wrapper since I want to try to drop this and just use a normal broadcast


progname ||= @progname

# Adapted from Logger#add
severity ||= UNKNOWN
if severity < level
return [severity, message, progname]
end
if progname.nil?
progname = @progname
end
if message.nil?
if block_given?
message = yield
Expand All @@ -37,43 +38,7 @@ def self.create_log_wrapper(io = File::NULL)

RequestLog.create(:message => message, :severity => format_severity(severity), :resource_id => resource_id) if resource_id

[severity, message, progname]
end

def info(progname = nil, resource_id: nil, &block)
severity, message, progname = add_to_db(INFO, nil, progname, resource_id: resource_id, &block)
automation_log_wrapper.add(severity, message, progname, &block)
add(severity, message, progname, &block)
end

def debug(progname = nil, resource_id: nil, &block)
severity, message, progname = add_to_db(DEBUG, nil, progname, resource_id: resource_id, &block)
automation_log_wrapper.add(severity, message, progname, &block)
add(severity, message, progname, &block)
end

def warn(progname = nil, resource_id: nil, &block)
severity, message, progname = add_to_db(WARN, nil, progname, resource_id: resource_id, &block)
automation_log_wrapper.add(severity, message, progname, &block)
add(severity, message, progname, &block)
end

def error(progname = nil, resource_id: nil, &block)
severity, message, progname = add_to_db(ERROR, nil, progname, resource_id: resource_id, &block)
automation_log_wrapper.add(severity, message, progname, &block)
add(severity, message, progname, &block)
end

def fatal(progname = nil, resource_id: nil, &block)
severity, message, progname = add_to_db(FATAL, nil, progname, resource_id: resource_id, &block)
automation_log_wrapper.add(severity, message, progname, &block)
add(severity, message, progname, &block)
end

def unknown(progname = nil, resource_id: nil, &block)
severity, message, progname = add_to_db(UNKNOWN, nil, progname, resource_id: resource_id, &block)
automation_log_wrapper.add(severity, message, progname, &block)
add(severity, message, progname, &block)
super
end
end
end
Expand Down
3 changes: 2 additions & 1 deletion lib/miq_automation_engine/engine/miq_ae_engine.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -336,7 +336,8 @@ def self.ae_user_object(options = {})
User.find_by!(:id => options[:user_id]).tap do |obj|
obj.current_group = MiqGroup.find_by!(:id => options[:miq_group_id]) unless options[:miq_group_id] == obj.current_group.id
miq_request_id = options[:object_type].to_s.include?("Request") ? options[:object_id] : nil
$miq_ae_logger.info("User [#{obj.userid}] with current group ID [#{obj.current_group.id}] name [#{obj.current_group.description}]", :resource_id => miq_request_id)
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
logger.info("User [#{obj.userid}] with current group ID [#{obj.current_group.id}] name [#{obj.current_group.description}]")
end
end
end
9 changes: 4 additions & 5 deletions lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_builtin_method.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -54,7 +54,7 @@ def self.powershell(_obj, inputs)
def self.miq_parse_provider_category(obj, _inputs)
provider_category = nil
ATTRIBUTE_LIST.detect { |attr| provider_category = category_for_key(obj, attr) }
$miq_ae_logger.info("Setting provider_category to: #{provider_category}", :resource_id => obj.workspace.find_miq_request_id)
obj.workspace.logger.info("Setting provider_category to: #{provider_category}")
obj.workspace.root["ae_provider_category"] = provider_category || UNKNOWN

prepend_vendor(obj)
Expand All @@ -75,9 +75,8 @@ def self.miq_parse_automation_request(obj, _inputs)
when 'physical_server_provision' then %w[PhysicalServer Lifecycle Provisioning]
end

miq_request_id = obj.workspace.find_miq_request_id
$miq_ae_logger.info("Request:<#{obj['request']}> Target Component:<#{obj['target_component']}> ", :resource_id => miq_request_id)
$miq_ae_logger.info("Target Class:<#{obj['target_class']}> Target Instance:<#{obj['target_instance']}>", :resource_id => miq_request_id)
obj.workspace.logger.info("Request:<#{obj['request']}> Target Component:<#{obj['target_component']}> ")
obj.workspace.logger.info("Target Class:<#{obj['target_class']}> Target Instance:<#{obj['target_instance']}>")
end

def self.miq_host_and_storage_least_utilized(obj, _inputs)
Expand Down Expand Up @@ -223,7 +222,7 @@ def self.prepend_vendor(obj)
vendor = nil
ATTRIBUTE_LIST.detect { |attr| vendor = detect_vendor(obj.workspace.root[attr], attr) }
if vendor
$miq_ae_logger.info("Setting prepend_namespace to: #{vendor}", :resource_id => obj.workspace.find_miq_request_id)
obj.workspace.logger.info("Setting prepend_namespace to: #{vendor}")
obj.workspace.prepend_namespace = vendor.downcase
end
end
Expand Down
39 changes: 24 additions & 15 deletions lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_method.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -86,9 +86,9 @@ def self.invoke(obj, aem, args)
end

if obj.workspace.readonly?
$miq_ae_logger.info("Workspace Instantiation is READONLY -- skipping method [#{aem.fqname}] with inputs [#{inputs.inspect}]", :resource_id => miq_request_id)
obj.workspace.logger.info("Workspace Instantiation is READONLY -- skipping method [#{aem.fqname}] with inputs [#{inputs.inspect}]")
elsif %w[inline builtin uri expression playbook ansible_job_template ansible_workflow_template].include?(aem.location.downcase.strip)
$miq_ae_logger.info("Invoking [#{aem.location}] method [#{aem.fqname}] with inputs [#{inputs.inspect}]", :resource_id => miq_request_id)
obj.workspace.logger.info("Invoking [#{aem.location}] method [#{aem.fqname}] with inputs [#{inputs.inspect}]")
return MiqAeEngine::MiqAeMethod.send("invoke_#{aem.location.downcase.strip}", aem, obj, inputs)
end

Expand All @@ -101,7 +101,7 @@ def self.invoke_external(cmd, workspace, serialize_workspace = false)

if serialize_workspace
ws, = Benchmark.realtime_block(:method_invoke_external_ws_create_time) { MiqAeWorkspace.create(:workspace => workspace) }
$miq_ae_logger.debug("Invoking External Method with MIQ_TOKEN=#{ws.guid} and command=#{cmd}", :resource_id => miq_request_id)
workspace.logger.debug("Invoking External Method with MIQ_TOKEN=#{ws.guid} and command=#{cmd}")
end

# Release connection to thread that will be used by method process. It will return it when it is done
Expand Down Expand Up @@ -168,11 +168,13 @@ def self.with_automation_env
private_class_method :with_automation_env

def self.process_ruby_method_results(return_code, msg, miq_request_id)
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
Copy link
Member

@kbrock kbrock May 30, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if we can simplify the creation of the logger even further. Moving a logger into the workspace is helpful, but also thinking about creating the log wrapper being an even simpler method.

ManageIQ::AutomationEngine.logger(miq_request_id)

That is just an example, haven't thought through this properly.


case return_code
when MIQ_OK
$miq_ae_logger.info(msg, :resource_id => miq_request_id)
logger.info(msg)
when MIQ_WARN
$miq_ae_logger.warn(msg, :resource_id => miq_request_id)
logger.warn(msg)
when MIQ_STOP
raise MiqAeException::StopInstantiation, msg
when MIQ_ABORT
Expand All @@ -199,9 +201,9 @@ def self.invoke_inline_ruby(aem, obj, inputs)
obj.workspace.invoker ||= MiqAeEngine::DrbRemoteInvoker.new(obj.workspace)
bodies, script_info = bodies_and_line_numbers(obj, aem)
obj.workspace.invoker.with_server(inputs, bodies, aem.fqname, script_info) do |code|
$miq_ae_logger.info("<AEMethod [#{aem.fqname}]> Starting ", :resource_id => miq_request_id)
obj.workspace.logger.info("<AEMethod [#{aem.fqname}]> Starting ")
rc, msg = run_ruby_method(code, miq_request_id)
$miq_ae_logger.info("<AEMethod [#{aem.fqname}]> Ending", :resource_id => miq_request_id)
obj.workspace.logger.info("<AEMethod [#{aem.fqname}]> Ending")
process_ruby_method_results(rc, msg, miq_request_id)
end
end
Expand All @@ -219,13 +221,15 @@ def self.run_method(cmd, miq_request_id)
yield stdin if block_given?
stdin.close
threads << Thread.new do
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
stdout.each_line do |msg|
$miq_ae_logger.info("Method STDOUT: #{msg.strip}", :resource_id => miq_request_id)
logger.info("Method STDOUT: #{msg.strip}")
end
end
threads << Thread.new do
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
stderr.each_line do |msg|
$miq_ae_logger.error("Method STDERR: #{msg.strip}", :resource_id => miq_request_id)
logger.error("Method STDERR: #{msg.strip}")
end
end
threads.each(&:join)
Expand All @@ -237,7 +241,8 @@ def self.run_method(cmd, miq_request_id)
threads = []
rescue StandardError => err
STDERR.puts "** AUTOMATE ** Method exec failed because #{err.class}:#{err.message}" if ENV.key?("CI") # rubocop:disable Style/StderrPuts
$miq_ae_logger.error("Method exec failed because (#{err.class}:#{err.message})", :resource_id => miq_request_id)
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
logger.error("Method exec failed because (#{err.class}:#{err.message})")
rc = MIQ_ABORT
msg = "Method execution failed"
ensure
Expand All @@ -248,13 +253,15 @@ def self.run_method(cmd, miq_request_id)
private_class_method :run_method

def self.cleanup(method_pid, threads, miq_request_id)
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)

if method_pid
begin
$miq_ae_logger.error("Terminating non responsive method with pid #{method_pid.inspect}", :resource_id => miq_request_id)
logger.error("Terminating non responsive method with pid #{method_pid.inspect}")
Process.kill("TERM", method_pid)
Process.wait(method_pid)
rescue Errno::ESRCH, RangeError => err
$miq_ae_logger.error("Error terminating #{method_pid.inspect} exception #{err}", :resource_id => miq_request_id)
logger.error("Error terminating #{method_pid.inspect} exception #{err}")
end
end
threads.each(&:exit)
Expand All @@ -281,6 +288,8 @@ def self.bodies_and_line_numbers(obj, aem)

def self.embedded_methods(workspace, method_obj, current_items, top)
miq_request_id = workspace.find_miq_request_id
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)

method_obj.embedded_methods.each do |name|
method_name, klass, ns = embedded_method_name(name)
match_ns = workspace.overlay_method(ns, klass, method_name)
Expand All @@ -290,12 +299,12 @@ def self.embedded_methods(workspace, method_obj, current_items, top)

fqname = "/#{match_ns}/#{klass}/#{method_name}"
if top == fqname
$miq_ae_logger.info("Skipping #{fqname}, cannot reference the top method", :resource_id => miq_request_id)
logger.info("Skipping #{fqname}, cannot reference the top method")
elsif loaded?(current_items, fqname)
$miq_ae_logger.info("Already loaded embedded method #{fqname}", :resource_id => miq_request_id)
logger.info("Already loaded embedded method #{fqname}")
else
current_items << {:data => aem.data, :fqname => fqname}
$miq_ae_logger.info("Loading embedded method #{fqname}", :resource_id => miq_request_id)
logger.info("Loading embedded method #{fqname}")
# Get the embedded methods for the this method
embedded_methods(workspace, aem, current_items, top)
end
Expand Down
11 changes: 5 additions & 6 deletions lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_object.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -78,7 +78,7 @@ def initialize(workspace, namespace, klass, instance, object_name = nil)
Benchmark.realtime_block(:instance_fetch_time) do
@aei = fetch_instance(@instance)
if @aei.nil?
$miq_ae_logger.info("Instance [#{@object_name}] not found in MiqAeDatastore - trying [#{MISSING_INSTANCE}]", :resource_id => @workspace.find_miq_request_id)
@workspace.logger.info("Instance [#{@object_name}] not found in MiqAeDatastore - trying [#{MISSING_INSTANCE}]")
# Try the .missing instance, if the requested one was not found
@attributes['_missing_instance'] = @instance
@instance = MISSING_INSTANCE
Expand Down Expand Up @@ -437,7 +437,7 @@ def uri2value(uri, required = false)
begin
methods.each { |meth| value = call_method(value, meth) }
rescue StandardError => err
$miq_ae_logger.warn("Error during substitution: #{err.message}", :resource_id => @workspace.find_miq_request_id)
@workspace.logger.warn("Error during substitution: #{err.message}")
return nil
end
return value
Expand Down Expand Up @@ -599,7 +599,7 @@ def process_assertion(field, message, args)
assertion = get_value(field, :aetype_assertion, true)
return if assertion.blank?

$miq_ae_logger.info("Evaluating substituted assertion [#{assertion}]", :resource_id => @workspace.find_miq_request_id)
@workspace.logger.info("Evaluating substituted assertion [#{assertion}]")

begin
_, _ = message, args # used by eval (?)
Expand Down Expand Up @@ -636,8 +636,7 @@ def process_relationship_raw(relationship, message, args, name, collect)
query = MiqAeUri.hash2query(args) if query.nil?
relationship = MiqAeUri.join(scheme, userinfo, host, port, registry, path, opaque, query, fragment)

miq_request_id = @workspace.find_miq_request_id
$miq_ae_logger.info("Following Relationship [#{relationship}]", :resource_id => miq_request_id)
@workspace.logger.info("Following Relationship [#{relationship}]")

if relationship.include?('*')
rels = []
Expand All @@ -652,7 +651,7 @@ def process_relationship_raw(relationship, message, args, name, collect)
process_collects(collect, rels)
@rels[name] = rels

$miq_ae_logger.info("Followed Relationship [#{relationship}]", :resource_id => miq_request_id)
@workspace.logger.info("Followed Relationship [#{relationship}]")
end

def process_collects(what, rels)
Expand Down
Loading
Loading