Move Logger resource_id param to initializer

Author: agrare

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)

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

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

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

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("<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
@@ -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

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)