easy-going-rails/lib/semantic/subscribers/action_controller.rb

module Semantic
  module Subscribers
    # LogSubscriber for event_group :action_controller
    class ActionController < LogSubscriber
      include AnsiColors

      INTERNAL_PARAMS = %i[controller action format _method only_path].freeze
      DEFAULT_DEV_HOSTS = ['127.0.0.1', 'localhost'].freeze
      TERMINUS_STRING = '╙─╜'.freeze

      def initialize(session_key)
        super(:controller)
        @session_key = session_key
        @transactions = {}
      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]
          path = colorize(request.filtered_path, BOLD)

          dimensions = Semantic::FancyDimensions.new(rails: '╓─╖', before: 1)
          if defined?(@previously_redirect) && @previously_redirect
            dimensions = Semantic::FancyDimensions.new(rails: '╓║╖', before: 0)
            @previously_redirect = false
          end
          logger.info("Started #{request.raw_request_method} #{path}", dimensions:)

          format = event.payload[:format]
          format = format.to_s.upcase if format.is_a?(Symbol)
          format = '*/*' if format.nil?
          format = colorize(format, BOLD)
          logger.debug("Processing by #{event.payload[:controller]}##{event.payload[:action]} as #{format}")

          params = event.payload[:params].deep_symbolize_keys.except(*INTERNAL_PARAMS)
          unless params.empty?
            params = params.ai(ruby19_syntax: true, plain: true, multiline: false)
            params.gsub!(/(\w+):/, "#{TEXT_CYAN}\\1#{CLEAR}:")
            params.gsub!(/"(.*?)"/, "\"#{TEXT_YELLOW}\\1#{CLEAR}\"")
          end
          logger.debug("Parameters: #{params}") unless params.empty?
        end
      end

      def process_action(event)
        session_value = @transactions.delete(event.transaction_id) # delete previous session_value from start_processing
        SemanticLogger.tagged(session_value) do
          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 << pop_active_record_summary
          additions << "GC: #{event.gc_time.round(1)}ms"
          additions.compact!

          if event.duration >= 1200
            logger.error process_duration(event, additions)
          elsif event.duration >= 600
            logger.warn process_duration(event, additions)
          elsif event.duration >= 300
            logger.info process_duration(event, additions)
          # elsif event.duration >= 100
          else
            logger.debug process_duration(event, additions)
          end

          status_family = status / 100

          dimensions = case status_family
                       when 2
                         Semantic::FancyDimensions.new(rails: TERMINUS_STRING)
                       when 3, 5
                         Semantic::FancyDimensions.new(rails: '╙║╜')
                       when 4
                         Semantic::FancyDimensions.new(rails: '╙╨╜')
                       end
          logger.info("Completed #{colorize(status, BOLD)} #{Rack::Utils::HTTP_STATUS_CODES[status]}", dimensions:)
          logger.info(' ', dimensions: Semantic::FancyDimensions.new(rails: ' ║ ')) if status_family == 3
          logger.info(' ', dimensions: Semantic::FancyDimensions.new(rails: '╓║╖')) if status_family == 5
        end
      end

      def redirect_to(event)
        location = capture_path(event.payload[:location])
        logger.debug("Redirected to #{colorize(location, BOLD)}")
        @previously_redirect = true
      end

      private

      # FIXME: might be more accurate, multiple transactions, sum of CRUD
      def pop_active_record_summary
        active_record_transactions = Thread.current[ActiveRecord.to_s]
        return unless active_record_transactions

        # reset thread local
        Thread.current[ActiveRecord.to_s] = nil

        active_record_transactions.map do |k, art|
          art.except(:total_duration)
             .select { |_, value| value.positive? }
             .map { |k, v| "#{v} #{k.to_s.pluralize(v)}" }
             .join(',')
        end.compact.join('|')
      end

      def redirect_regex
        return @redirect_regex if defined?(@redirect_regex)

        options = Rails.application.routes.default_url_options
        dev_hosts = DEFAULT_DEV_HOSTS + Array.wrap(options[:host])
        dev_hosts_or = dev_hosts.uniq.join('|')
        dev_from = "http://(?:#{dev_hosts_or}):#{options[:port]}(.*)"

        @redirect_regex = /^#{dev_from}/
      end

      def capture_path(url)
        m = redirect_regex.match(url)
        m.nil? ? url : m[1]
      end

      def session_value(event) = event.payload[:headers]['rack.session'].fetch(@session_key, nil)
      def process_duration(event, additions) = "Processed in #{event.duration.round}ms (#{additions.join(' | ')})"
    end
  end
end