From d1a9849e91165a2dd81f3f43c6d34f1bf309dd67 Mon Sep 17 00:00:00 2001 From: Adam Grare Date: Fri, 4 Apr 2025 08:57:53 -0400 Subject: [PATCH 1/2] Move Logger resource_id param to initializer --- lib/manageiq/automation_engine/engine.rb | 4 +- lib/manageiq/automation_engine/logger.rb | 67 +++------- .../engine/miq_ae_engine.rb | 3 +- .../miq_ae_engine/miq_ae_builtin_method.rb | 9 +- .../engine/miq_ae_engine/miq_ae_method.rb | 39 +++--- .../engine/miq_ae_engine/miq_ae_object.rb | 11 +- .../miq_ae_engine/miq_ae_state_machine.rb | 28 ++-- .../miq_ae_engine/miq_ae_workspace_runtime.rb | 18 ++- .../miq_ae_method_service/miq_ae_service.rb | 18 +-- .../miq_ae_service_model_base.rb | 9 +- .../manageiq/automation_engine/logger_spec.rb | 123 ++++++++++-------- 11 files changed, 162 insertions(+), 167 deletions(-) diff --git a/lib/manageiq/automation_engine/engine.rb b/lib/manageiq/automation_engine/engine.rb index 22e620ad..384abe14 100644 --- a/lib/manageiq/automation_engine/engine.rb +++ b/lib/manageiq/automation_engine/engine.rb @@ -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) diff --git a/lib/manageiq/automation_engine/logger.rb b/lib/manageiq/automation_engine/logger.rb index 70ab8c25..7f5cca4b 100644 --- a/lib/manageiq/automation_engine/logger.rb +++ b/lib/manageiq/automation_engine/logger.rb @@ -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 + + 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 @@ -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 diff --git a/lib/miq_automation_engine/engine/miq_ae_engine.rb b/lib/miq_automation_engine/engine/miq_ae_engine.rb index a3907693..16949168 100644 --- a/lib/miq_automation_engine/engine/miq_ae_engine.rb +++ b/lib/miq_automation_engine/engine/miq_ae_engine.rb @@ -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 diff --git a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_builtin_method.rb b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_builtin_method.rb index 860cff1a..15a4590d 100644 --- a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_builtin_method.rb +++ b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_builtin_method.rb @@ -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) @@ -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) @@ -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 diff --git a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_method.rb b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_method.rb index d474452a..a93ffa08 100644 --- a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_method.rb +++ b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_method.rb @@ -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 @@ -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 @@ -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 @@ -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(" Starting ", :resource_id => miq_request_id) + obj.workspace.logger.info(" Starting ") rc, msg = run_ruby_method(code, miq_request_id) - $miq_ae_logger.info(" Ending", :resource_id => miq_request_id) + obj.workspace.logger.info(" Ending") process_ruby_method_results(rc, msg, miq_request_id) end end @@ -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) @@ -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 @@ -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) @@ -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) @@ -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 diff --git a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_object.rb b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_object.rb index 18ba5c26..e1ec41c9 100644 --- a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_object.rb +++ b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_object.rb @@ -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 @@ -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 @@ -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 (?) @@ -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 = [] @@ -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) diff --git a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_state_machine.rb b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_state_machine.rb index 9edf03f0..f15cd534 100644 --- a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_state_machine.rb +++ b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_state_machine.rb @@ -51,15 +51,15 @@ def process_state_step_with_error_handling(field, step = nil) current_state = @workspace.root['ae_state'] yield if @workspace.root['ae_next_state'].present? && current_state != @workspace.root['ae_next_state'] - $miq_ae_logger.warn("Skipping to state #{@workspace.root['ae_next_state']}", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.warn("Skipping to state #{@workspace.root['ae_next_state']}") @workspace.root['ae_result'] = 'skip' if step == 'on_entry' end rescue MiqAeException::StopInstantiation => e - $miq_ae_logger.error("State=<#{field['name']}> running #{step} raised exception: <#{e.message}>", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.error("State=<#{field['name']}> running #{step} raised exception: <#{e.message}>") raise rescue StandardError => e error_message = "State=<#{field['name']}> running #{step} raised exception: <#{e.message}>" - $miq_ae_logger.error(error_message, :resource_id => @workspace.find_miq_request_id) + @workspace.logger.error(error_message) @workspace.root['ae_reason'] = error_message @workspace.root['ae_result'] = 'error' end @@ -87,20 +87,20 @@ def process_state(field, message, args) # Check the ae_result and set the next state appropriately if @workspace.root['ae_result'] == 'ok' - $miq_ae_logger.info("Processed State=[#{field['name']}]", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("Processed State=[#{field['name']}]") elsif @workspace.root['ae_result'] == 'skip' - $miq_ae_logger.warn("Skipping State=[#{field['name']}]", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.warn("Skipping State=[#{field['name']}]") return set_next_state(field, message) elsif %w[retry restart async_launch].include?(@workspace.root['ae_result']) increment_state_retries elsif @workspace.root['ae_result'] == 'error' - $miq_ae_logger.warn("Error in State=[#{field['name']}]", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.warn("Error in State=[#{field['name']}]") # Process on_error method return process_state_step_with_error_handling(field, 'on_error') do process_state_method(field, 'on_error') if @workspace.root['ae_result'] == 'continue' - $miq_ae_logger.warn("Resetting Error in State=[#{field['name']}]", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.warn("Resetting Error in State=[#{field['name']}]") @workspace.root['ae_result'] = 'ok' set_next_state(field, message) end @@ -126,7 +126,7 @@ def process_state(field, message, args) def process_state_relationship(field, message, args) relationship = get_value(field, :aetype_relationship) unless relationship.blank? || relationship.lstrip[0, 1] == '#' - $miq_ae_logger.info("Processing State=[#{field['name']}]", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("Processing State=[#{field['name']}]") @workspace.root['ae_state_step'] = 'main' enforce_state_maxima(field) match_data = STATE_METHOD_REGEX.match(relationship) @@ -136,7 +136,7 @@ def process_state_relationship(field, message, args) process_relationship_raw(relationship, message, args, field['name'], field['collect']) raise MiqAeException::MiqAeDatastoreError, "empty relationship" unless @rels[field['name']] end - $miq_ae_logger.info("Processed State=[#{field['name']}] with Result=[#{@workspace.root['ae_result']}]", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("Processed State=[#{field['name']}] with Result=[#{@workspace.root['ae_result']}]") end end @@ -147,7 +147,7 @@ def process_state_method(field, method_name) method = substitute_value(method.strip) next if method.blank? || method.lstrip[0, 1] == '#' - $miq_ae_logger.info("In State=[#{field['name']}], invoking [#{method_name}] method=[#{method}]", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("In State=[#{field['name']}], invoking [#{method_name}] method=[#{method}]") @workspace.root['ae_status_state'] = method_name @workspace.root['ae_state'] = field['name'] @workspace.root['ae_state_step'] = method_name @@ -171,13 +171,13 @@ def set_next_state(field, message) if %w[skip ok].include?(@workspace.root['ae_result']) @workspace.root['ae_state'] = next_state(field['name'], message).to_s reset_state_maxima_metadata - $miq_ae_logger.info("Next State=[#{@workspace.root['ae_state']}]", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("Next State=[#{@workspace.root['ae_state']}]") @workspace.root['ae_result'] = 'ok' elsif @workspace.root['ae_result'] == 'restart' - $miq_ae_logger.info("State=[#{field['name']}] has requested a restart", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("State=[#{field['name']}] has requested a restart") @workspace.root['ae_result'] = 'retry' @workspace.root['ae_state'] = restart_state(message).to_s - $miq_ae_logger.info("Will restart at State=[#{@workspace.root['ae_state']}]", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("Will restart at State=[#{@workspace.root['ae_state']}]") end end @@ -190,7 +190,7 @@ def restart_state(message) def validate_state(states) next_state = @workspace.root['ae_next_state'] if next_state.present? && states.exclude?(next_state) - $miq_ae_logger.error("Next State=#{next_state} is invalid aborting state machine", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.error("Next State=#{next_state} is invalid aborting state machine") raise MiqAeException::AbortInstantiation, "Invalid state specified <#{next_state}>" end end diff --git a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_workspace_runtime.rb b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_workspace_runtime.rb index 51e4a231..8f4d47d7 100644 --- a/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_workspace_runtime.rb +++ b/lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_workspace_runtime.rb @@ -28,6 +28,10 @@ def initialize(options = {}) delegate :prepend_namespace=, :to => :@dom_search + def logger + @logger ||= ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => find_miq_request_id) + end + def readonly? @readonly end @@ -63,7 +67,7 @@ def self.instantiate_with_user(uri, user, attrs) workspace rescue MiqAeException => err - $miq_ae_logger.error(err.message, :resource_id => miq_request_id) + workspace.logger.error(err.message, :resource_id => miq_request_id) ensure clear_stored_workspace end @@ -160,7 +164,7 @@ def instantiate(uri, user, root = nil) args = MiqAeUri.query2hash(query) miq_request_id = self.class.find_miq_request_id(args) - $miq_ae_logger.info("Instantiating [#{ManageIQ::Password.sanitize_string(uri)}]", :resource_id => miq_request_id) if root.nil? + logger.info("Instantiating [#{ManageIQ::Password.sanitize_string(uri)}]") if root.nil? if (ae_state_data = args.delete('ae_state_data')) @persist_state_hash.merge!(YAML.load(ae_state_data)) @@ -209,18 +213,18 @@ def instantiate(uri, user, root = nil) end obj.process_fields(message) rescue MiqAeException::MiqAeDatastoreError => err - $miq_ae_logger.error(err.message, :resource_id => miq_request_id) + logger.error(err.message) rescue MiqAeException::AssertionFailure => err - $miq_ae_logger.info(err.message, :resource_id => miq_request_id) + logger.info(err.message) delete(obj) rescue MiqAeException::StopInstantiation => err - $miq_ae_logger.info("Stopping instantiation because [#{err.message}]", :resource_id => miq_request_id) + logger.info("Stopping instantiation because [#{err.message}]") delete(obj) rescue MiqAeException::UnknownMethodRc => err - $miq_ae_logger.error("Aborting instantiation (unknown method return code) because [#{err.message}]", :resource_id => miq_request_id) + logger.error("Aborting instantiation (unknown method return code) because [#{err.message}]") raise rescue MiqAeException::AbortInstantiation => err - $miq_ae_logger.info("Aborting instantiation because [#{err.message}]", :resource_id => miq_request_id) + logger.info("Aborting instantiation because [#{err.message}]") raise ensure @current.pop if pushed diff --git a/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service.rb b/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service.rb index e9f46825..4c06752a 100644 --- a/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service.rb +++ b/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service.rb @@ -69,7 +69,7 @@ def disconnect_sql def log(level, msg) Thread.current["tracking_label"] = @tracking_label - $miq_ae_logger.send(level, " #{ManageIQ::Password.sanitize_string(msg)}", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.send(level, " #{ManageIQ::Password.sanitize_string(msg)}") end def set_state_var(name, value) @@ -98,7 +98,7 @@ def ansible_stats_vars def set_service_var(name, value) if service_object.nil? - $miq_ae_logger.error("Service object not found in root object, set_service_var skipped for #{name} = #{value}", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.error("Service object not found in root object, set_service_var skipped for #{name} = #{value}") return end @@ -133,7 +133,7 @@ def instantiate(uri) MiqAeServiceObject.new(obj, self) rescue StandardError => e - $miq_ae_logger.error("instantiate failed : #{e.message}", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.error("instantiate failed : #{e.message}") nil end @@ -235,7 +235,7 @@ def ar_object(svc_obj) def notification_type(values_hash) type = values_hash[:type].present? ? values_hash[:type].to_sym : default_notification_type(values_hash) type.tap do |t| - $miq_ae_logger.info("Validating Notification type: #{t}", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("Validating Notification type: #{t}") valid_type = NotificationType.find_by(:name => t) raise ArgumentError, "Invalid notification type specified" unless valid_type end @@ -257,7 +257,7 @@ def create_notification_with_user!(values_hash) subject = notification_subject(values_hash) options[:message] = values_hash[:message] if values_hash[:message].present? - $miq_ae_logger.info("Calling Create Notification type: #{type} subject type: #{subject.class.base_class.name} id: #{subject.id} options: #{options.inspect}", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("Calling Create Notification type: #{type} subject type: #{subject.class.base_class.name} id: #{subject.id} options: #{options.inspect}") MiqAeServiceModelBase.wrap_results(Notification.create!(:type => type, :subject => subject, :options => options, @@ -275,7 +275,7 @@ def instance_create(path, values_hash = {}) return false unless editable_instance?(path) ns, klass, instance = MiqAeEngine::MiqAePath.split(path) - $miq_ae_logger.info("Instance Create for ns: #{ns} class #{klass} instance: #{instance}", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.info("Instance Create for ns: #{ns} class #{klass} instance: #{instance}") aec = MiqAeClass.lookup_by_namespace_and_name(ns, klass) return false if aec.nil? @@ -389,7 +389,7 @@ def editable_instance?(path) domain = MiqAeDomain.lookup_by_fqname(dom, false) return false unless domain - $miq_ae_logger.warn("path=#{path.inspect} : is not editable", :resource_id => @workspace.find_miq_request_id) unless domain.editable?(@workspace.ae_user) + @workspace.logger.warn("path=#{path.inspect} : is not editable") unless domain.editable?(@workspace.ae_user) domain.editable?(@workspace.ae_user) end @@ -397,7 +397,7 @@ def owned_domain?(dom) domains = @workspace.ae_user.current_tenant.ae_domains.collect(&:name).map(&:upcase) return true if domains.include?(dom.upcase) - $miq_ae_logger.warn("domain=#{dom} : is not editable", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.warn("domain=#{dom} : is not editable") false end @@ -405,7 +405,7 @@ def visible_domain?(dom) domains = @workspace.ae_user.current_tenant.visible_domains.collect(&:name).map(&:upcase) return true if domains.include?(dom.upcase) - $miq_ae_logger.warn("domain=#{dom} : is not viewable", :resource_id => @workspace.find_miq_request_id) + @workspace.logger.warn("domain=#{dom} : is not viewable") false end diff --git a/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb b/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb index aa8cdac1..e60cb4d6 100644 --- a/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb +++ b/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb @@ -362,7 +362,8 @@ def object_send(name, *params) begin @object.public_send(name, *params) rescue Exception # rubocop:disable Lint/RescueException - $miq_ae_logger.error("The following error occurred during instance method <#{name}> for AR object <#{@object.inspect}>", :resource_id => self.class.find_miq_request_id(@object)) + logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => self.class.find_miq_request_id(@object)) + logger.error("The following error occurred during instance method <#{name}> for AR object <#{@object.inspect}>") raise end end @@ -381,9 +382,9 @@ def self.ar_method ActiveRecord::Base.connection.clear_query_cache if ActiveRecord::Base.connection.query_cache_enabled yield rescue Exception => err # rubocop:disable Lint/RescueException - miq_request_id = find_miq_request_id(@object) - $miq_ae_logger.error("MiqAeServiceModelBase.ar_method raised: <#{err.class}>: <#{err.message}>", :resource_id => miq_request_id) - $miq_ae_logger.error(err.backtrace.join("\n"), :resource_id => miq_request_id) + logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => find_miq_request_id(@object)) + logger.error("MiqAeServiceModelBase.ar_method raised: <#{err.class}>: <#{err.message}>") + logger.error(err.backtrace.join("\n")) raise ensure begin diff --git a/spec/lib/manageiq/automation_engine/logger_spec.rb b/spec/lib/manageiq/automation_engine/logger_spec.rb index f2b2f0a3..92826443 100644 --- a/spec/lib/manageiq/automation_engine/logger_spec.rb +++ b/spec/lib/manageiq/automation_engine/logger_spec.rb @@ -1,7 +1,8 @@ describe ManageIQ::AutomationEngine::Logger do let(:io) { StringIO.new } + let(:resource_id) { nil } subject do - described_class.create_log_wrapper(io).tap do |logger| + described_class.create_log_wrapper(:io => io, :resource_id => resource_id).tap do |logger| logger.level = Logger::DEBUG end end @@ -10,42 +11,48 @@ describe "##{sev}" do let(:sev_uc) { sev.upcase } - it "with a resource_id" do - subject.public_send(sev, "foo", :resource_id => 123) + context "with a resource_id" do + let(:resource_id) { 123 } - expect(io.string).to match(/#{sev_uc}.*foo/) + it "creates the RequestLog record" do + subject.public_send(sev, "foo") - expect(RequestLog.count).to eq(1) - log = RequestLog.first - expect(log.message).to eq("foo") - expect(log.severity).to eq(sev_uc) - expect(log.resource_id).to eq(123) - end + expect(io.string).to match(/#{sev_uc}.*foo/) - it "with a resource_id and a block" do - subject.public_send(sev, :resource_id => 123) { "foo" } + expect(RequestLog.count).to eq(1) + log = RequestLog.first + expect(log.message).to eq("foo") + expect(log.severity).to eq(sev_uc) + expect(log.resource_id).to eq(123) + end - expect(io.string).to match(/#{sev_uc}.*foo/) + it "with a block creates the RequestLog record" do + subject.public_send(sev) { "foo" } - expect(RequestLog.count).to eq(1) - log = RequestLog.first - expect(log.message).to eq("foo") - expect(log.severity).to eq(sev_uc) - expect(log.resource_id).to eq(123) + expect(io.string).to match(/#{sev_uc}.*foo/) + + expect(RequestLog.count).to eq(1) + log = RequestLog.first + expect(log.message).to eq("foo") + expect(log.severity).to eq(sev_uc) + expect(log.resource_id).to eq(123) + end end - it "without a resource_id" do - subject.public_send(sev, "foo") + context "without a resource_id" do + it "doesn't create a RequestLog record" do + subject.public_send(sev, "foo") - expect(io.string).to match(/#{sev_uc}.*foo/) - expect(RequestLog.count).to eq(0) - end + expect(io.string).to match(/#{sev_uc}.*foo/) + expect(RequestLog.count).to eq(0) + end - it "without a resource_id and with a block" do - subject.public_send(sev) { "foo" } + it "with a block doesn't create the RequestLog" do + subject.public_send(sev) { "foo" } - expect(io.string).to match(/#{sev_uc}.*foo/) - expect(RequestLog.count).to eq(0) + expect(io.string).to match(/#{sev_uc}.*foo/) + expect(RequestLog.count).to eq(0) + end end end end @@ -54,10 +61,14 @@ context "when the level doesn't include DEBUG" do before { subject.level = Logger::INFO } - it "with a resource_id" do - subject.debug("foo", :resource_id => 123) + context "with a resource_id" do + let(:resource_id) { 123 } - expect(RequestLog.count).to eq(0) + it "doesn't create a request_log record" do + subject.debug("foo") + + expect(RequestLog.count).to eq(0) + end end it "without a resource_id" do @@ -70,7 +81,8 @@ end describe "supports container logging" do - subject { described_class.create_log_wrapper } + subject { described_class.create_log_wrapper(:resource_id => resource_id) } + let(:automation_log_wrapper) { subject.automation_log_wrapper } let(:container_log) do if automation_log_wrapper.respond_to?(:broadcasts) @@ -87,38 +99,45 @@ allow(container_log.logdev).to receive(:write) end - it "with a resource_id" do - expect(subject.logdev).to be_nil # i.e. won't write to a file - expect(subject).to receive(:add).with(Logger::INFO, "foo", "automation").and_call_original - expect(container_log).to receive(:add).with(Logger::INFO, "foo", "automation").and_call_original + context "with a resource_id" do + let(:resource_id) { 123 } - subject.info("foo", :resource_id => 123) + it "creates a request_log record" do + expect(subject.logdev).to be_nil # i.e. won't write to a file + expect(subject).to receive(:add).with(Logger::INFO, nil, "foo").and_call_original + expect(container_log).to receive(:add).with(Logger::INFO, nil, "foo").and_call_original + expect(container_log.logdev).to receive(:write).with(/"message":"foo"/) - expect(RequestLog.count).to eq(1) - log = RequestLog.first - expect(log.message).to eq("foo") - expect(log.severity).to eq("INFO") - expect(log.resource_id).to eq(123) - end + subject.info("foo") - it "with a resource_id and a block" do - expect(subject.logdev).to be_nil # i.e. won't write to a file - expect(subject).to receive(:add).with(Logger::INFO, "foo", "automation").and_call_original - expect(container_log).to receive(:add).with(Logger::INFO, "foo", "automation").and_call_original + expect(RequestLog.count).to eq(1) + log = RequestLog.first + expect(log.message).to eq("foo") + expect(log.severity).to eq("INFO") + expect(log.resource_id).to eq(123) + end + + it "with a block creates a request_log record" do + expect(subject.logdev).to be_nil # i.e. won't write to a file + expect(subject).to receive(:add).with(Logger::INFO, nil, nil).and_call_original + expect(container_log).to receive(:add).with(Logger::INFO, nil, nil).and_call_original + expect(container_log.logdev).to receive(:write).with(/"message":"foo"/) - subject.info(:resource_id => 123) { "foo" } + subject.info { "foo" } - expect(RequestLog.count).to eq(1) - log = RequestLog.first - expect(log.message).to eq("foo") - expect(log.severity).to eq("INFO") - expect(log.resource_id).to eq(123) + expect(RequestLog.count).to eq(1) + log = RequestLog.first + expect(log.message).to eq("foo") + expect(log.severity).to eq("INFO") + expect(log.resource_id).to eq(123) + end end it "without a resource_id" do expect(subject.logdev).to be_nil # i.e. won't write to a file expect(subject).to receive(:add).with(Logger::INFO, nil, "foo").and_call_original expect(container_log).to receive(:add).with(Logger::INFO, nil, "foo").and_call_original + expect(container_log.logdev).to receive(:write).with(/"message":"foo"/) subject.info("foo") From 82b80a74ae2451951966954071716e3db1c07c27 Mon Sep 17 00:00:00 2001 From: Adam Grare Date: Thu, 24 Apr 2025 11:56:22 -0400 Subject: [PATCH 2/2] Use .wrap for RequestLogger --- lib/manageiq/automation_engine/logger.rb | 24 ++++++++++-------------- 1 file changed, 10 insertions(+), 14 deletions(-) diff --git a/lib/manageiq/automation_engine/logger.rb b/lib/manageiq/automation_engine/logger.rb index 7f5cca4b..4de12c3c 100644 --- a/lib/manageiq/automation_engine/logger.rb +++ b/lib/manageiq/automation_engine/logger.rb @@ -1,29 +1,25 @@ module ManageIQ module AutomationEngine class Logger < ManageIQ::Loggers::Base - attr_reader :automation_log_wrapper, :resource_id + attr_reader :resource_id - def initialize(*args, automation_log_wrapper:, resource_id: nil, **kwargs) - @automation_log_wrapper = automation_log_wrapper - @resource_id = resource_id + def initialize(*args, resource_id: nil, **kwargs) + @resource_id = resource_id super(*args, **kwargs) end - 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 => automation_log_wrapper || Vmdb::Loggers.create_logger("automation.log"), :resource_id => resource_id) + 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(severity, message = nil, progname = nil, &block) - automation_log_wrapper.add(severity, message, progname, &block) - severity ||= Logger::UNKNOWN - return true if severity < @level + return true if severity < @level || resource_id.nil? progname ||= @progname @@ -36,9 +32,9 @@ def add(severity, message = nil, progname = nil, &block) end end - RequestLog.create(:message => message, :severity => format_severity(severity), :resource_id => resource_id) if resource_id + RequestLog.create(:message => message, :severity => format_severity(severity), :resource_id => resource_id) - super + true end end end