diff --git a/sentry-ruby/lib/sentry-ruby.rb b/sentry-ruby/lib/sentry-ruby.rb index fea912c0a..7abbac571 100644 --- a/sentry-ruby/lib/sentry-ruby.rb +++ b/sentry-ruby/lib/sentry-ruby.rb @@ -11,11 +11,12 @@ require "sentry/utils/encoding_helper" require "sentry/utils/logging_helper" require "sentry/configuration" -require "sentry/logger" +require "sentry/logging" require "sentry/event" require "sentry/error_event" require "sentry/transaction_event" require "sentry/check_in_event" +require "sentry/log_event" require "sentry/span" require "sentry/transaction" require "sentry/hub" @@ -251,6 +252,9 @@ def init(&block) @backpressure_monitor = config.enable_backpressure_handling ? Sentry::BackpressureMonitor.new(config, client) : nil @metrics_aggregator = config.metrics.enabled ? Sentry::Metrics::Aggregator.new(config, client) : nil exception_locals_tp.enable if config.include_local_variables + + Sentry::Logging.setup_logger(config) + at_exit { close } end @@ -489,6 +493,19 @@ def capture_check_in(slug, status, **options) get_current_hub.capture_check_in(slug, status, **options) end + def capture_log(message, level: :info, **attributes) + return unless initialized? + + event = LogEvent.new( + level: level, + body: message, + timestamp: Time.now.to_f, + attributes: attributes + ) + + capture_event(event) + end + # Takes or initializes a new Sentry::Transaction and makes a sampling decision for it. # # @return [Transaction, nil] diff --git a/sentry-ruby/lib/sentry/configuration.rb b/sentry-ruby/lib/sentry/configuration.rb index 9ff9bde6d..5f7f74e09 100644 --- a/sentry-ruby/lib/sentry/configuration.rb +++ b/sentry-ruby/lib/sentry/configuration.rb @@ -311,6 +311,10 @@ def capture_exception_frame_locals=(value) # @!visibility private attr_reader :errors, :gem_specs + # Experimental features configuration + # @return [Hash] + attr_accessor :_experiments + # These exceptions could enter Puma's `lowlevel_error_handler` callback and the SDK's Puma integration # But they are mostly considered as noise and should be ignored by default # Please see https://github.com/getsentry/sentry-ruby/pull/2026 for more information @@ -452,6 +456,7 @@ def initialize @transport = Transport::Configuration.new @cron = Cron::Configuration.new @metrics = Metrics::Configuration.new + @_experiments = {} @gem_specs = Hash[Gem::Specification.map { |spec| [spec.name, spec.version.to_s] }] if Gem::Specification.respond_to?(:map) run_post_initialization_callbacks diff --git a/sentry-ruby/lib/sentry/envelope/item.rb b/sentry-ruby/lib/sentry/envelope/item.rb index e1539bf6c..864ad0239 100644 --- a/sentry-ruby/lib/sentry/envelope/item.rb +++ b/sentry-ruby/lib/sentry/envelope/item.rb @@ -15,7 +15,7 @@ class Envelope::Item # rate limits and client reports use the data_category rather than envelope item type def self.data_category(type) case type - when "session", "attachment", "transaction", "profile", "span" then type + when "session", "attachment", "transaction", "profile", "span", "log" then type when "sessions" then "session" when "check_in" then "monitor" when "statsd", "metric_meta" then "metric_bucket" diff --git a/sentry-ruby/lib/sentry/log_event.rb b/sentry-ruby/lib/sentry/log_event.rb new file mode 100644 index 000000000..505648410 --- /dev/null +++ b/sentry-ruby/lib/sentry/log_event.rb @@ -0,0 +1,59 @@ +# frozen_string_literal: true + +module Sentry + class LogEvent < Event + TYPE = "log" + + LEVELS = %i[trace debug info warn error fatal].freeze + + attr_accessor :level, :body, :attributes, :trace_id + + def initialize(configuration: Sentry.configuration, **options) + super(configuration: configuration) + @type = TYPE + @level = options.fetch(:level) + @body = options[:body] + @trace_id = options[:trace_id] || SecureRandom.hex(16) + @attributes = options[:attributes] || {} + end + + # https://develop.sentry.dev/sdk/telemetry/logs/#log-envelope-item-payload + def to_hash + data = {} + data[:level] = @level.to_s + data[:body] = @body + data[:timestamp] = Time.parse(@timestamp).to_f + data[:trace_id] = @trace_id + data[:attributes] = serialize_attributes + data + end + + private + + def serialize_attributes + result = {} + + @attributes.each do |key, value| + result[key.to_s] = { + value: value.to_s, + type: value_type(value) + } + end + + result + end + + def value_type(value) + case value + when Integer + "integer" + when TrueClass, FalseClass + "boolean" + when Float + "double" + else + "string" + end + end + end +end diff --git a/sentry-ruby/lib/sentry/logging.rb b/sentry-ruby/lib/sentry/logging.rb new file mode 100644 index 000000000..8936f2033 --- /dev/null +++ b/sentry-ruby/lib/sentry/logging.rb @@ -0,0 +1,17 @@ +# frozen_string_literal: true + +require_relative "logger" +require_relative "logging/device" +require_relative "logging/handler" + +module Sentry + module Logging + def self.setup_logger(config) + if config._experiments[:enable_logs] + config.logger = Device.new(handlers: [config.logger, Handler.new(config)]) + end + + config.logger + end + end +end diff --git a/sentry-ruby/lib/sentry/logging/device.rb b/sentry-ruby/lib/sentry/logging/device.rb new file mode 100644 index 000000000..51f6ef445 --- /dev/null +++ b/sentry-ruby/lib/sentry/logging/device.rb @@ -0,0 +1,46 @@ +module Sentry + module Logging + class Device + attr_reader :handlers + + def initialize(options) + @handlers = options.fetch(:handlers) + end + + def trace(message, payload = {}) + log(:trace, message, payload) + end + + def debug(message, payload = {}) + log(:debug, message, payload) + end + + def info(message, payload = {}) + log(:info, message, payload) + end + + def warn(message, payload = {}) + log(:warn, message, payload) + end + + def error(message, payload = {}) + log(:error, message, payload) + end + + def fatal(message, payload = {}) + log(:fatal, message, payload) + end + + def log(level, message, payload) + handlers.each do |handler| + case handler + when Sentry::Logger + handler.public_send(level, message) + else + handler.public_send(level, message, payload) + end + end + end + end + end +end diff --git a/sentry-ruby/lib/sentry/logging/handler.rb b/sentry-ruby/lib/sentry/logging/handler.rb new file mode 100644 index 000000000..4b41d089f --- /dev/null +++ b/sentry-ruby/lib/sentry/logging/handler.rb @@ -0,0 +1,49 @@ +module Sentry + module Logging + class Handler + # https://develop.sentry.dev/sdk/telemetry/logs/#log-severity-number + LEVELS = { + "trace" => 1, + "debug" => 5, + "info" => 9, + "warn" => 13, + "error" => 17, + "fatal" => 21 + }.freeze + + attr_reader :config + + def initialize(config) + @config = config + end + + def trace(message, payload = {}) + log(:trace, message, payload) + end + + def debug(message, payload = {}) + log(:debug, message, payload) + end + + def info(message, payload = {}) + log(:info, message, payload) + end + + def warn(message, payload = {}) + log(:warn, message, payload) + end + + def error(message, payload = {}) + log(:error, message, payload) + end + + def fatal(message, payload = {}) + log(:fatal, message, payload) + end + + def log(level, message, payload) + Sentry.capture_log(message, level: level, severity: LEVELS[level], **payload) + end + end + end +end diff --git a/sentry-ruby/lib/sentry/scope.rb b/sentry-ruby/lib/sentry/scope.rb index 4feb6ecdd..68dfc079c 100644 --- a/sentry-ruby/lib/sentry/scope.rb +++ b/sentry-ruby/lib/sentry/scope.rb @@ -54,7 +54,7 @@ def apply_to_event(event, hint = nil) event.transaction = transaction_name if transaction_name event.transaction_info = { source: transaction_source } if transaction_source event.fingerprint = fingerprint - event.level = level + event.level = level unless event.is_a?(LogEvent) event.breadcrumbs = breadcrumbs event.rack_env = rack_env if rack_env event.attachments = attachments diff --git a/sentry-ruby/lib/sentry/transport.rb b/sentry-ruby/lib/sentry/transport.rb index d446387f2..40c313a12 100644 --- a/sentry-ruby/lib/sentry/transport.rb +++ b/sentry-ruby/lib/sentry/transport.rb @@ -133,10 +133,21 @@ def envelope_from_event(event) envelope = Envelope.new(envelope_headers) - envelope.add_item( - { type: item_type, content_type: "application/json" }, - event_payload - ) + if event.is_a?(LogEvent) + envelope.add_item( + { + type: "log", + item_count: 1, + content_type: "application/vnd.sentry.items.log+json" + }, + { items: [event_payload] } + ) + else + envelope.add_item( + { type: item_type, content_type: "application/json" }, + event_payload + ) + end if event.is_a?(TransactionEvent) && event.profile envelope.add_item( diff --git a/sentry-ruby/spec/sentry/client_spec.rb b/sentry-ruby/spec/sentry/client_spec.rb index e069ccc5b..51e493023 100644 --- a/sentry-ruby/spec/sentry/client_spec.rb +++ b/sentry-ruby/spec/sentry/client_spec.rb @@ -103,6 +103,7 @@ def sentry_context envelope.add_item({ type: 'event' }, { payload: 'test' }) envelope.add_item({ type: 'statsd' }, { payload: 'test2' }) envelope.add_item({ type: 'transaction' }, { payload: 'test3' }) + envelope.add_item({ type: 'log' }, { level: 'info', message: 'test4' }) envelope end @@ -119,6 +120,15 @@ def sentry_context subject.send_envelope(envelope) end + it 'includes log item in the envelope' do + log_item = envelope.items.find { |item| item.type == 'log' } + + expect(log_item).not_to be_nil + expect(log_item.payload[:level]).to eq('info') + expect(log_item.payload[:message]).to eq('test4') + expect(log_item.data_category).to eq('log') + end + it 'sends envelope with spotlight transport if enabled' do configuration.spotlight = true @@ -153,6 +163,7 @@ def sentry_context expect(subject.transport).to have_recorded_lost_event(:network_error, 'error') expect(subject.transport).to have_recorded_lost_event(:network_error, 'metric_bucket') expect(subject.transport).to have_recorded_lost_event(:network_error, 'transaction') + expect(subject.transport).to have_recorded_lost_event(:network_error, 'log') end end end diff --git a/sentry-ruby/spec/sentry/envelope/item_spec.rb b/sentry-ruby/spec/sentry/envelope/item_spec.rb index ea9cf1019..f21fb11b7 100644 --- a/sentry-ruby/spec/sentry/envelope/item_spec.rb +++ b/sentry-ruby/spec/sentry/envelope/item_spec.rb @@ -11,6 +11,7 @@ ['transaction', 'transaction'], ['span', 'span'], ['profile', 'profile'], + ['log', 'log'], ['check_in', 'monitor'], ['statsd', 'metric_bucket'], ['metric_meta', 'metric_bucket'], diff --git a/sentry-ruby/spec/sentry/log_event_spec.rb b/sentry-ruby/spec/sentry/log_event_spec.rb new file mode 100644 index 000000000..fe19a9c22 --- /dev/null +++ b/sentry-ruby/spec/sentry/log_event_spec.rb @@ -0,0 +1,105 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe Sentry::LogEvent do + let(:configuration) do + Sentry::Configuration.new.tap do |config| + config.dsn = Sentry::TestHelper::DUMMY_DSN + end + end + + describe "#initialize" do + it "initializes with required attributes" do + event = described_class.new( + configuration: configuration, + level: :info, + body: "User John has logged in!" + ) + + expect(event).to be_a(described_class) + expect(event.level).to eq(:info) + expect(event.body).to eq("User John has logged in!") + expect(event.trace_id).to_not be(nil) + end + + it "accepts trace_id" do + trace_id = "5b8efff798038103d269b633813fc60c" + event = described_class.new( + configuration: configuration, + level: :info, + body: "User John has logged in!", + trace_id: trace_id + ) + + expect(event.trace_id).to eq(trace_id) + end + + it "accepts attributes" do + attributes = { + "sentry.message.template" => "User %s has logged in!", + "sentry.message.parameters.0" => "John" + } + + event = described_class.new( + configuration: configuration, + level: :info, + body: "User John has logged in!", + attributes: attributes + ) + + expect(event.attributes).to eq(attributes) + end + end + + describe "#to_hash" do + it "includes all required fields" do + trace_id = "5b8efff798038103d269b633813fc60c" + attributes = { + "sentry.message.template" => "User %s has logged in!", + "sentry.message.parameters.0" => "John" + } + + event = described_class.new( + configuration: configuration, + level: :info, + body: "User John has logged in!", + trace_id: trace_id, + attributes: attributes + ) + + hash = event.to_hash + + expect(hash[:level]).to eq("info") + expect(hash[:body]).to eq("User John has logged in!") + expect(hash[:trace_id]).to eq(trace_id) + expect(hash[:timestamp]).to be_a(Float) + expect(hash[:attributes]).to be_a(Hash) + expect(hash[:attributes]["sentry.message.template"]).to eq({ value: "User %s has logged in!", type: "string" }) + expect(hash[:attributes]["sentry.message.parameters.0"]).to eq({ value: "John", type: "string" }) + end + + it "serializes different attribute types correctly" do + attributes = { + "string_attr" => "string value", + "integer_attr" => 42, + "boolean_attr" => true, + "float_attr" => 3.14 + } + + event = described_class.new( + configuration: configuration, + level: :info, + body: "Test message", + attributes: attributes + ) + + hash = event.to_hash + + expect(hash[:attributes]["string_attr"]).to eq({ value: "string value", type: "string" }) + expect(hash[:attributes]["integer_attr"]).to eq({ value: "42", type: "integer" }) + expect(hash[:attributes]["boolean_attr"]).to eq({ value: "true", type: "boolean" }) + expect(hash[:attributes]["float_attr"]).to eq({ value: "3.14", type: "double" }) + end + end +end diff --git a/sentry-ruby/spec/sentry/logging_spec.rb b/sentry-ruby/spec/sentry/logging_spec.rb new file mode 100644 index 000000000..11b067562 --- /dev/null +++ b/sentry-ruby/spec/sentry/logging_spec.rb @@ -0,0 +1,75 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe Sentry::Logging do + let(:default_logger) { Sentry::Logger.new(output)} + let(:output) { StringIO.new } + + def expect_log(level, message) + yield(message) + expect(output.string).to include(level.upcase) + expect(output.string).to include(message) + end + + context "when log events are not enabled" do + + before do + perform_basic_setup do |config| + config.logger = default_logger + end + end + + # TODO: At the moment the Sentry::Logger enforces info - is that intentional? + ["info", "warn", "error", "fatal"].each do |level| + describe "##{level}" do + it "logs using configured default logger" do + expect_log(level, "Hello World") { |msg| Sentry.logger.public_send(level, msg) } + end + end + end + end + + context "when log events are enabled" do + before do + perform_basic_setup do |config| + config.logger = default_logger + config._experiments = { enable_logs: true } + end + end + + # TODO: At the moment the Sentry::Logger enforces info - is that intentional? + ["info", "warn", "error", "fatal"].each do |level| + describe "##{level}" do + it "logs using default logger and LogEvent logger" do + expect_log(level, "Hello World") { |msg| Sentry.logger.public_send(level, msg) } + + expect(sentry_events.size).to be(1) + + log_event = sentry_events.first + + expect(log_event.type).to eql("log") + expect(log_event.level).to eql(level.to_sym) + expect(log_event.trace_id).to_not be(nil) + expect(log_event.body).to eql("Hello World") + end + + it "logs using default logger and LogEvent logger with extra attributes" do + payload = { user_id: 123, action: "create" } + + expect_log(level, "Hello World") { |msg| Sentry.logger.public_send(level, msg, payload) } + + expect(sentry_events.size).to be(1) + + log_event = sentry_events.first + + expect(log_event.type).to eql("log") + expect(log_event.level).to eql(level.to_sym) + expect(log_event.trace_id).to_not be(nil) + expect(log_event.body).to eql("Hello World") + expect(log_event.attributes).to include(payload) + end + end + end + end +end diff --git a/sentry-ruby/spec/sentry/transport_spec.rb b/sentry-ruby/spec/sentry/transport_spec.rb index 372fbf636..91ce45ed1 100644 --- a/sentry-ruby/spec/sentry/transport_spec.rb +++ b/sentry-ruby/spec/sentry/transport_spec.rb @@ -237,6 +237,83 @@ end end + context "log events" do + let(:log_events) do + 5.times.map do |i| + Sentry::LogEvent.new( + configuration: configuration, + level: :info, + body: "User John has logged in!", + trace_id: "5b8efff798038103d269b633813fc60c", + timestamp: 1544719860.0, + attributes: { + "sentry.message.template" => "User %s has logged in!", + "sentry.message.parameters.0" => "John", + "sentry.environment" => "production", + "sentry.release" => "1.0.0", + "sentry.trace.parent_span_id" => "b0e6f15b45c36b12" + } + ) + end + end + + let(:envelope) do + envelope = Sentry::Envelope.new + + # Add log item header + envelope.add_item( + { + type: "log", + item_count: log_events.size, + content_type: "application/vnd.sentry.items.log+json" + }, + { items: log_events.map(&:to_hash) } + ) + + envelope + end + + it "generates correct envelope content for log events" do + result, _ = subject.serialize_envelope(envelope) + + envelope_header, item_header, item_payload = result.split("\n") + + # Check envelope header + envelope_header_parsed = JSON.parse(envelope_header) + expect(envelope_header_parsed).to be_a(Hash) + + # Check item header + item_header_parsed = JSON.parse(item_header) + expect(item_header_parsed).to eq({ + "type" => "log", + "item_count" => 5, + "content_type" => "application/vnd.sentry.items.log+json" + }) + + # Check item payload + item_payload_parsed = JSON.parse(item_payload) + expect(item_payload_parsed).to have_key("items") + expect(item_payload_parsed["items"].size).to eq(5) + + # Check first log event + log_event = item_payload_parsed["items"].first + expect(log_event["level"]).to eq("info") + expect(log_event["body"]).to eq("User John has logged in!") + expect(log_event["trace_id"]).to eq("5b8efff798038103d269b633813fc60c") + # The timestamp should be a float representing seconds since epoch + expect(log_event["timestamp"]).to be_a(Float) + + # Check attributes + expect(log_event["attributes"]).to include( + "sentry.message.template" => {"value" => "User %s has logged in!", "type" => "string"}, + "sentry.message.parameters.0" => {"value" => "John", "type" => "string"}, + "sentry.environment" => {"value" => "production", "type" => "string"}, + "sentry.release" => {"value" => "1.0.0", "type" => "string"}, + "sentry.trace.parent_span_id" => {"value" => "b0e6f15b45c36b12", "type" => "string"} + ) + end + end + context "malformed breadcrumb" do let(:event) { client.event_from_message("foo") } @@ -502,6 +579,51 @@ expect(io.string).to match(/Sending envelope with items \[event, attachment, attachment\]/) end end + + context "log events" do + let(:log_events) do + 5.times.map do |i| + Sentry::LogEvent.new( + configuration: configuration, + level: :info, + body: "User John has logged in!", + trace_id: "5b8efff798038103d269b633813fc60c", + timestamp: 1544719860.0, + attributes: { + "sentry.message.template" => "User %s has logged in!", + "sentry.message.parameters.0" => "John", + "sentry.environment" => "production", + "sentry.release" => "1.0.0", + "sentry.trace.parent_span_id" => "b0e6f15b45c36b12" + } + ) + end + end + + let(:envelope) do + envelope = Sentry::Envelope.new + + # Add log item header + envelope.add_item( + { + type: "log", + item_count: log_events.size, + content_type: "application/vnd.sentry.items.log+json" + }, + { items: log_events.map(&:to_hash) } + ) + + envelope + end + + it "sends the log events and logs the action" do + expect(subject).to receive(:send_data) + + subject.send_envelope(envelope) + + expect(io.string).to match(/Sending envelope with items \[log\]/) + end + end end describe "#send_event" do