Add specs for new QueryRecorder features

spec/support/helpers/query_recorder.rb

@@ -12,7 +12,7 @@ module ActiveRecord
       @cached = []
       @skip_cached = skip_cached
       @query_recorder_debug = ENV['QUERY_RECORDER_DEBUG'] || query_recorder_debug
-      @log_file = File.open(log_file, 'w') if log_file && @query_recorder_debug
+      @log_file = log_file
       # force replacement of bind parameters to give tests the ability to check for ids
       ActiveRecord::Base.connection.unprepared_statement do
         ActiveSupport::Notifications.subscribed(method(:callback), 'sql.active_record', &block)
@@ -72,11 +72,11 @@ module ActiveRecord
 
     def callback(name, start, finish, message_id, values)
       duration = finish - start
-      backtrace = @query_recorder_debug ? show_backtrace(values, duration) : nil
 
       if values[:cached] && skip_cached
         @cached << values[:sql]
       elsif !values[:name]&.include?("SCHEMA")
+        backtrace = @query_recorder_debug ? show_backtrace(values, duration) : nil
         @log << values[:sql]
         store_sql_by_source(values: values, duration: duration, backtrace: backtrace)
       end

spec/support_specs/helpers/active_record/query_recorder_spec.rb

@@ -11,6 +11,66 @@ RSpec.describe ActiveRecord::QueryRecorder do
     end
   end
 
+  describe 'printing to the log' do
+    let(:backtrace) { %r{QueryRecorder backtrace:  --> (\w+/)*\w+\.rb:\d+:in `.*'} }
+    let(:duration_line) { %r{QueryRecorder DURATION:  --> \d+\.\d+} }
+
+    def match_section(query, lines)
+      query_lines = lines.take(query.size)
+      expect(query_lines).to match(query)
+      expect(lines[query.size]).to match(duration_line)
+      backtrace_lines = lines.drop(query.size + 1).take_while { |line| line.match(backtrace) }
+      expect(backtrace_lines).not_to be_empty
+
+      # Advance to the next section
+      lines.drop(query.size + 1 + backtrace_lines.size)
+    end
+
+    it 'prints SQL, duration and backtrace, all prefixed with QueryRecorder' do
+      io = StringIO.new
+
+      control = ActiveRecord::QueryRecorder.new(log_file: io, query_recorder_debug: true) do
+        TestQueries.count
+        TestQueries.first
+        TestQueries.where(<<~FRAGMENT).to_a # tests multi-line SQL
+          version = 'foo'
+           OR
+          version = 'bar'
+        FRAGMENT
+      end
+
+      query_a = start_with(%q[QueryRecorder SQL:  --> SELECT COUNT(*) FROM "schema_migrations"])
+
+      query_b = start_with(%q[QueryRecorder SQL:  --> SELECT "schema_migrations".* FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC LIMIT 1])
+
+      query_c_a = eq(%q[QueryRecorder SQL:  --> SELECT "schema_migrations".* FROM "schema_migrations" WHERE (version = 'foo'])
+      query_c_b = eq(%q(QueryRecorder SQL:  -->  OR))
+      query_c_c = eq(%q(QueryRecorder SQL:  --> version = 'bar'))
+      query_c_d = start_with("QueryRecorder SQL:  --> )")
+
+      expect(control.count).to eq(3)
+
+      lines = io.string.lines.map(&:chomp)
+
+      expect(lines).to all(start_with('QueryRecorder'))
+      lines = match_section([query_a], lines)
+      lines = match_section([query_b], lines)
+      lines = match_section([query_c_a, query_c_b, query_c_c, query_c_d], lines)
+
+      expect(lines).to be_empty
+    end
+  end
+
+  it 'includes duration information' do
+    control = ActiveRecord::QueryRecorder.new do
+      TestQueries.count
+      TestQueries.first
+    end
+
+    expect(control.count).to eq(2)
+    expect(control.data.values.flat_map { _1[:durations] }).to match([be > 0, be > 0])
+  end
+
   describe 'detecting the right number of calls and their origin' do
     it 'detects two separate queries' do
       control = ActiveRecord::QueryRecorder.new query_recorder_debug: true do
@@ -23,10 +83,10 @@ RSpec.describe ActiveRecord::QueryRecorder do
         .to eq(control.data.keys.size)
       # Ensure exactly 2 COUNT queries were detected
       expect(control.occurrences_by_line_method.last[1][:occurrences]
-               .find_all {|i| i.match(/SELECT COUNT/) }.count).to eq(2)
+               .count { |str| str.start_with?('SELECT COUNT') }).to eq(2)
       # Ensure exactly 1 LIMIT 1 (#first)
       expect(control.occurrences_by_line_method.first[1][:occurrences]
-               .find_all { |i| i.match(/ORDER BY.*#{TestQueries.table_name}.*LIMIT 1/) }.count).to eq(1)
+               .count { |str| str.match(/ORDER BY.*#{TestQueries.table_name}.*LIMIT 1/) }).to eq(1)
 
       # Ensure 3 DB calls overall were executed
       expect(control.log.size).to eq(3)