Ruby trace logger

spec_trace.rb

#----------------------------------------------------------------------------------------
# Example Usage (RSpec)
#----------------------------------------------------------------------------------------
# Define a trace object. Syntax is as follows:
#
#   let (:trace) {
#     SpecTrace.new({
#       Module::ClassA => { exclude: [:method_to_ignore, :another_method_to_ignore] }
#       Module::ClassB => { include: [:method_to_trace, :another_method_to_trace] },
#     })
#   }
#
# Later in the spec:
#
#   it "equals some_value" do
#     trace.scoped do
#       expect(controller.action(args)).to eq some_value
#     end
#   end
#
# This will trace:
#  - All methods in ClassA, except method_to_ignore() and another_method_to_ignore()
#  - Only method_to_trace() and another_method_to_trace() in ClassB
#----------------------------------------------------------------------------------------
class SpecTrace
  COLORS = [:yellow, :light_red, :light_green, :light_blue].freeze

  def initialize(classes)
    Thread.current[:spec_trace] ||= 0
    Thread.current[:spec_trace] += 1

    if classes.keys.empty?
      log "Trust me, you don't want to trace log *everything*. Please specify at least one class to trace.".red
      return
    end
    @trace_id = Thread.current[:spec_trace]
    @classes = classes
    @indent = 0
    log ("-" * 80).yellow
    log "Trace #{@trace_id} initialized"
    classes.each do |klass, methods|
      log klass.to_s.cyan
      @indent += 1
      log "Include: ".green + (methods[:include] ? methods[:include].join(', ') : "*")
      log "Exclude: ".red + methods[:exclude].join(', ') if methods[:exclude]
      @indent -= 1
    end
    log ("-" * 80).yellow
  end

  def log(str = nil)
    print "SpecTrace[#{@trace_id}] ".send(COLORS[@trace_id % COLORS.length - 1])
    print "    " * @indent
    puts str
  end

  def scoped
    trace_call = TracePoint.new(:call) do |tp|
      if @classes.key?(tp.defined_class) &&
        (@classes[tp.defined_class][:include]&.include?(tp.method_id) != false) &&
        !@classes[tp.defined_class][:exclude]&.include?(tp.method_id)

        log "#{tp.defined_class} #{tp.path.sub(Rails.root.to_s, "")}:#{tp.lineno}".gray
        log "CALL ".green + tp.method_id.to_s
        tp.binding.local_variables.each do |name|
          var = tp.binding.local_variable_get(name)
          next if var.nil?
          log name.to_s.cyan + " = #{var.class} #{var}"
        end
        puts
        @indent += 1
      end
    end

    trace_return = TracePoint.new(:return) do |tp|
      if @classes.key?(tp.defined_class) &&
        (@classes[tp.defined_class][:include]&.include?(tp.method_id) != false) &&
        !@classes[tp.defined_class][:exclude]&.include?(tp.method_id)

        @indent -= 1
        log "#{tp.defined_class} #{tp.path.sub(Rails.root.to_s, "")}:#{tp.lineno}".gray
        log "RETURN ".red + "#{tp.method_id}"
        log "retval ".light_red + "#{tp.return_value.class} => #{tp.return_value}"
        tp.binding.local_variables.each do |name|
          var = tp.binding.local_variable_get(name)
          next if var.nil?
          log name.to_s.cyan + " = #{var.class} #{var}"
        end
        puts
      end
    end

    trace_call.enable
    trace_return.enable
    yield
  ensure
    trace_call.disable if trace_call.enabled?
    trace_return.disable if trace_return.enabled?
  end
end