[PATCH] Fixes #25267 - Provide Ruby logger API method formatter

Since GH is down and I would like to hit 1.20 with this smart-proxy patch, I am sending here for review.

Method formatter is no longer available in the logging gem stack, we used to have it in Ruby logger stack. It was unused in proxy, but dynflow core use it. This patch puts it back, also moves some local variable manipulation outside of synchronized block so errors can be reported from formatters with structured fields.

diff --git a/lib/proxy/log_buffer/decorator.rb b/lib/proxy/log_buffer/decorator.rb
index 21b6288..88d2d11 100644
--- a/lib/proxy/log_buffer/decorator.rb
+++ b/lib/proxy/log_buffer/decorator.rb
@@ -7,6 +7,8 @@ module Proxy::LogBuffer
       @@instance ||= new(::Proxy::LoggerFactory.logger, ::Proxy::LoggerFactory.log_file)
     end
 
+    attr_accessor :formatter
+
     def initialize(logger, log_file, buffer = Proxy::LogBuffer::Buffer.instance)
       @logger = logger
       @buffer = buffer
@@ -28,17 +30,18 @@ module Proxy::LogBuffer
     end
 
     def add(severity, message = nil, progname = nil, backtrace = nil)
+      severity ||= UNKNOWN
+      if message.nil?
+        if block_given?
+          message = yield
+        else
+          message = progname
+        end
+      end
+      message = formatter.call(severity, Time.now.utc, progname, message) if formatter
+      return if message == ''
       @mutex.synchronize do
         handle_log_rolling if @roll_log
-        severity ||= UNKNOWN
-        if message.nil?
-          if block_given?
-            message = yield
-          else
-            message = progname
-          end
-        end
-        return if message == ''
         # add to the logger first
         @logger.add(severity, message)
         @logger.add(::Logger::Severity::DEBUG, backtrace) if backtrace

I’m not sure this behaves exactly as expected. I always thought about the formatter as “let me format the message in any way I like and then just print it”. What happens here is that the formatted message gets processed again before being printed so we get doubled timestamps and stuff like that. We could change the formatter, but it doesn’t feel right.

2018-10-23T10:30:04  [I] Smart proxy has launched on 1 socket(s), waiting for requests                                                                                                                                                      
2018-10-23T10:30:11  [I] [2018-10-23 08:30:11.894 #3774]     1 -- dynflow: Execution plan cleaner removing 0 execution plans.                                                                                                               
                                                                                                                                                                                                                                            
2018-10-23T10:30:11 74c5a74d [I] [2018-10-23 08:30:11.901 #3774]     1 -- Started GET /features                                                                                                                                             
                                                                                                                                                                                                                                            
2018-10-23T10:30:11 74c5a74d [I] [2018-10-23 08:30:11.904 #3774]     1 -- Finished GET /features with 200 (3.06 ms)                                                                                                                         
                                                                                                                                                                                                                                            
2018-10-23T10:30:17 50053842 [I] [2018-10-23 08:30:17.115 #3774]     1 -- Started GET /features                                                                                                                                             
                                                                                                                                                                                                                                            
2018-10-23T10:30:17 50053842 [I] [2018-10-23 08:30:17.116 #3774]     1 -- Finished GET /features with 200 (0.53 ms)                                                                                                                         
                                                                                                                                                                                                                                            
2018-10-23T10:30:26  [D] [2018-10-23 08:30:26.886 #3774]     0 -- dynflow: Executor heartbeat                                                                                                                                               
                                                                                                                                                                                                                                            
^C2018-10-23T10:30:33  [I] [2018-10-23 08:30:33.262 #3774]     1 -- dynflow: start terminating delayed_executor...                                                                                                                          
                                                                                                                                                                                                                                            
2018-10-23T10:30:33  [I] [2018-10-23 08:30:33.262 #3774]     1 -- dynflow: start terminating throttle_limiter...                                                                                                                            
                                                                                                                                                                                                                                            
2018-10-23T10:30:33  [I] [2018-10-23 08:30:33.263 #3774]     1 -- dynflow: start terminating executor...                                                                                                                                    
                                                                                                                                                                                                                                            
2018-10-23T10:30:33  [I] [2018-10-23 08:30:33.263 #3774]     1 -- dynflow: shutting down Core ...                                                                                                                                           
                                                                                                                                                                                                                                            
2018-10-23T10:30:33  [I] [2018-10-23 08:30:33.265 #3774]     1 -- dynflow: ... Dynflow core terminated.                                                                                                                                     
                                                                                                                                                                                                                                            
2018-10-23T10:30:33  [I] [2018-10-23 08:30:33.266 #3774]     1 -- dynflow: start terminating executor dispatcher...                                                                                                                         
                                                                                                                                                                                                                                            
2018-10-23T10:30:33  [I] [2018-10-23 08:30:33.267 #3774]     1 -- dynflow: start terminating client dispatcher...                                                                                                                          

2018-10-23T10:30:33  [I] [2018-10-23 08:30:33.268 #3774]     1 -- dynflow: stop listening for new events...                                                                                                                                

2018-10-23T10:30:33  [I] [2018-10-23 08:30:33.268 #3774]     1 -- dynflow: start terminating clock...

Github is up, let’s take this to https://github.com/theforeman/smart_proxy_dynflow/pull/56 I will reply there. Thanks.