Skip to content

[WIP] Use logger wrap #571

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 2 commits into
base: master
Choose a base branch
from
Open

[WIP] Use logger wrap #571

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
d1a9849
Move Logger resource_id param to initializer
agrare Apr 4, 2025
82b80a7
Use .wrap for RequestLogger
agrare Apr 24, 2025
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
73 changes: 17 additions & 56 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,28 @@
module ManageIQ
module AutomationEngine
class Logger < ManageIQ::Loggers::Base
attr_reader :automation_log_wrapper
attr_reader :resource_id

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

def initialize(*args, automation_log_wrapper:, **kwargs)
@automation_log_wrapper = automation_log_wrapper
super(*args, **kwargs)
end

def self.create_log_wrapper(io = File::NULL)
# 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"))
def self.create_log_wrapper(log_wrapper: nil, resource_id: nil)
log_wrapper ||= $miq_ae_logger

new(nil, :progname => "automation", :resource_id => resource_id).wrap(log_wrapper)
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)
severity ||= Logger::UNKNOWN
return true if severity < @level || resource_id.nil?

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 @@ -35,45 +32,9 @@ def self.create_log_wrapper(io = File::NULL)
end
end

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
RequestLog.create(:message => message, :severity => format_severity(severity), :resource_id => resource_id)

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)
true
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)

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