[rails] add e2e specs for rails structured logging

Author: solnic

sentry-ruby/lib/sentry/debug_structured_logger.rb

@@ -51,8 +51,6 @@ def capture_log_event(level, message, parameters, **attributes)
     end
 
     def logged_events
-      return [] unless File.exist?(log_file)
-
       File.readlines(log_file).map do |line|
         JSON.parse(line)
       end

spec/apps/rails-mini/Gemfile

@@ -4,7 +4,12 @@ source 'https://rubygems.org'
 
 gem "rake"
 gem "puma"
+
 gem 'railties'
 gem 'actionpack'
+gem 'activerecord'
+gem 'activejob'
+gem 'sqlite3'
+
 gem 'sentry-ruby', path: Pathname(__dir__).join("../../..").realpath
 gem 'sentry-rails', path: Pathname(__dir__).join("../../..").realpath

spec/apps/rails-mini/app.rb

@@ -5,8 +5,11 @@
 Bundler.require
 
 ENV["RAILS_ENV"] = "development"
+ENV["DATABASE_URL"] = "sqlite3:tmp/rails_mini_development.sqlite3"
 
-require "action_controller"
+require "action_controller/railtie"
+require "active_record/railtie"
+require "active_job/railtie"
 
 class RailsMiniApp < Rails::Application
   config.hosts = nil
@@ -39,10 +42,71 @@ def debug_log_path
       config.transport.transport_class = Sentry::DebugTransport
       config.sdk_debug_transport_log_file = debug_log_path.join("sentry_debug_events.log")
       config.background_worker_threads = 0
+
+      config.enable_logs = true
+      config.structured_logger_class = Sentry::DebugStructuredLogger
+      config.sdk_debug_structured_logger_log_file = debug_log_path.join("sentry_e2e_tests.log")
+
+      config.rails.structured_logging.enabled = true
+      config.rails.structured_logging.attach_to = [:active_record, :action_controller, :active_job]
     end
   end
 end
 
+class Post < ActiveRecord::Base
+end
+
+class User < ActiveRecord::Base
+end
+
+class ApplicationJob < ActiveJob::Base
+  retry_on ActiveRecord::Deadlocked
+
+  discard_on ActiveJob::DeserializationError
+end
+
+class SampleJob < ApplicationJob
+  queue_as :default
+
+  def perform(message = "Hello from ActiveJob!")
+    Rails.logger.info("SampleJob executed with message: #{message}")
+
+    Post.count
+    User.count
+
+    message
+  end
+end
+
+class DatabaseJob < ApplicationJob
+  queue_as :default
+
+  def perform(post_title = "Test Post")
+    Rails.logger.info("DatabaseJob creating post: #{post_title}")
+
+    post = Post.create!(title: post_title, content: "Content for #{post_title}")
+    found_post = Post.find(post.id)
+
+    Rails.logger.info("DatabaseJob found post: #{found_post.title}")
+
+    found_post
+  end
+end
+
+class FailingJob < ApplicationJob
+  queue_as :default
+
+  def perform(should_fail = true)
+    Rails.logger.info("FailingJob started")
+
+    if should_fail
+      raise StandardError, "Intentional job failure for testing"
+    end
+
+    "Job completed successfully"
+  end
+end
+
 class ErrorController < ActionController::Base
   before_action :set_cors_headers
 
@@ -97,12 +161,134 @@ def set_cors_headers
   end
 end
 
+class PostsController < ActionController::Base
+  before_action :set_cors_headers
+  def index
+    posts = Post.all.to_a
+
+    Sentry.logger.info("Posts index accessed", posts_count: posts.length)
+
+    render json: {
+      posts: posts.map { |p| { id: p.id, title: p.title, content: p.content } }
+    }
+  end
+
+  def create
+    post = Post.create!(post_params)
+
+    Sentry.logger.info("Post created", post_id: post.id, title: post.title)
+
+    render json: { post: { id: post.id, title: post.title, content: post.content } }, status: :created
+  rescue ActiveRecord::RecordInvalid => e
+    render json: { error: e.message }, status: :unprocessable_entity
+  end
+
+  def show
+    post = Post.find(params[:id])
+    render json: { post: { id: post.id, title: post.title, content: post.content } }
+  rescue ActiveRecord::RecordNotFound
+    render json: { error: "Post not found" }, status: :not_found
+  end
+
+  private
+
+  def post_params
+    params.require(:post).permit(:title, :content)
+  end
+
+  def set_cors_headers
+    response.headers['Access-Control-Allow-Origin'] = '*'
+    response.headers['Access-Control-Allow-Methods'] = 'GET, POST, PUT, DELETE, OPTIONS'
+    response.headers['Access-Control-Allow-Headers'] = 'Content-Type, Authorization, sentry-trace, baggage'
+  end
+end
+
+class JobsController < ActionController::Base
+  before_action :set_cors_headers
+
+  def sample_job
+    job = SampleJob.perform_later("Hello from Rails mini app!")
+
+    Sentry.logger.info("SampleJob enqueued", job_id: job.job_id)
+
+    render json: {
+      message: "SampleJob enqueued successfully",
+      job_id: job.job_id,
+      job_class: job.class.name
+    }
+  end
+
+  def database_job
+    title = params[:title] || "Test Post from Job"
+    job = DatabaseJob.perform_later(title)
+
+    Sentry.logger.info("DatabaseJob enqueued", job_id: job.job_id, post_title: title)
+
+    render json: {
+      message: "DatabaseJob enqueued successfully",
+      job_id: job.job_id,
+      job_class: job.class.name,
+      post_title: title
+    }
+  end
+
+  def failing_job
+    should_fail = params[:should_fail] != "false"
+    job = FailingJob.perform_later(should_fail)
+
+    Sentry.logger.info("FailingJob enqueued", job_id: job.job_id, should_fail: should_fail)
+
+    render json: {
+      message: "FailingJob enqueued successfully",
+      job_id: job.job_id,
+      job_class: job.class.name,
+      should_fail: should_fail
+    }
+  end
+
+  private
+
+  def set_cors_headers
+    response.headers['Access-Control-Allow-Origin'] = '*'
+    response.headers['Access-Control-Allow-Methods'] = 'GET, POST, PUT, DELETE, OPTIONS'
+    response.headers['Access-Control-Allow-Headers'] = 'Content-Type, Authorization, sentry-trace, baggage'
+  end
+end
+
 RailsMiniApp.initialize!
 
+ActiveRecord::Schema.define do
+  create_table :posts, force: true do |t|
+    t.string :title, null: false
+    t.text :content
+    t.timestamps
+  end
+
+  create_table :users, force: true do |t|
+    t.string :name, null: false
+    t.string :email
+    t.timestamps
+  end
+end
+
+Post.create!(title: "Welcome Post", content: "Welcome to the Rails mini app!")
+Post.create!(title: "Sample Post", content: "This is a sample post for testing.")
+User.create!(name: "Test User", email: "test@example.com")
+
 RailsMiniApp.routes.draw do
   get '/health', to: 'events#health'
   get '/error', to: 'error#error'
   get '/trace_headers', to: 'events#trace_headers'
+  get '/logged_events', to: 'events#logged_events'
+  post '/clear_logged_events', to: 'events#clear_logged_events'
+
+  get '/posts', to: 'posts#index'
+  post '/posts', to: 'posts#create'
+  get '/posts/:id', to: 'posts#show'
+
+  post '/jobs/sample', to: 'jobs#sample_job'
+  post '/jobs/database', to: 'jobs#database_job'
+  post '/jobs/failing', to: 'jobs#failing_job'
 
   match '*path', to: proc { |env|
     [200, {

spec/features/structured_logging_spec.rb

@@ -0,0 +1,49 @@
+# frozen_string_literal: true
+
+RSpec.describe "Structured Logging", type: :e2e do
+  it "captures Rails application logs using structured logging" do
+    response = make_request("/posts")
+    expect(response.code).to eq("200")
+
+    logged_events = Sentry.logger.logged_events
+    expect(logged_events).not_to be_empty
+
+    log_event = logged_events.first
+    expect(log_event).to have_key("timestamp")
+    expect(log_event).to have_key("level")
+    expect(log_event).to have_key("message")
+    expect(log_event).to have_key("attributes")
+    expect(log_event["timestamp"]).to be_a(String)
+  end
+
+  it "captures logs from Rails mini app" do
+    response = make_request("/posts")
+    expect(response.code).to eq("200")
+
+    logged_events = Sentry.logger.logged_events
+    expect(logged_events).not_to be_empty
+
+    posts_log = logged_events.find { |log| log["message"] == "Posts index accessed" }
+    expect(posts_log).not_to be_nil
+    expect(posts_log["level"]).to eq("info")
+    expect(posts_log["attributes"]["posts_count"]).to eq(2)
+  end
+
+  it "captures structured logs with proper format" do
+    response = make_request("/posts")
+    expect(response.code).to eq("200")
+
+    logged_events = Sentry.logger.logged_events
+    expect(logged_events).not_to be_empty
+
+    log_event = logged_events.first
+    expect(log_event).to have_key("timestamp")
+    expect(log_event).to have_key("level")
+    expect(log_event).to have_key("message")
+    expect(log_event).to have_key("attributes")
+    expect(log_event["timestamp"]).to be_a(String)
+    expect(log_event["level"]).to be_a(String)
+    expect(log_event["message"]).to be_a(String)
+    expect(log_event["attributes"]).to be_a(Hash)
+  end
+end

spec/spec_helper.rb

@@ -7,6 +7,7 @@
 
 require "capybara"
 require "capybara/rspec"
+require "debug"
 
 require_relative "support/test_helper"
 
@@ -31,12 +32,14 @@
 
 RSpec.configure do |config|
   config.include(Capybara::DSL, type: :e2e)
-
   config.include(Test::Helper)
 
   config.before(:suite) do
     Test::Helper.perform_basic_setup do |config|
       config.transport.transport_class = Sentry::DebugTransport
+      config.structured_logger_class = Sentry::DebugStructuredLogger
+      config.sdk_debug_structured_logger_log_file = Test::Helper.debug_log_path.join("sentry_e2e_tests.log")
+      config.enable_logs = true
     end
 
     Test::Helper.clear_logged_events
@@ -45,4 +48,8 @@
   config.after(:each) do
     Test::Helper.clear_logged_events
   end
+
+  config.after(:each) do
+    Test::Helper.clear_logs
+  end
 end

spec/support/test_helper.rb

@@ -1,9 +1,20 @@
 # frozen_string_literal: true
 
+require 'net/http'
+require 'uri'
+
 module Test
   module Helper
     module_function
 
+    def rails_app_url
+      ENV.fetch("SENTRY_E2E_RAILS_APP_URL")
+    end
+
+    def make_request(path)
+      Net::HTTP.get_response(URI("#{rails_app_url}#{path}"))
+    end
+
     def logged_events
       @logged_events ||= begin
         extracted_events = []
@@ -40,11 +51,7 @@ def logged_envelopes
     end
 
     def logged_structured_events
-      if Sentry.logger.is_a?(Sentry::DebugStructuredLogger)
-        Sentry.logger.logged_events
-      else
-        []
-      end
+      Sentry.logger.logged_events
     end
 
     # TODO: move this to a shared helper for all gems
@@ -58,5 +65,18 @@ def perform_basic_setup
         yield(config) if block_given?
       end
     end
+
+    def debug_log_path
+      @log_path ||= begin
+        path = Pathname(__dir__).join("../../log")
+        FileUtils.mkdir_p(path) unless path.exist?
+        path.realpath
+      end
+    end
+
+    def clear_logs
+      Sentry.get_current_client.transport.clear
+      Sentry.logger.clear
+    end
   end
 end