Fix multiple logging issue to stdout

lib/debug_logging/argument_printer.rb

@@ -6,8 +6,8 @@ def debug_benchmark_to_s(tms: nil)
       "completed in #{format('%f', tms.real)}s (#{format('%f', tms.total)}s CPU)"
     end
 
-    def debug_event_name_to_s(method_to_notify: nil)
-      "#{method_to_notify}.log"
+    def debug_event_name_to_s(method_to_notify: nil, separator: nil, invocation_id: nil)
+      "#{method_to_notify}.log#{separator}#{invocation_id}"
     end
 
     def debug_invocation_id_to_s(args: nil, config_proxy: nil)

lib/debug_logging/class_notifier.rb

@@ -13,7 +13,6 @@ def notifies(*methods_to_notify)
         # method name must be a symbol
         method_to_notify = method_to_notify.to_sym
         original_method = method(method_to_notify)
-        config_proxy = nil
         (class << self; self; end).class_eval do
           define_method(method_to_notify) do |*args, &block|
             config_proxy = if (proxy = instance_variable_get(DebugLogging::Configuration.config_pointer('k', method_to_notify)))
@@ -28,19 +27,18 @@ def notifies(*methods_to_notify)
                              instance_variable_set(DebugLogging::Configuration.config_pointer('k', method_to_notify), proxy)
                              proxy
                            end
-            ActiveSupport::Notifications.instrument(
-              debug_event_name_to_s(method_to_notify: method_to_notify), { debug_args: args }.merge(payload)
-            ) do
+            invocation_id = debug_invocation_id_to_s(args: args, config_proxy: config_proxy)
+            debug_event_name = debug_event_name_to_s(method_to_notify: method_to_notify, separator: '#', invocation_id: invocation_id)
+            ActiveSupport::Notifications.subscribe(debug_event_name) do |*debug_args|
+              config_proxy&.log do
+                DebugLogging::LogSubscriber.log_event(ActiveSupport::Notifications::Event.new(*debug_args))
+              end
+            end
+            ActiveSupport::Notifications.instrument(debug_event_name, { debug_args: args }.merge(payload)) do
               original_method.call(*args, &block)
             end
           end
         end
-
-        ActiveSupport::Notifications.subscribe(/log/) do |*args|
-          config_proxy&.log do
-            DebugLogging::LogSubscriber.log_event(ActiveSupport::Notifications::Event.new(*args))
-          end
-        end
       end
     end
   end

lib/debug_logging/instance_notifier_modulizer.rb

@@ -12,7 +12,6 @@ def self.to_mod(methods_to_notify: nil)
           else
             method_to_notify.to_sym
           end
-          config_proxy = nil
           define_method(method_to_notify) do |*args, &block|
             config_proxy = if (proxy = instance_variable_get(DebugLogging::Configuration.config_pointer('i', method_to_notify)))
                              proxy
@@ -26,25 +25,24 @@ def self.to_mod(methods_to_notify: nil)
                              instance_variable_set(DebugLogging::Configuration.config_pointer('i', method_to_notify), proxy)
                              proxy
                            end
+            invocation_id = self.class.debug_invocation_id_to_s(args: args, config_proxy: config_proxy)
+            debug_event_name = self.class.debug_event_name_to_s(method_to_notify: method_to_notify, separator: '#', invocation_id: invocation_id)
+            ActiveSupport::Notifications.subscribe(debug_event_name) do |*debug_args|
+              config_proxy&.log do
+                DebugLogging::LogSubscriber.log_event(ActiveSupport::Notifications::Event.new(*debug_args))
+              end
+            end
             paydirt = { debug_args: args }
             if payload.key?(:instance_variables)
               payload[:instance_variables].each do |k|
                 paydirt[k] = instance_variable_get("@#{k}") if instance_variable_get("@#{k}")
               end
             end
             paydirt.merge!(payload.reject { |k| k == :instance_variables })
-            ActiveSupport::Notifications.instrument(
-              self.class.debug_event_name_to_s(method_to_notify: method_to_notify), paydirt
-            ) do
+            ActiveSupport::Notifications.instrument(debug_event_name, paydirt) do
               super(*args, &block)
             end
           end
-
-          ActiveSupport::Notifications.subscribe(/log/) do |*args|
-            config_proxy&.log do
-              DebugLogging::LogSubscriber.log_event(ActiveSupport::Notifications::Event.new(*args))
-            end
-          end
         end
       end
     end

spec/debug_logging/class_notifier_spec.rb

@@ -23,7 +23,7 @@
       expect(output).to match(/payload={:debug_args=>\[{:a=>"a"}\]}/)
       expect(complete_notified_klass.instance_variable_get(DebugLogging::Configuration.config_pointer('k', :k_with_dsplat))).to receive(:log)
       expect(@events).to contain_exactly(
-        have_attributes(name: 'k_with_dsplat.log', payload: { debug_args: [{ a: 'a' }] })
+        have_attributes(name: /k_with_dsplat.log/, payload: { debug_args: [{ a: 'a' }] })
       )
       complete_notified_klass.k_with_dsplat(a: 'a')
     end
@@ -37,7 +37,7 @@
       expect(output).to match(/payload={:debug_args=>\[{:a=>"a"}\], :id=>1, :first_name=>"Joe", :last_name=>"Schmoe"}\n/)
       expect(complete_notified_klass.instance_variable_get(DebugLogging::Configuration.config_pointer('k', :k_with_dsplat_payload))).to receive(:log).once.and_call_original
       expect(@events).to contain_exactly(
-        have_attributes(name: 'k_with_dsplat_payload.log', payload: { debug_args: [{ a: 'a' }], id: 1, first_name: 'Joe', last_name: 'Schmoe' })
+        have_attributes(name: /k_with_dsplat_payload.log/, payload: { debug_args: [{ a: 'a' }], id: 1, first_name: 'Joe', last_name: 'Schmoe' })
       )
       complete_notified_klass.k_with_dsplat_payload(a: 'a')
     end
@@ -71,12 +71,12 @@
       expect(output).to match(/k_with_dsplat.log/)
       expect(output).to match(/payload={:debug_args=>\[\]}/)
       expect(@events).to contain_exactly(
-        have_attributes(name: 'i.log', payload: { debug_args: [] }),
-        have_attributes(name: 'i_with_ssplat.log', payload: { debug_args: [], id: 1, first_name: 'Joe', last_name: 'Schmoe' }),
-        have_attributes(name: 'i_with_dsplat.log', payload: { debug_args: [], salutation: 'Mr.', suffix: 'Jr.' }),
-        have_attributes(name: 'k.log', payload: { debug_args: [] }),
-        have_attributes(name: 'k_with_ssplat.log', payload: { debug_args: [] }),
-        have_attributes(name: 'k_with_dsplat.log', payload: { debug_args: [] })
+        have_attributes(name: /i.log/, payload: { debug_args: [] }),
+        have_attributes(name: /i_with_ssplat.log/, payload: { debug_args: [], id: 1, first_name: 'Joe', last_name: 'Schmoe' }),
+        have_attributes(name: /i_with_dsplat.log/, payload: { debug_args: [], salutation: 'Mr.', suffix: 'Jr.' }),
+        have_attributes(name: /k.log/, payload: { debug_args: [] }),
+        have_attributes(name: /k_with_ssplat.log/, payload: { debug_args: [] }),
+        have_attributes(name: /k_with_dsplat.log/, payload: { debug_args: [] })
       )
     end
 

spec/debug_logging/instance_notifier_spec.rb

@@ -33,11 +33,11 @@
       expect(output).to match(/i_with_instance_vars.log/)
       expect(output).to match(/payload={:debug_args=>\[\], :action=>"Create", :id=>2, :msg=>{:greeting=>"bye"}}/)
       expect(@events).to contain_exactly(
-        have_attributes(name: 'i.log', payload: { debug_args: [] }),
-        have_attributes(name: 'i_with_ssplat.log', payload: { debug_args: [], id: 1, first_name: 'Joe', last_name: 'Schmoe' }),
-        have_attributes(name: 'i_with_dsplat.log', payload: { debug_args: [], salutation: 'Mr.', suffix: 'Jr.' }),
-        have_attributes(name: 'i_with_instance_vars.log', payload: { debug_args: [], action: 'Update', id: 1, msg: { greeting: 'hi' } }),
-        have_attributes(name: 'i_with_instance_vars.log', payload: { debug_args: [], action: 'Create', id: 2, msg: { greeting: 'bye' } })
+        have_attributes(name: /i.log/, payload: { debug_args: [] }),
+        have_attributes(name: /i_with_ssplat.log/, payload: { debug_args: [], id: 1, first_name: 'Joe', last_name: 'Schmoe' }),
+        have_attributes(name: /i_with_dsplat.log/, payload: { debug_args: [], salutation: 'Mr.', suffix: 'Jr.' }),
+        have_attributes(name: /i_with_instance_vars.log/, payload: { debug_args: [], action: 'Update', id: 1, msg: { greeting: 'hi' } }),
+        have_attributes(name: /i_with_instance_vars.log/, payload: { debug_args: [], action: 'Create', id: 2, msg: { greeting: 'bye' } })
       )
     end
 
@@ -58,7 +58,7 @@
         expect(output).to match(/i.log/)
         expect(output).to match(/payload={:debug_args=>\[\]}/)
         expect(@events).to contain_exactly(
-          have_attributes(name: 'i.log', payload: { debug_args: [] })
+          have_attributes(name: /i.log/, payload: { debug_args: [] })
         )
       end
 
@@ -75,7 +75,7 @@
         expect(output).to match(/i_with_ssplat.log/)
         expect(output).to match(/payload={:debug_args=>\["a", 1, true, \["b", 2, false\], {:c=>:d, :e=>:f}\]}/)
         expect(@events).to contain_exactly(
-          have_attributes(name: 'i_with_ssplat.log', payload: { debug_args: ['a', 1, true, ['b', 2, false], { c: :d, e: :f }] })
+          have_attributes(name: /i_with_ssplat.log/, payload: { debug_args: ['a', 1, true, ['b', 2, false], { c: :d, e: :f }] })
         )
       end
 
@@ -92,7 +92,7 @@
         expect(output).to match(/i_with_dsplat.log/)
         expect(output).to match(/payload={:debug_args=>\[{:a=>"a", :b=>1, :c=>true, :d=>\["b", 2, false\], :e=>{:c=>:d, :e=>:f}}\]}/)
         expect(@events).to contain_exactly(
-          have_attributes(name: 'i_with_dsplat.log', payload: { debug_args: [{ a: 'a', b: 1, c: true, d: ['b', 2, false], e: { c: :d, e: :f } }] })
+          have_attributes(name: /i_with_dsplat.log/, payload: { debug_args: [{ a: 'a', b: 1, c: true, d: ['b', 2, false], e: { c: :d, e: :f } }] })
         )
       end
 
@@ -129,7 +129,7 @@
         expect(output).to match(/k.log/)
         expect(output).to match(/payload={:debug_args=>\[\]}/)
         expect(@events).to contain_exactly(
-          have_attributes(name: 'k.log', payload: { debug_args: [] })
+          have_attributes(name: /k.log/, payload: { debug_args: [] })
         )
       end
 
@@ -147,7 +147,7 @@
         expect(output).to match(/k_with_ssplat.log/)
         expect(output).to match(/payload={:debug_args=>\["a", 1, true, \["b", 2, false\], {:c=>:d, :e=>:f}\]}/)
         expect(@events).to contain_exactly(
-          have_attributes(name: 'k_with_ssplat.log', payload: { debug_args: ['a', 1, true, ['b', 2, false], { c: :d, e: :f }] })
+          have_attributes(name: /k_with_ssplat.log/, payload: { debug_args: ['a', 1, true, ['b', 2, false], { c: :d, e: :f }] })
         )
       end
 
@@ -164,7 +164,7 @@
         expect(output).to match(/k_with_dsplat.log/)
         expect(output).to match(/payload={:debug_args=>\[{:a=>"a", :b=>1, :c=>true, :d=>\["b", 2, false\], :e=>{:c=>:d, :e=>:f}}\]}/)
         expect(@events).to contain_exactly(
-          have_attributes(name: 'k_with_dsplat.log', payload: { debug_args: [{ a: 'a', b: 1, c: true, d: ['b', 2, false], e: { c: :d, e: :f } }] })
+          have_attributes(name: /k_with_dsplat.log/, payload: { debug_args: [{ a: 'a', b: 1, c: true, d: ['b', 2, false], e: { c: :d, e: :f } }] })
         )
       end
 

spec/debug_logging/log_subscriber_spec.rb

@@ -20,7 +20,7 @@
         complete_notified_klass.k_with_dsplat(a: 'a')
 
         expect(@log_subscriber.event).to be_a_kind_of(ActiveSupport::Notifications::Event)
-        expect(@log_subscriber.event.name).to eq('k_with_dsplat.log')
+        expect(@log_subscriber.event.name).to match(/k_with_dsplat.log/)
         expect(@log_subscriber.event.payload).to eq({ debug_args: [{ a: 'a' }] })
       end
     end
@@ -31,7 +31,7 @@
         complete_notified_klass.k_with_dsplat_payload(a: 'a')
 
         expect(@log_subscriber.event).to be_a_kind_of(ActiveSupport::Notifications::Event)
-        expect(@log_subscriber.event.name).to eq('k_with_dsplat_payload.log')
+        expect(@log_subscriber.event.name).to match(/k_with_dsplat_payload.log/)
         expect(@log_subscriber.event.payload).to eq({ debug_args: [{ a: 'a' }], id: 1, first_name: 'Joe', last_name: 'Schmoe' })
       end
     end
@@ -44,7 +44,7 @@
         end.to raise_error(StandardError)
 
         expect(@log_subscriber.event).to be_a_kind_of(ActiveSupport::Notifications::Event)
-        expect(@log_subscriber.event.name).to eq('k_with_ssplat_error.log')
+        expect(@log_subscriber.event.name).to match(/k_with_ssplat_error.log/)
         expect(@log_subscriber.event.payload).to include({ debug_args: [{ a: 'a' }], exception: ['StandardError', 'bad method!'] })
       end
     end