Support transaction (part 1) (#1108)

* Support Transaction recording

* Add AR support to the test app

* Support tracing in sentry-rails

* Change APIs

* Use new transaction API in sentry-rails

* Update sentry_trace related APIs

.github/workflows/sentry_rails_test.yml

@@ -30,7 +30,12 @@ jobs:
 
     steps:
     - uses: actions/checkout@v1
-
+    - name: Install sqlite
+      run: |
+        # See https://github.community/t5/GitHub-Actions/ubuntu-latest-Apt-repository-list-issues/td-p/41122/page/2
+        for apt_file in `grep -lr microsoft /etc/apt/sources.list.d/`; do sudo rm $apt_file; done
+        sudo apt-get update
+        sudo apt-get install libsqlite3-dev
     - name: Set up Ruby ${{ matrix.ruby_version }}
       uses: ruby/setup-ruby@v1
       with:

sentry-rails/Gemfile

@@ -6,6 +6,10 @@ gemspec
 rails_version = ENV["RAILS_VERSION"]
 rails_version = "6.0" if rails_version.nil?
 
+gem 'activerecord-jdbcmysql-adapter', platform: :jruby
+gem "jdbc-sqlite3", platform: :jruby
+gem "sqlite3", platform: :ruby
+
 gem "rails", "~> #{rails_version}"
 gem "rspec-rails", "~> 4.0"
 gem "codecov"

sentry-rails/examples/rails-6.0/config/application.rb

@@ -23,6 +23,7 @@ class Application < Rails::Application
     Sentry.init do |config|
       config.breadcrumbs_logger = [:sentry_logger]
       config.send_default_pii = true
+      config.traces_sample_rate = 1.0
       config.dsn = 'https://2fb45f003d054a7ea47feb45898f7649@o447951.ingest.sentry.io/5434472'
     end
   end

sentry-rails/lib/sentry/rails.rb

@@ -1,6 +1,7 @@
 require "sentry-ruby"
 require "sentry/rails/configuration"
 require "sentry/rails/railtie"
+require "sentry/rails/tracing"
 
 module Sentry
   module Rails

sentry-rails/lib/sentry/rails/railtie.rb

@@ -10,6 +10,7 @@ module Sentry
   class Railtie < ::Rails::Railtie
     initializer "sentry.use_rack_middleware" do |app|
       app.config.middleware.insert 0, Sentry::Rails::CaptureException
+      app.config.middleware.insert 0, Sentry::Rack::Tracing
     end
 
     initializer 'sentry.action_controller' do
@@ -50,6 +51,10 @@ class Railtie < ::Rails::Railtie
 
         exceptions_class.send(:prepend, Sentry::Rails::Overrides::DebugExceptionsCatcher)
       end
+
+      if Sentry.configuration.traces_sample_rate.to_f > 0.0
+        Sentry::Rails::Tracing.subscribe_tracing_events
+      end
     end
 
     initializer 'sentry.active_job' do

sentry-rails/lib/sentry/rails/tracing.rb

@@ -0,0 +1,17 @@
+require "sentry/rails/tracing/abstract_subscriber"
+require "sentry/rails/tracing/active_record_subscriber"
+
+module Sentry
+  module Rails
+    module Tracing
+      def self.subscribe_tracing_events
+        # need to avoid duplicated subscription
+        return if @subscribed
+
+        Tracing::ActiveRecordSubscriber.subscribe!
+
+        @subscribed = true
+      end
+    end
+  end
+end

sentry-rails/lib/sentry/rails/tracing/abstract_subscriber.rb

@@ -0,0 +1,35 @@
+module Sentry
+  module Rails
+    module Tracing
+      class AbstractSubscriber
+
+        class << self
+          def subscribe!
+            raise NotImplementedError
+          end
+
+          def subscribe_to_event(event_name)
+            if ::Rails.version.to_i == 5
+              ActiveSupport::Notifications.subscribe(event_name) do |_, start, finish, _, payload|
+                next unless get_current_transaction
+
+                duration = finish.to_f - start.to_f
+                yield(event_name, duration, payload)
+              end
+            else
+              ActiveSupport::Notifications.subscribe(event_name) do |event|
+                next unless get_current_transaction
+
+                yield(event_name, event.duration, event.payload)
+              end
+            end
+          end
+
+          def get_current_transaction
+            Sentry.get_current_scope.get_transaction
+          end
+        end
+      end
+    end
+  end
+end

sentry-rails/lib/sentry/rails/tracing/active_record_subscriber.rb

@@ -0,0 +1,23 @@
+module Sentry
+  module Rails
+    module Tracing
+      class ActiveRecordSubscriber < AbstractSubscriber
+        EVENT_NAME = "sql.active_record".freeze
+        EXCLUDED_EVENTS = ["SCHEMA", "TRANSACTION"].freeze
+
+        def self.subscribe!
+          subscribe_to_event(EVENT_NAME) do |event_name, duration, payload|
+            if !EXCLUDED_EVENTS.include? payload[:name]
+              timestamp = Time.now.utc.to_f
+              start_timestamp = timestamp - duration.to_f
+
+              new_span = get_current_transaction.start_child(op: event_name, description: payload[:sql], start_timestamp: start_timestamp, timestamp: timestamp)
+              new_span.set_data(:name, payload[:name])
+              new_span.set_data(:connection_id, payload[:connection_id])
+            end
+          end
+        end
+      end
+    end
+  end
+end

sentry-rails/spec/sentry/rails/tracing_spec.rb

@@ -0,0 +1,64 @@
+require "spec_helper"
+
+RSpec.describe Sentry::Rails::Tracing, type: :request do
+  let(:transport) do
+    Sentry.get_current_client.transport
+  end
+
+  let(:event) do
+    transport.events.last.to_json_compatible
+  end
+
+  after do
+    transport.events = []
+  end
+
+  context "with traces_sample_rate set" do
+    before do
+      expect(described_class).to receive(:subscribe_tracing_events).and_call_original
+
+      make_basic_app do |config|
+        config.traces_sample_rate = 1.0
+      end
+    end
+
+    it "records transaction" do
+      get "/posts"
+
+      expect(transport.events.count).to eq(2)
+
+      event = transport.events.first.to_hash
+      transaction = transport.events.last.to_hash
+
+      expect(event.dig(:contexts, :trace, :trace_id).length).to eq(32)
+      expect(event.dig(:contexts, :trace, :trace_id)).to eq(transaction.dig(:contexts, :trace, :trace_id))
+
+      expect(transaction[:type]).to eq("transaction")
+      expect(transaction[:spans].count).to eq(2)
+
+      first_span = transaction[:spans][0]
+      expect(first_span[:op]).to eq("rack.request")
+      expect(first_span[:status]).to eq("internal_error")
+      expect(first_span[:data]).to eq({ "status_code" => 500 })
+
+      second_span = transaction[:spans][1]
+      expect(second_span[:op]).to eq("sql.active_record")
+      expect(second_span[:description]).to eq("SELECT \"posts\".* FROM \"posts\"")
+      expect(second_span[:parent_span_id]).to eq(first_span[:span_id])
+    end
+  end
+
+  context "without traces_sample_rate set" do
+    before do
+      expect(described_class).not_to receive(:subscribe_tracing_events)
+
+      make_basic_app
+    end
+
+    it "doesn't record any transaction" do
+      get "/posts"
+
+      expect(transport.events.count).to eq(1)
+    end
+  end
+end

sentry-rails/spec/sentry/rails_spec.rb

@@ -1,7 +1,7 @@
 require "spec_helper"
 
 RSpec.describe Sentry::Rails, type: :request do
-  before(:all) do
+  before do
     make_basic_app
   end
 
@@ -21,8 +21,9 @@
     expect(described_class::VERSION).to be_a(String)
   end
 
-  it "inserts middleware" do
-    expect(Rails.application.middleware).to include(Sentry::Rails::CaptureException)
+  it "inserts middleware to a correct position" do
+    expect(Rails.application.middleware.find_index(Sentry::Rack::Tracing)).to eq(0)
+    expect(Rails.application.middleware.find_index(Sentry::Rails::CaptureException)).to eq(1)
   end
 
   it "doesn't do anything on a normal route" do

sentry-rails/spec/support/test_rails_app/app.rb

@@ -1,5 +1,5 @@
 require 'rails'
-# require "active_record/railtie"
+require "active_record"
 require "action_view/railtie"
 require "action_controller/railtie"
 # require "action_mailer/railtie"
@@ -11,9 +11,36 @@
 
 ActiveSupport::Deprecation.silenced = true
 
+ActiveRecord::Base.establish_connection(adapter: "sqlite3", database: ":memory:")
+ActiveRecord::Base.logger = Logger.new(nil)
+
+ActiveRecord::Schema.define do
+  create_table :posts, force: true do |t|
+  end
+
+  create_table :comments, force: true do |t|
+    t.integer :post_id
+  end
+end
+
+class Post < ActiveRecord::Base
+  has_many :comments
+end
+
+class Comment < ActiveRecord::Base
+  belongs_to :post
+end
+
 class TestApp < Rails::Application
 end
 
+class PostsController < ActionController::Base
+  def index
+    Post.all.to_a
+    raise "foo"
+  end
+end
+
 class HelloController < ActionController::Base
   def exception
     raise "An unhandled exception!"
@@ -48,6 +75,7 @@ def self.name
     get "/exception", :to => "hello#exception"
     get "/view_exception", :to => "hello#view_exception"
     get "/not_found", :to => "hello#not_found"
+    resources :posts, only: [:index]
     root :to => "hello#world"
   end
 

sentry-ruby/examples/rails-6.0/config/application.rb

@@ -21,6 +21,7 @@ class Application < Rails::Application
     config.exceptions_app = self.routes
 
     config.middleware.insert_after ActionDispatch::DebugExceptions, Sentry::Rack::CaptureException
+    config.middleware.insert 0, Sentry::Rack::Tracing
 
     Sentry.init do |config|
       config.breadcrumbs_logger = [:sentry_logger]

sentry-ruby/lib/sentry-ruby.rb

@@ -3,6 +3,9 @@
 require "sentry/configuration"
 require "sentry/logger"
 require "sentry/event"
+require "sentry/transaction_event"
+require "sentry/span"
+require "sentry/transaction"
 require "sentry/hub"
 require "sentry/rack"
 
@@ -92,6 +95,10 @@ def capture_message(message, **options, &block)
       get_current_hub.capture_message(message, **options, &block)
     end
 
+    def start_transaction(**options)
+      get_current_hub.start_transaction(**options)
+    end
+
     def last_event_id
       get_current_hub.last_event_id
     end

sentry-ruby/lib/sentry/client.rb

@@ -51,6 +51,18 @@ def event_from_message(message)
       Event.new(configuration: configuration, message: message)
     end
 
+    def event_from_transaction(transaction)
+      TransactionEvent.new(configuration: configuration).tap do |event|
+        event.transaction = transaction.name
+        event.contexts.merge!(trace: transaction.get_trace_context)
+        event.timestamp = transaction.timestamp
+        event.start_timestamp = transaction.start_timestamp
+
+        finished_spans = transaction.span_recorder.spans.select { |span| span.timestamp }.map(&:to_hash)
+        event.spans = finished_spans
+      end
+    end
+
     def send_event(event)
       return false unless configuration.sending_allowed?(event)
 

sentry-ruby/lib/sentry/configuration.rb

@@ -95,6 +95,8 @@ class Configuration
 
     attr_reader :transport
 
+    attr_accessor :traces_sample_rate
+
     # Optional Proc, called before sending an event to the server/
     # E.g.: lambda { |event| event }
     # E.g.: lambda { |event| nil }

sentry-ruby/lib/sentry/event.rb

@@ -13,20 +13,18 @@ class Event
       release environment server_name modules
       message user tags contexts extra
       fingerprint breadcrumbs backtrace transaction
-      platform sdk
+      platform sdk type
     )
 
     attr_accessor(*ATTRIBUTES)
-    attr_reader :id, :configuration
-
-    alias event_id id
+    attr_reader :configuration
 
     def initialize(configuration:, message: nil)
       # this needs to go first because some setters rely on configuration
       @configuration = configuration
 
       # Set some simple default values
-      @id            = SecureRandom.uuid.delete("-")
+      @event_id      = SecureRandom.uuid.delete("-")
       @timestamp     = Time.now.utc.iso8601
       @platform      = :ruby
       @sdk           = Sentry.sdk_meta
@@ -51,8 +49,8 @@ def initialize(configuration:, message: nil)
     class << self
       def get_log_message(event_hash)
         message = event_hash[:message] || event_hash['message']
-        message = get_message_from_exception(event_hash) if message.empty?
-        message = '<no message value>' if message.empty?
+        message = get_message_from_exception(event_hash) if message.nil? || message.empty?
+        message = '<no message value>' if message.nil? || message.empty?
         message
       end
 
@@ -87,11 +85,12 @@ def rack_env=(env)
       end
     end
 
-    def to_hash
-      data = ATTRIBUTES.each_with_object({}) do |att, memo|
-        memo[att] = public_send(att) if public_send(att)
-      end
+    def type
+      "event"
+    end
 
+    def to_hash
+      data = serialize_attributes
       data[:breadcrumbs] = breadcrumbs.to_hash if breadcrumbs
       data[:stacktrace] = @stacktrace.to_hash if @stacktrace
       data[:request] = @request.to_hash if @request
@@ -152,6 +151,14 @@ def stacktrace_interface_from(backtrace)
 
     private
 
+    def serialize_attributes
+      self.class::ATTRIBUTES.each_with_object({}) do |att, memo|
+        if value = public_send(att)
+          memo[att] = value
+        end
+      end
+    end
+
     # When behind a proxy (or if the user is using a proxy), we can't use
     # REMOTE_ADDR to determine the Event IP, and must use other headers instead.
     def calculate_real_ip_from_rack(env)