finish_processing

app/controllers/application_controller.rb

@@ -1,5 +1,8 @@
 class ApplicationController < ActionController::Base
+  around_action :tag_log
+
   private
 
   def flash_stream = turbo_stream.replace(:notification, partial: 'layouts/notification')
+  def tag_log(&) = SemanticLogger.tagged(session[:toto1], &)
 end

app/controllers/hot_controller.rb

@@ -1,6 +1,6 @@
 class HotController < ApplicationController
   def index
-    session[:toto1] = 'TOTO1'
+    session[:toto1] = session[:toto1].nil? ? 'blabla' : nil
     logger.info('callee')
     logger.info(__callee__)
     logger.info(__method__)

config/environments/development.rb

@@ -88,7 +88,10 @@ Rails.application.configure do # rubocop:disable Metrics/BlockLength
     end
   elsif Rails.application.server?
     config.after_initialize do
-      Semantic::LogSubscriber.new # force loading
+      # force module preloading
+      Semantic::AnsiColors.class
+      Semantic::AnsiDimensions.class
+
       Semantic::DevLoader.new
     end
   end

lib/semantic/ansi_formatter.rb

@@ -28,6 +28,7 @@ module Semantic
     end
 
     def call(log, logger)
+      # puts 'ok'
       log = alter(log)
 
       self.log = log

lib/semantic/dev_loader.rb

@@ -23,8 +23,12 @@ module Semantic
     def append_subscriber_once
       return unless @previous_subscribe.nil?
 
+      subscriber = Semantic::LogSubscriber.new('toto1')
       @previous_subscribe = ActiveSupport::Notifications.subscribe 'start_processing.action_controller' do |event|
-        Semantic::LogSubscriber.new.start_processing(event)
+        subscriber.start_processing(event)
+      end
+      ActiveSupport::Notifications.subscribe 'process_action.action_controller' do |event|
+        subscriber.finish_processing(event)
       end
     end
   end

lib/semantic/log_subscriber.rb

@@ -3,24 +3,49 @@ module Semantic
     include SemanticLogger::Loggable
     # def logger = SemanticLogger['Rails']
 
-    SESSION_KEY = 'toto1'.freeze
+    EMPTY = 'none'.freeze
 
-    def initialize
+    def initialize(session_key)
+      @session_key = session_key
+      @transactions = {}
+      super()
     end
 
     def start_processing(event)
+      session_value = session_value(event)
+      @transactions[event.transaction_id] = session_value # preserve session_value to help finish_processing
+
+      SemanticLogger.tagged(session_value) do
         request = event.payload[:request]
-      rack_session = event.payload[:headers]['rack.session']
-      session_value = rack_session.fetch(SESSION_KEY, 'EMPTY')
+        logger.info("Started #{request.raw_request_method} #{request.filtered_path}")
 
         format = event.payload[:format]
         format = format.to_s.upcase if format.is_a?(Symbol)
         format = '*/*' if format.nil?
+        logger.debug("Processing by #{event.payload[:controller]}##{event.payload[:action]} as #{format}")
+      end
+    end
 
+    def finish_processing(event)
+      session_value = @transactions.delete(event.transaction_id) # get previous session_value from start_processing
       SemanticLogger.tagged(session_value) do
-        logger.info("Started #{request.raw_request_method} #{request.filtered_path}")
-        logger.debug("Processing by #{event.payload[:controller]}##{event.payload[:action]} as #{format}")
+        payload = event.payload
+        additions = ActionController::Base.log_process_action(payload)
+        status = payload[:status]
+
+        if status.nil? && (exception_class_name = payload[:exception]&.first)
+          status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
         end
+
+        additions << "GC: #{event.gc_time.round(1)}ms"
+
+        logger.info("Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms " \
+                    "(#{additions.join(' | ')})")
       end
     end
+
+    private
+
+    def session_value(event) = event.payload[:headers]['rack.session'].fetch(@session_key, EMPTY)
+  end
 end