Wrap all automate logger calls to process the request_id

[jrafanie]

Rails 7.1 changed how the broadcast logger works to provide a public API.
https://www.github.com/rails/rails/pull/48615

Our automation logger was subclassing Logger with new behavior and
different method signatures to cut a record in the request_log for
each automation log message, namely by accepting a request_id keyword argument.

So, we intercept all calls to the broadcast logger or a traditional logger to allow
this request_id keyword argument. We process this kwarg and forwarding them along
the rest of the arguments to the broadcast logger/logger.

Rails 7.1 cross repo

[jrafanie]

@agrare @Fryguy please review... This is rails 7.1 only. See the
commit "Use new public 7.1 broadcast logging API" in: ManageIQ/manageiq#23225
The bulk of the relevant change is this:

index c85f3f2506..756e1d3460 100644
--- a/lib/vmdb/loggers.rb
+++ b/lib/vmdb/loggers.rb
@@ -86,23 +86,8 @@ module Vmdb
       log_file = ManageIQ.root.join("log", log_file) if log_file.try(:dirname).to_s == "."
       progname = log_file.try(:basename, ".*").to_s

-      logger_class.new(nil, :progname => progname).tap do |logger|
-        # HACK: In order to access the wrapped logger in test, we inject it as an instance var.
-        if Rails.env.test?
-          logger.instance_variable_set(:@wrapped_logger, wrapped_logger)
-
-          def logger.wrapped_logger
-            @wrapped_logger
-          end
-        end
-
-        logger.extend(ActiveSupport::Logger.broadcast(wrapped_logger))
-        if logger.class.const_defined?(:FormatterMixin)
-          wrapped_logger.formatter.extend(logger.class.const_get(:FormatterMixin))
-        end
-
-        wrapped_logger.progname = progname
-      end
+      logger = logger_class.new(nil, :progname => progname)
+      logger.wrap(wrapped_logger).tap { |broadcaster| broadcaster.progname = progname }
     end

     private_class_method def self.configure_external_loggers

I think the description above describes it well but ultimately, the Automation logger was trying to get in front of all calls to the logger so it can grab the request_id and cut the request_logs row for that log message. The broadcast logger ALSO wants to be in the front of all calls to the logger so it can send the same message to all broadcasts in the logger.

We can't have both in front intercepting all client logging calls. So, we move the behavior we need from the automation logger into the broadcast logger used by automate. That's what the idea is here... minimize the code changes while still working with the broadcast logger.

EDIT: This is extending of the logger with the automation logger behavior was changed to use the logger itself as an object as previously but to then wrap the broadcast logger with rails 7.1 or the original pseudo-broadcast logger in 7.0

[jrafanie]

Note, cross repo test for rails 7.1 includes this PR, see: ManageIQ/manageiq-cross_repo-tests#937

[Fryguy]

I think you only need the wrapped logger? (or does this allow writing to a passed in logdev - not sure why we need that)

[Fryguy]

Oh test - interesting - wondering if we need that at all, and just pass an alternative wrapped_logger

[jrafanie]

yes, it's for test alone to keep the changes minimal

[jrafanie]

Note, we need to do both adds because we're re-implementing the wrapper logger by wrapping itself and retaining the prior behavior. If we change automation engine to remove the outer wrapper, we can then remove these add lines and the corresponding tests for passing in the IO object. When we're on rails 7.1, we can switch to actual broadcast logging and split these out as different broadcasts so we'll have outer wrapper that does no logging and will only for process the request_id kwarg and one or more broadcasts that can write to different outputters.

[Fryguy]

Overall, LGTM - Had one cleanup comment above and a couple minor questions, but I'd be happy merging as is

[jrafanie]

Overall, LGTM - Had one cleanup comment above and a couple minor questions, but I'd be happy merging as is

Should I make it rails 7/7.1 agnostic by adding respond_to?(:broadcasts) logic in the tests?

[Fryguy]

Oh yeah, if you can make it Rails version agnostic that might be better.

[jrafanie]

Oh yeah, if you can make it Rails version agnostic that might be better.

FYI, I updated with the changes mentioned above but will have to wait until we're on rails 7.1 broadcaster before we rip up the existing tests and behavior.

This is now passing on rails 7.0 and rails 7.1 was kicked to test with this branch and it's also 💚

[Fryguy]

Nice

> $miq_ae_logger.info("test", :resource_id => 1234)
{"@timestamp":"2025-02-14T16:57:17.247079","pid":88203,"tid":"256c","level":"debug","message":"  \u001b[1m\u001b[36mTRANSACTION (0.2ms)\u001b[0m  \u001b[1m\u001b[35mBEGIN\u001b[0m"}
{"@timestamp":"2025-02-14T16:57:17.247513","pid":88203,"tid":"256c","level":"debug","message":"  \u001b[1m\u001b[36mRequestLog Create (0.6ms)\u001b[0m  \u001b[1m\u001b[32mINSERT INTO \"request_logs\" (\"message\", \"severity\", \"resource_id\", \"created_at\", \"updated_at\") VALUES ($1, $2, $3, $4, $5) RETURNING \"id\"\u001b[0m  [[\"message\", \"test\"], [\"severity\", \"INFO\"], [\"resource_id\", 1234], [\"created_at\", \"2025-02-14 21:57:17.246293\"], [\"updated_at\", \"2025-02-14 21:57:17.246293\"]]"}
{"@timestamp":"2025-02-14T16:57:17.248428","pid":88203,"tid":"256c","level":"debug","message":"  \u001b[1m\u001b[36mTRANSACTION (0.8ms)\u001b[0m  \u001b[1m\u001b[35mCOMMIT\u001b[0m"}
{"@timestamp":"2025-02-14T16:57:17.248475","pid":88203,"tid":"256c","service":"automation","level":"info","message":"test"}

[jrafanie]

Just so we don't lose it, this is the patch to bring back https://www.github.com/rails/rails/pull/52868 to allow kwargs to be passed through the broadcast logger. We don't need it now but in case I need to search for broadcast logger and kwargs, here's the patch to get it to work in rails 7.1 and 7.2:

new file mode 100644
index 0000000000..5970218465
--- /dev/null
+++ b/lib/patches/broadcast_logger.rb
@@ -0,0 +1,36 @@
+if Rails.version < "8.0"
+  module BroadcastLoggerPassThroughKwargs
+    def add(...)
+      dispatch { |logger| logger.add(...) }
+    end
+    alias_method :log, :add
+
+    def debug(...)
+      dispatch { |logger| logger.debug(...) }
+    end
+
+    def info(...)
+      dispatch { |logger| logger.info(...) }
+    end
+
+    def warn(...)
+      dispatch { |logger| logger.warn(...) }
+    end
+
+    def error(...)
+      dispatch { |logger| logger.error(...) }
+    end
+
+    def fatal(...)
+      dispatch { |logger| logger.fatal(...) }
+    end
+
+    def unknown(...)
+      dispatch { |logger| logger.unknown(...) }
+    end
+
+  end
+  ActiveSupport::BroadcastLogger.prepend(BroadcastLoggerPassThroughKwargs)
+else
+  warn "This Rails patch is not needed with rails 8 due to https://github.com/rails/rails/pull/52868! Remove me for rails 8: #{__FILE__}"
+end
diff --git a/lib/vmdb/loggers.rb b/lib/vmdb/loggers.rb
index 756e1d3460..a1a5f54686 100644
--- a/lib/vmdb/loggers.rb
+++ b/lib/vmdb/loggers.rb
@@ -1,6 +1,7 @@
 require 'manageiq'
 require 'manageiq-loggers'
 require 'miq_environment'
+require 'patches/broadcast_logger'

 module Vmdb
   def self.logger