Module: Polyrun::RSpec::ExampleDebug

Defined in:
lib/polyrun/rspec/example_debug.rb,
lib/polyrun/rspec/example_debug_instrumentation.rb

Overview

Per-example RSpec debugging for local investigation (SQL, TracePoint, timeouts).

POLYRUN_EXAMPLE_DEBUG=1 enables installers; DEBUG=1 / POLYRUN_DEBUG=1 trace orchestration only. POLYRUN_DEBUG_SQL=1 or legacy DEBUG_SQL=1 logs mutating SQL. POLYRUN_DEBUG_TRACE=1 or legacy DEBUG_TRACE=1 traces :call/:raise under the app root. DEBUG_LOG_LEVEL accepts Ruby Logger severities as integers (0 debug … 4 fatal) or names.

Constant Summary collapse

LOG_LEVEL_BY_NAME = 
{
  "debug" => Logger::DEBUG,
  "info" => Logger::INFO,
  "warn" => Logger::WARN,
  "error" => Logger::ERROR,
  "fatal" => Logger::FATAL
}.freeze
SKIPPED_SQL_PREFIX = 
/\A(?:SELECT|SET|SHOW|BEGIN|COMMIT|ROLLBACK|RELEASE|SAVEPOINT)/

Class Method Summary collapse

Class Method Details

.enabled? ⇒ Boolean

Returns:

  • (Boolean) 


24
25
26
 
# File 'lib/polyrun/rspec/example_debug.rb', line 24

def enabled?
  truthy?(ENV["POLYRUN_EXAMPLE_DEBUG"])
end

.example_timeout_disabled? ⇒ Boolean

Returns:

  • (Boolean) 


44
45
46
 
# File 'lib/polyrun/rspec/example_debug.rb', line 44

def example_timeout_disabled?
  enabled?
end

.install!(rspec_config: fetch_rspec_configuration!) ) ⇒ Object 



71
72
73
74
75
 
# File 'lib/polyrun/rspec/example_debug.rb', line 71

def install!(rspec_config: fetch_rspec_configuration!)
  install_spec_path_helpers!(rspec_config)
  install_sql_debug!(rspec_config) if sql_enabled?
  install_trace_debug!(rspec_config) if trace_enabled?
end

.install_example_timeout!(rspec_config, seconds: ENV.fetch("RSPEC_EXAMPLE_TIMEOUT_SEC", "30").to_f) ⇒ Object 



95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
 
# File 'lib/polyrun/rspec/example_debug.rb', line 95

def install_example_timeout!(
  rspec_config,
  seconds: ENV.fetch("RSPEC_EXAMPLE_TIMEOUT_SEC", "30").to_f
)
  return if seconds <= 0
  return if example_timeout_disabled?

  rspec_config.around(:each) do |example|
    if example.metadata[:benchmark] || example.metadata[:slow]
      example.run
    else
      Timeout.timeout(seconds) { example.run }
    end
  rescue Timeout::Error
    raise "Example timed out after #{seconds}s (#{example.location})"
  end
end

.install_prosopite!(rspec_config: fetch_rspec_configuration!) ) ⇒ Object 



113
114
115
116
117
118
119
120
121
122
 
# File 'lib/polyrun/rspec/example_debug.rb', line 113

def install_prosopite!(rspec_config: fetch_rspec_configuration!)
  return unless prosopite_enabled?
  return unless defined?(Prosopite) && defined?(Rails)

  log_path = Rails.root.join("tmp", "prosopite_#{Time.current.strftime("%Y%m%d_%H%M%S")}.log")
  Prosopite.custom_logger = Logger.new(log_path)

  rspec_config.before { Prosopite.scan }
  rspec_config.after { Prosopite.finish }
end

.install_rails_logging!(rspec_config: fetch_rspec_configuration!) ) ⇒ Object 



77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
 
# File 'lib/polyrun/rspec/example_debug.rb', line 77

def install_rails_logging!(rspec_config: fetch_rspec_configuration!)
  return unless enabled?
  return unless defined?(Rails)

  rspec_config.before do |example|
    group = example.metadata[:example_group]
    Polyrun::Log.puts "\n\nRunning #{group[:file_path]}:#{group[:line_number]}"

    level = log_level
    Rails.logger.level = level
    if defined?(ActiveRecord::Base)
      ar_logger = Logger.new(Polyrun::Log.stdout)
      ar_logger.level = level
      ActiveRecord::Base.logger = ar_logger
    end
  end
end

.install_spec_path_helpers!(rspec_config) ⇒ Object 



124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
 
# File 'lib/polyrun/rspec/example_debug.rb', line 124

def install_spec_path_helpers!(rspec_config)
  rspec_config.before do |example|
    group = example.metadata[:example_group]
    spec_file_path = group[:file_path]

    define_singleton_method(:spec_dirname) { File.dirname(spec_file_path) }
    define_singleton_method(:spec_basename) { File.basename(spec_file_path) }

    if ExampleDebug.print_spec_enabled?
      Polyrun::Log.puts "\nRunning #{spec_file_path}:#{group[:line_number]}\n"
    end
  end

  rspec_config.after do |example|
    next unless ExampleDebug.print_spec_enabled?

    group = example.metadata[:example_group]
    Polyrun::Log.puts "\nFinished #{group[:file_path]}:#{group[:line_number]}\n"
  end
end

.install_sql_debug!(rspec_config, io: Polyrun::Log.stdout) ⇒ Object 



8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
 
# File 'lib/polyrun/rspec/example_debug_instrumentation.rb', line 8

def install_sql_debug!(rspec_config, io: Polyrun::Log.stdout)
  return unless defined?(ActiveSupport::Notifications)

  rspec_config.around do |example|
    subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |event|
      payload = event.payload[:sql]
      next unless loggable_sql?(payload)

      line = sql_with_interpolated_binds(payload, event.payload[:type_casted_binds])
      io.puts "+ #{line}"
    end

    example.run
  ensure
    ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber
  end
end

.install_trace_debug!(rspec_config, root: trace_root, io: Polyrun::Log.stdout) ⇒ Object 



26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
 
# File 'lib/polyrun/rspec/example_debug_instrumentation.rb', line 26

def install_trace_debug!(rspec_config, root: trace_root, io: Polyrun::Log.stdout)
  require "pp"
  root_path = File.expand_path(root.to_s)
  trace = TracePoint.new do |trace_point|
    if trace_point.event == :call && trace_point.path.to_s.start_with?(root_path)
      io.puts PP.pp({event: :call, path: "#{trace_point.path}:#{trace_point.lineno}"}, +"")
    elsif trace_point.event == :raise
      io.puts PP.pp(
        {
          event: :raise,
          raised_exception: trace_point.raised_exception,
          path: "#{trace_point.path}:#{trace_point.lineno}",
          method_id: trace_point.method_id
        },
        +""
      )
    end
  end

  rspec_config.around do |example|
    trace.enable
    example.run
  ensure
    trace.disable
  end
end

.log_level ⇒ Object 



48
49
50
 
# File 'lib/polyrun/rspec/example_debug.rb', line 48

def log_level
  parse_log_level(ENV.fetch("DEBUG_LOG_LEVEL", "debug"))
end

.loggable_sql?(sql) ⇒ Boolean

Returns:

  • (Boolean) 


53
54
55
 
# File 'lib/polyrun/rspec/example_debug_instrumentation.rb', line 53

def loggable_sql?(sql)
  !sql.to_s.match?(SKIPPED_SQL_PREFIX)
end

.print_spec_enabled? ⇒ Boolean

Returns:

  • (Boolean) 


40
41
42
 
# File 'lib/polyrun/rspec/example_debug.rb', line 40

def print_spec_enabled?
  enabled? && truthy?(ENV["DEBUG_PRINT_SPEC"])
end

.prosopite_enabled? ⇒ Boolean

Returns:

  • (Boolean) 


36
37
38
 
# File 'lib/polyrun/rspec/example_debug.rb', line 36

def prosopite_enabled?
  enabled? && truthy?(ENV["DEBUG_PROSOPITE"])
end

.rails_log_level ⇒ Object 



52
53
54
55
56
57
58
59
60
 
# File 'lib/polyrun/rspec/example_debug.rb', line 52

def rails_log_level
  case log_level
  when Logger::DEBUG then :debug
  when Logger::INFO then :info
  when Logger::WARN then :warn
  when Logger::ERROR then :error
  else :fatal
  end
end

.sql_enabled? ⇒ Boolean

Returns:

  • (Boolean) 


28
29
30
 
# File 'lib/polyrun/rspec/example_debug.rb', line 28

def sql_enabled?
  enabled? && (truthy?(ENV["POLYRUN_DEBUG_SQL"]) || truthy?(ENV["DEBUG_SQL"]))
end

.sql_with_interpolated_binds(sql, binds) ⇒ Object 



57
58
59
60
61
62
63
 
# File 'lib/polyrun/rspec/example_debug_instrumentation.rb', line 57

def sql_with_interpolated_binds(sql, binds)
  output = sql.to_s.dup
  Array(binds).each_with_index do |bind, index|
    output = output.gsub("$#{index + 1}", "'#{bind}'")
  end
  output
end

.trace_enabled? ⇒ Boolean

Returns:

  • (Boolean) 


32
33
34
 
# File 'lib/polyrun/rspec/example_debug.rb', line 32

def trace_enabled?
  enabled? && (truthy?(ENV["POLYRUN_DEBUG_TRACE"]) || truthy?(ENV["DEBUG_TRACE"]))
end