Amazing debugging for grape-ruby, rspec test examples, show SQL traces, show stack calls and all exceptions in stack, helper to find out which spec file stuck, store logs to files

debug_helper.rb

require "amazing_print"
class Debug
  attr_reader :messages, :before_gc_stats, :after_gc_stats, :time_report, :mem_report

  def initialize(with_sql: false, with_stack: false, store_file: false, console_print: false, output_path: nil, context: nil, file_prefix: nil, messages: [])
    @with_sql = with_sql
    @with_stack = with_stack
    @console_print = console_print
    @context = context
    @messages = messages

    @store_file = store_file
    @output_path = output_path
    @file_prefix = file_prefix
    @output_file = if @store_file
      root_dir = Rails.root.join("tmp/traces")
      FileUtils.mkdir_p(root_dir)
      @output_path ||= root_dir.join("#{Time.now.strftime("%Y%m%d%H%M")}_#{@file_prefix}_trace.txt")
      File.open(@output_path, "a")
    end
  end

  def store_message(**kwargs)
    @messages << kwargs if @messages
    @output_file&.puts(kwargs)
    ap(kwargs) if @console_print
  end

  def analyze_sql_traces
    @messages.each_with_index do |message, index|
      if message[:event] == "sql.active_record"
        query = "EXPLAIN (FORMAT JSON) #{message[:sql]}"
        result = ActiveRecord::Base.connection.execute(query)
        @messages[index][:sql_explain] = JSON.parse(result.first.fetch("QUERY PLAN"))
      end
    end
  end

  def report(analyze_sql: false)
    puts "Total allocated objects: #{mem_report.total_allocated}"
    puts "Total allocated memory: #{mem_report.total_allocated_memsize / 1024.0} KB"
    puts "Total retained objects: #{mem_report.total_retained}"
    puts "Total retained memory: #{mem_report.total_retained_memsize / 1024.0} KB"
    puts "Request timing: #{(time_report * 1000).round(2)} ms"
    puts "Objects created: #{after_gc_stats[:total_allocated_objects] - before_gc_stats[:total_allocated_objects]}"

    analyze_sql_traces if analyze_sql

    puts messages
  end

  def trace(&block)
    @output_file&.puts("\n\n---\n")
    store_message(context: @context)

    if @with_sql
      subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |event|
        payload = event.payload[:sql]
        # next if payload.match?(/^(SET|SHOW|BEGIN|COMMIT|ROLLBACK|RELEASE|SAVEPOINT)/)
        # next if payload.include?("audits")
        next if payload.include?("pg_attribute")

        type_casted_binds = if event.payload[:type_casted_binds].is_a?(Array)
          event.payload[:type_casted_binds]
        elsif event.payload[:type_casted_binds].is_a?(Proc)
          event.payload[:type_casted_binds].call
        else
          []
        end

        if type_casted_binds.is_a?(Array)
          type_casted_binds.each_with_index.reverse_each do |bind, index|
            payload = payload.gsub("$#{index + 1}", "'#{bind}'")
          end
        end

        store_message(event: "sql.active_record", sql: payload)
      end
    end

    if @with_stack
      trace_point = TracePoint.new do |tp|
        if tp.event == :call && tp.path.start_with?(Rails.root.to_s)
          store_message(
            event: tp.event,
            path: "#{tp.path}:#{tp.lineno}"
          )
        elsif tp.event == :raise
          store_message(
            event: tp.event,
            raised_exception: tp.raised_exception,
            path: "#{tp.path}:#{tp.lineno}",
            method_id: tp.method_id
          )
        end
      end
      trace_point.enable
    end

    GC.start
    GC.disable
    @before_gc_stats = GC.stat

    @mem_report = MemoryProfiler.report do
      @time_report = Benchmark.realtime do
        block.call
      end
    end

    @after_gc_stats = GC.stat
    GC.enable
  ensure
    trace_point.disable if @with_stack
    ActiveSupport::Notifications.unsubscribe(subscriber) if @with_sql
  end
end

debug_support.rb

require "amazing_print"
class Debug
  def self.print_message(message, output_file: nil)
    if output_file
      output_file.puts(message)
    else
      ap(message)
    end
  end

  def self.trace(with_sql: false, with_stack: false, store_file: false, output_path: nil, context: nil, file_prefix: nil)
    file = if store_file
      root_dir = Rails.root.join("tmp/traces")
      FileUtils.mkdir_p(root_dir)
      output_path ||= root_dir.join("#{Time.now.strftime("%Y%m%d%H%M")}_#{file_prefix}_trace.txt")
      File.open(output_path, "a")
    end
    file.puts("\n\n---\nBEGIN CONTEXT: #{context}\n\n") if file

    if with_sql
      subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |event|
        payload = event.payload[:sql]
        # next if payload.match?(/^(SET|SHOW|BEGIN|COMMIT|ROLLBACK|RELEASE|SAVEPOINT)/)
        # next if payload.include?("audits")
        next if payload.include?("pg_attribute")

        if event.payload[:type_casted_binds].is_a?(Array)
          event.payload[:type_casted_binds].each_with_index do |bind, index|
            payload = payload.gsub("$#{index + 1}", "'#{bind}'")
          end
        end

        print_message({sql: payload}, output_file: file)
      end
    end

    if with_stack
      trace = TracePoint.new do |tp|
        if tp.event == :call && tp.path.start_with?(Rails.root.to_s)
          print_message({
            event: tp.event,
            path: "#{tp.path}:#{tp.lineno}"
          }, output_file: file)
        elsif tp.event == :raise
          print_message({
            event: tp.event,
            raised_exception: tp.raised_exception,
            path: "#{tp.path}:#{tp.lineno}",
            method_id: tp.method_id
          }, output_file: file)
        end
      end
      trace.enable
    end

    yield
  ensure
    trace.disable if with_stack
    ActiveSupport::Notifications.unsubscribe(subscriber) if with_sql
  end
end

example_request_spec.rb

  it "returns status code 200" do
    collector = Debug.new(with_sql: true, with_stack: false)
    collector.trace do
      perform_request
    end
    collector.report(analyze_sql: false) if ENV["PROFILE"]
    puts collector.messages
    expect(collector.messages.length).to eq(55)
    expect(response).to have_http_status(:success)
  end

grape_debug.rb

module GrapeDebug
  class GrapeTracer < ::Grape::Middleware::Base
    TRACE_ENABLED = ENV["TRACE"]

    def call!(env)
      if TRACE_ENABLED
        file_prefix = [env["REQUEST_METHOD"], env["PATH_INFO"]].join("_").downcase.gsub(/[^a-z0-9_]+/, "_")
        context = [env["REQUEST_METHOD"], env["PATH_INFO"]].join(" ")
        Debug.trace(with_sql: true, with_stack: false, store_file: true, file_prefix: file_prefix, context: context) do
          @app.call(env)
        end
      else
        @app.call(env)
      end
    end
  end
end