Skip to content

Commit 1a57f86

Browse files
agrareagrare
committed
Move Logger resource_id param to initializer
1 parent 8ed0882 commit 1a57f86

File tree

11 files changed

+126
-143
lines changed

11 files changed

+126
-143
lines changed

‎lib/manageiq/automation_engine/engine.rb

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -17,9 +17,7 @@ def self.plugin_name
1717
end
1818

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

2523
def self.apply_logger_config(config)

‎lib/manageiq/automation_engine/logger.rb

Lines changed: 17 additions & 52 deletions
Original file line numberDiff line numberDiff line change
@@ -1,31 +1,32 @@
11
module ManageIQ
22
module AutomationEngine
33
class Logger < ManageIQ::Loggers::Base
4-
attr_reader :automation_log_wrapper
4+
attr_reader :automation_log_wrapper, :resource_id
55

6-
def initialize(*args, automation_log_wrapper:, **kwargs)
6+
def initialize(*args, automation_log_wrapper:, resource_id: nil, **kwargs)
77
@automation_log_wrapper = automation_log_wrapper
8+
@resource_id = resource_id
9+
810
super(*args, **kwargs)
911
end
1012

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

18-
private def add_to_db(severity, message = nil, progname = nil, resource_id: nil)
19-
return [severity, message, progname] unless resource_id
20+
private
21+
22+
def add(severity, message = nil, progname = nil, &block)
23+
automation_log_wrapper.add(severity, message, progname, &block)
24+
25+
severity ||= Logger::UNKNOWN
26+
return true if resource_id.nil? || severity < @level
27+
28+
progname ||= @progname
2029

21-
# Adapted from Logger#add
22-
severity ||= UNKNOWN
23-
if severity < level
24-
return [severity, message, progname]
25-
end
26-
if progname.nil?
27-
progname = @progname
28-
end
2930
if message.nil?
3031
if block_given?
3132
message = yield
@@ -35,45 +36,9 @@ def self.create_log_wrapper(io = File::NULL)
3536
end
3637
end
3738

38-
RequestLog.create(:message => message, :severity => format_severity(severity), :resource_id => resource_id) if resource_id
39+
RequestLog.create(:message => message, :severity => format_severity(severity), :resource_id => resource_id)
3940

40-
[severity, message, progname]
41-
end
42-
43-
def info(progname = nil, resource_id: nil, &block)
44-
severity, message, progname = add_to_db(INFO, nil, progname, resource_id: resource_id, &block)
45-
automation_log_wrapper.add(severity, message, progname, &block)
46-
add(severity, message, progname, &block)
47-
end
48-
49-
def debug(progname = nil, resource_id: nil, &block)
50-
severity, message, progname = add_to_db(DEBUG, nil, progname, resource_id: resource_id, &block)
51-
automation_log_wrapper.add(severity, message, progname, &block)
52-
add(severity, message, progname, &block)
53-
end
54-
55-
def warn(progname = nil, resource_id: nil, &block)
56-
severity, message, progname = add_to_db(WARN, nil, progname, resource_id: resource_id, &block)
57-
automation_log_wrapper.add(severity, message, progname, &block)
58-
add(severity, message, progname, &block)
59-
end
60-
61-
def error(progname = nil, resource_id: nil, &block)
62-
severity, message, progname = add_to_db(ERROR, nil, progname, resource_id: resource_id, &block)
63-
automation_log_wrapper.add(severity, message, progname, &block)
64-
add(severity, message, progname, &block)
65-
end
66-
67-
def fatal(progname = nil, resource_id: nil, &block)
68-
severity, message, progname = add_to_db(FATAL, nil, progname, resource_id: resource_id, &block)
69-
automation_log_wrapper.add(severity, message, progname, &block)
70-
add(severity, message, progname, &block)
71-
end
72-
73-
def unknown(progname = nil, resource_id: nil, &block)
74-
severity, message, progname = add_to_db(UNKNOWN, nil, progname, resource_id: resource_id, &block)
75-
automation_log_wrapper.add(severity, message, progname, &block)
76-
add(severity, message, progname, &block)
41+
super
7742
end
7843
end
7944
end

‎lib/miq_automation_engine/engine/miq_ae_engine.rb

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -336,7 +336,8 @@ def self.ae_user_object(options = {})
336336
User.find_by!(:id => options[:user_id]).tap do |obj|
337337
obj.current_group = MiqGroup.find_by!(:id => options[:miq_group_id]) unless options[:miq_group_id] == obj.current_group.id
338338
miq_request_id = options[:object_type].to_s.include?("Request") ? options[:object_id] : nil
339-
$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)
339+
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
340+
logger.info("User [#{obj.userid}] with current group ID [#{obj.current_group.id}] name [#{obj.current_group.description}]")
340341
end
341342
end
342343
end

‎lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_builtin_method.rb

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -54,7 +54,7 @@ def self.powershell(_obj, inputs)
5454
def self.miq_parse_provider_category(obj, _inputs)
5555
provider_category = nil
5656
ATTRIBUTE_LIST.detect { |attr| provider_category = category_for_key(obj, attr) }
57-
$miq_ae_logger.info("Setting provider_category to: #{provider_category}", :resource_id => obj.workspace.find_miq_request_id)
57+
obj.workspace.logger.info("Setting provider_category to: #{provider_category}")
5858
obj.workspace.root["ae_provider_category"] = provider_category || UNKNOWN
5959

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

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

8382
def self.miq_host_and_storage_least_utilized(obj, _inputs)
@@ -223,7 +222,7 @@ def self.prepend_vendor(obj)
223222
vendor = nil
224223
ATTRIBUTE_LIST.detect { |attr| vendor = detect_vendor(obj.workspace.root[attr], attr) }
225224
if vendor
226-
$miq_ae_logger.info("Setting prepend_namespace to: #{vendor}", :resource_id => obj.workspace.find_miq_request_id)
225+
obj.workspace.logger.info("Setting prepend_namespace to: #{vendor}")
227226
obj.workspace.prepend_namespace = vendor.downcase
228227
end
229228
end

‎lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_method.rb

Lines changed: 24 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -86,9 +86,9 @@ def self.invoke(obj, aem, args)
8686
end
8787

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

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

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

107107
# 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
168168
private_class_method :with_automation_env
169169

170170
def self.process_ruby_method_results(return_code, msg, miq_request_id)
171+
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
172+
171173
case return_code
172174
when MIQ_OK
173-
$miq_ae_logger.info(msg, :resource_id => miq_request_id)
175+
logger.info(msg)
174176
when MIQ_WARN
175-
$miq_ae_logger.warn(msg, :resource_id => miq_request_id)
177+
logger.warn(msg)
176178
when MIQ_STOP
177179
raise MiqAeException::StopInstantiation, msg
178180
when MIQ_ABORT
@@ -199,9 +201,9 @@ def self.invoke_inline_ruby(aem, obj, inputs)
199201
obj.workspace.invoker ||= MiqAeEngine::DrbRemoteInvoker.new(obj.workspace)
200202
bodies, script_info = bodies_and_line_numbers(obj, aem)
201203
obj.workspace.invoker.with_server(inputs, bodies, aem.fqname, script_info) do |code|
202-
$miq_ae_logger.info("<AEMethod [#{aem.fqname}]> Starting ", :resource_id => miq_request_id)
204+
obj.workspace.logger.info("<AEMethod [#{aem.fqname}]> Starting ")
203205
rc, msg = run_ruby_method(code, miq_request_id)
204-
$miq_ae_logger.info("<AEMethod [#{aem.fqname}]> Ending", :resource_id => miq_request_id)
206+
obj.workspace.logger.info("<AEMethod [#{aem.fqname}]> Ending")
205207
process_ruby_method_results(rc, msg, miq_request_id)
206208
end
207209
end
@@ -219,13 +221,15 @@ def self.run_method(cmd, miq_request_id)
219221
yield stdin if block_given?
220222
stdin.close
221223
threads << Thread.new do
224+
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
222225
stdout.each_line do |msg|
223-
$miq_ae_logger.info("Method STDOUT: #{msg.strip}", :resource_id => miq_request_id)
226+
logger.info("Method STDOUT: #{msg.strip}")
224227
end
225228
end
226229
threads << Thread.new do
230+
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
227231
stderr.each_line do |msg|
228-
$miq_ae_logger.error("Method STDERR: #{msg.strip}", :resource_id => miq_request_id)
232+
logger.error("Method STDERR: #{msg.strip}")
229233
end
230234
end
231235
threads.each(&:join)
@@ -237,7 +241,8 @@ def self.run_method(cmd, miq_request_id)
237241
threads = []
238242
rescue StandardError => err
239243
STDERR.puts "** AUTOMATE ** Method exec failed because #{err.class}:#{err.message}" if ENV.key?("CI") # rubocop:disable Style/StderrPuts
240-
$miq_ae_logger.error("Method exec failed because (#{err.class}:#{err.message})", :resource_id => miq_request_id)
244+
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
245+
logger.error("Method exec failed because (#{err.class}:#{err.message})")
241246
rc = MIQ_ABORT
242247
msg = "Method execution failed"
243248
ensure
@@ -248,13 +253,15 @@ def self.run_method(cmd, miq_request_id)
248253
private_class_method :run_method
249254

250255
def self.cleanup(method_pid, threads, miq_request_id)
256+
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
257+
251258
if method_pid
252259
begin
253-
$miq_ae_logger.error("Terminating non responsive method with pid #{method_pid.inspect}", :resource_id => miq_request_id)
260+
logger.error("Terminating non responsive method with pid #{method_pid.inspect}")
254261
Process.kill("TERM", method_pid)
255262
Process.wait(method_pid)
256263
rescue Errno::ESRCH, RangeError => err
257-
$miq_ae_logger.error("Error terminating #{method_pid.inspect} exception #{err}", :resource_id => miq_request_id)
264+
logger.error("Error terminating #{method_pid.inspect} exception #{err}")
258265
end
259266
end
260267
threads.each(&:exit)
@@ -281,6 +288,8 @@ def self.bodies_and_line_numbers(obj, aem)
281288

282289
def self.embedded_methods(workspace, method_obj, current_items, top)
283290
miq_request_id = workspace.find_miq_request_id
291+
logger = ManageIQ::AutomationEngine::Logger.create_log_wrapper(:resource_id => miq_request_id)
292+
284293
method_obj.embedded_methods.each do |name|
285294
method_name, klass, ns = embedded_method_name(name)
286295
match_ns = workspace.overlay_method(ns, klass, method_name)
@@ -290,12 +299,12 @@ def self.embedded_methods(workspace, method_obj, current_items, top)
290299

291300
fqname = "/#{match_ns}/#{klass}/#{method_name}"
292301
if top == fqname
293-
$miq_ae_logger.info("Skipping #{fqname}, cannot reference the top method", :resource_id => miq_request_id)
302+
logger.info("Skipping #{fqname}, cannot reference the top method")
294303
elsif loaded?(current_items, fqname)
295-
$miq_ae_logger.info("Already loaded embedded method #{fqname}", :resource_id => miq_request_id)
304+
logger.info("Already loaded embedded method #{fqname}")
296305
else
297306
current_items << {:data => aem.data, :fqname => fqname}
298-
$miq_ae_logger.info("Loading embedded method #{fqname}", :resource_id => miq_request_id)
307+
logger.info("Loading embedded method #{fqname}")
299308
# Get the embedded methods for the this method
300309
embedded_methods(workspace, aem, current_items, top)
301310
end

‎lib/miq_automation_engine/engine/miq_ae_engine/miq_ae_object.rb

Lines changed: 5 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -78,7 +78,7 @@ def initialize(workspace, namespace, klass, instance, object_name = nil)
7878
Benchmark.realtime_block(:instance_fetch_time) do
7979
@aei = fetch_instance(@instance)
8080
if @aei.nil?
81-
$miq_ae_logger.info("Instance [#{@object_name}] not found in MiqAeDatastore - trying [#{MISSING_INSTANCE}]", :resource_id => @workspace.find_miq_request_id)
81+
@workspace.logger.info("Instance [#{@object_name}] not found in MiqAeDatastore - trying [#{MISSING_INSTANCE}]")
8282
# Try the .missing instance, if the requested one was not found
8383
@attributes['_missing_instance'] = @instance
8484
@instance = MISSING_INSTANCE
@@ -437,7 +437,7 @@ def uri2value(uri, required = false)
437437
begin
438438
methods.each { |meth| value = call_method(value, meth) }
439439
rescue StandardError => err
440-
$miq_ae_logger.warn("Error during substitution: #{err.message}", :resource_id => @workspace.find_miq_request_id)
440+
@workspace.logger.warn("Error during substitution: #{err.message}")
441441
return nil
442442
end
443443
return value
@@ -599,7 +599,7 @@ def process_assertion(field, message, args)
599599
assertion = get_value(field, :aetype_assertion, true)
600600
return if assertion.blank?
601601

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

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

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

642641
if relationship.include?('*')
643642
rels = []
@@ -652,7 +651,7 @@ def process_relationship_raw(relationship, message, args, name, collect)
652651
process_collects(collect, rels)
653652
@rels[name] = rels
654653

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

658657
def process_collects(what, rels)

0 commit comments

Comments
 (0)