diff --git a/CHANGELOG.md b/CHANGELOG.md index b4458e0..d3c41c2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,10 @@ +## Unreleased +* Fix severity numbers sent with `opentelemetry-exporter-otlp-logs` >= 0.7.0 (Ruby levels were sent instead of OpenTelemetry levels). +* Remove the OTLP exporter monkey patch; severity is now mapped when the log is emitted. +* Replace the [#114](https://github.com/scoutapp/scout_apm_ruby_logging/pull/114) guard with a small `LogRecordData` shim, so mismatched `opentelemetry-exporter-otlp-logs` / `opentelemetry-logs-sdk` versions no longer drop logs. +* Declare `opentelemetry-logs-api` as a direct dependency. +* Fix `logger.unknown` raising `NameError`; it is now sent as FATAL. + ## 2.1.1 * Fix all logs being dropped with `opentelemetry-logs-sdk` >= 0.7.0. Thanks @rpearce! * See [#114](https://github.com/scoutapp/scout_apm_ruby_logging/pull/114). diff --git a/lib/scout_apm/logging/loggers/formatter.rb b/lib/scout_apm/logging/loggers/formatter.rb index 6f51373..d27b415 100644 --- a/lib/scout_apm/logging/loggers/formatter.rb +++ b/lib/scout_apm/logging/loggers/formatter.rb @@ -3,6 +3,7 @@ require 'json' require 'logger' +require 'opentelemetry-logs-api' require 'scout_apm' module ScoutApm @@ -12,6 +13,19 @@ module Loggers class Formatter < ::Logger::Formatter DATETIME_FORMAT = '%Y-%m-%dT%H:%M:%S.%LZ' + # Ruby's Logger::Severity integers (0..5) do not match OpenTelemetry's + # SeverityNumber scale. Emit the OTel value directly so the exporter can + # pass it straight through without a patch. Logger labels UNKNOWN as + # 'ANY'; it ranks above FATAL, so keep it at the top of the scale. + SEVERITY_NUMBER_MAP = { + 'DEBUG' => ::OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_DEBUG, + 'INFO' => ::OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_INFO, + 'WARN' => ::OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_WARN, + 'ERROR' => ::OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_ERROR, + 'FATAL' => ::OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_FATAL, + 'ANY' => ::OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_FATAL + }.freeze + def call(severity, time, progname, msg) attributes_to_log = { severity:, @@ -42,7 +56,9 @@ def emit_log(msg, severity, time, attributes_to_log) version: '0.1.0' ).on_emit( severity_text: severity, - severity_number: ::Logger::Severity.const_get(severity), + severity_number: SEVERITY_NUMBER_MAP.fetch( + severity, ::OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_UNSPECIFIED + ), attributes: attributes_to_log.transform_keys(&:to_s), timestamp: time, body: msg, diff --git a/lib/scout_apm/logging/loggers/opentelemetry/log_record_data_compat.rb b/lib/scout_apm/logging/loggers/opentelemetry/log_record_data_compat.rb new file mode 100644 index 0000000..bc54439 --- /dev/null +++ b/lib/scout_apm/logging/loggers/opentelemetry/log_record_data_compat.rb @@ -0,0 +1,34 @@ +# frozen_string_literal: true + +module OpenTelemetry + module SDK + module Logs + # The OTLP logs exporter and the logs SDK are versioned independently, and every exporter + # release only requires `opentelemetry-logs-sdk ~> 0.1`, so Bundler can resolve pairs that + # disagree on LogRecordData's fields: + # * exporter <= 0.5.1 reads `total_recorded_attributes`, which logs-sdk >= 0.7.0 replaced + # with `dropped_attributes_count` (read by exporter >= 0.6.0). See #114. + # * exporter >= 0.5.0 reads `event_name`, which logs-sdk < 0.6.0 does not have. + # Define whichever of these is missing so any resolved pair can export. + class LogRecordData + unless method_defined?(:total_recorded_attributes) + def total_recorded_attributes + attributes&.size.to_i + dropped_attributes_count.to_i + end + end + + unless method_defined?(:dropped_attributes_count) + def dropped_attributes_count + [total_recorded_attributes.to_i - attributes&.size.to_i, 0].max + end + end + + unless method_defined?(:event_name) + def event_name + nil + end + end + end + end + end +end diff --git a/lib/scout_apm/logging/loggers/opentelemetry/log_record_patch.rb b/lib/scout_apm/logging/loggers/opentelemetry/log_record_patch.rb deleted file mode 100644 index 933a4b6..0000000 --- a/lib/scout_apm/logging/loggers/opentelemetry/log_record_patch.rb +++ /dev/null @@ -1,45 +0,0 @@ -module OpenTelemetry - module Exporter - module OTLP - module Logs - # Patch the log record creation to add back severity number. - class LogsExporter - def as_otlp_log_record(log_record_data) - dropped_attributes_count = - if log_record_data.respond_to?(:dropped_attributes_count) - log_record_data.dropped_attributes_count - else - log_record_data.total_recorded_attributes - log_record_data.attributes&.size.to_i - end - - Opentelemetry::Proto::Logs::V1::LogRecord.new( - time_unix_nano: log_record_data.timestamp, - observed_time_unix_nano: log_record_data.observed_timestamp, - severity_number: as_otlp_severity_number(log_record_data.severity_number), - severity_text: log_record_data.severity_text, - body: as_otlp_any_value(log_record_data.body), - attributes: log_record_data.attributes&.map { |k, v| as_otlp_key_value(k, v) }, - dropped_attributes_count: dropped_attributes_count, - flags: log_record_data.trace_flags.instance_variable_get(:@flags), - trace_id: log_record_data.trace_id, - span_id: log_record_data.span_id - ) - end - - # TODO: This has been removed in newer versions of the OpenTelemetry Ruby Logs SDK, however - # it appears that we are missing the severity number. Investigate this. - def as_otlp_severity_number(severity_number) - case severity_number - when 0 then Opentelemetry::Proto::Logs::V1::SeverityNumber::SEVERITY_NUMBER_DEBUG - when 1 then Opentelemetry::Proto::Logs::V1::SeverityNumber::SEVERITY_NUMBER_INFO - when 2 then Opentelemetry::Proto::Logs::V1::SeverityNumber::SEVERITY_NUMBER_WARN - when 3 then Opentelemetry::Proto::Logs::V1::SeverityNumber::SEVERITY_NUMBER_ERROR - when 4 then Opentelemetry::Proto::Logs::V1::SeverityNumber::SEVERITY_NUMBER_FATAL - when 5 then Opentelemetry::Proto::Logs::V1::SeverityNumber::SEVERITY_NUMBER_UNSPECIFIED - end - end - end - end - end - end -end diff --git a/lib/scout_apm/logging/loggers/opentelemetry/opentelemetry.rb b/lib/scout_apm/logging/loggers/opentelemetry/opentelemetry.rb index 4d29c1d..59afbf3 100644 --- a/lib/scout_apm/logging/loggers/opentelemetry/opentelemetry.rb +++ b/lib/scout_apm/logging/loggers/opentelemetry/opentelemetry.rb @@ -4,7 +4,7 @@ require 'opentelemetry/sdk' require 'opentelemetry-logs-sdk' require 'opentelemetry/exporter/otlp_logs' -require_relative './log_record_patch' +require_relative './log_record_data_compat' module ScoutApm module Logging diff --git a/scout_apm_logging.gemspec b/scout_apm_logging.gemspec index 0928f24..74d6e49 100644 --- a/scout_apm_logging.gemspec +++ b/scout_apm_logging.gemspec @@ -23,6 +23,7 @@ Gem::Specification.new do |s| s.add_dependency 'opentelemetry-common' s.add_dependency 'opentelemetry-exporter-otlp-logs', '>= 0.2.0' s.add_dependency 'opentelemetry-instrumentation-base' + s.add_dependency 'opentelemetry-logs-api' s.add_dependency 'opentelemetry-logs-sdk', '>= 0.2.0' s.add_dependency 'opentelemetry-sdk', '>= 1.2' s.add_dependency 'scout_apm' diff --git a/spec/integration/rails/lifecycle_spec.rb b/spec/integration/rails/lifecycle_spec.rb index df9b3de..a9f15e8 100644 --- a/spec/integration/rails/lifecycle_spec.rb +++ b/spec/integration/rails/lifecycle_spec.rb @@ -24,8 +24,8 @@ # We have to write to the file, as we are applying the patch in the fork, and # need to run the expectations in the main process. File.open(@file_path, 'a+') do |file| - msgs = transform_body_to_msgs(request.body) - file.puts(msgs) + records = transform_body_to_records(request.body) + records.each { |record| file.puts(record.to_json) } end { body: '', headers: {}, status: 200 } end @@ -98,19 +98,28 @@ expect(local_messages.count('Fatal level log')).to eq(1) # Verify the logs are sent to the receiver - receiver_contents = File.readlines(@file_path, chomp: true) - expect(receiver_contents.count('[TEST] Some log')).to eq(1) - expect(receiver_contents.count('[YIELD] Yield Test')).to eq(1) - expect(receiver_contents.count('Another Log')).to eq(1) - expect(receiver_contents.count('Should not be captured')).to eq(0) - expect(local_messages.count('Warn level log')).to eq(1) - expect(local_messages.count('Error level log')).to eq(1) - expect(local_messages.count('Fatal level log')).to eq(1) + receiver_records = File.readlines(@file_path, chomp: true).map { |line| JSON.parse(line) } + receiver_messages = receiver_records.map { |record| record['body'] } + expect(receiver_messages.count('[TEST] Some log')).to eq(1) + expect(receiver_messages.count('[YIELD] Yield Test')).to eq(1) + expect(receiver_messages.count('Another Log')).to eq(1) + expect(receiver_messages.count('Should not be captured')).to eq(0) + expect(receiver_messages.count('Warn level log')).to eq(1) + expect(receiver_messages.count('Error level log')).to eq(1) + expect(receiver_messages.count('Fatal level log')).to eq(1) + + # Verify the severity number sent on the wire uses the OpenTelemetry scale, + # not Ruby's Logger::Severity scale. Guards against upstream exporter drift + # now that the severity-remapping patch has been removed. + expect(severity_for(receiver_records, 'Warn level log')).to eq(:SEVERITY_NUMBER_WARN) + expect(severity_for(receiver_records, 'Error level log')).to eq(:SEVERITY_NUMBER_ERROR) + expect(severity_for(receiver_records, 'Fatal level log')).to eq(:SEVERITY_NUMBER_FATAL) + expect(severity_for(receiver_records, '[TEST] Some log')).to eq(:SEVERITY_NUMBER_INFO) # Verify we recorded server ActionCable messages - expect(receiver_contents.count { |msg| msg.include?('ActionCable Connected:') }).to eq(1) - expect(receiver_contents.count('Subscribed to test_channel')).to eq(1) - expect(receiver_contents.count { |msg| msg.include?('Ding received with data: {"message"') }).to eq(1) + expect(receiver_messages.count { |msg| msg.include?('ActionCable Connected:') }).to eq(1) + expect(receiver_messages.count('Subscribed to test_channel')).to eq(1) + expect(receiver_messages.count { |msg| msg.include?('Ding received with data: {"message"') }).to eq(1) expect(local_messages.count { |msg| msg.include?('ActionCable Connected:') }).to eq(1) expect(local_messages.count('Subscribed to test_channel')).to eq(1) expect(local_messages.count { |msg| msg.include?('Ding received with data: {"message"') }).to eq(1) @@ -122,7 +131,7 @@ private - def transform_body_to_msgs(body) + def transform_body_to_records(body) # rubocop:disable Metrics/AbcSize gz = Zlib::GzipReader.new(StringIO.new(body)) uncompressed = gz.read @@ -132,9 +141,18 @@ def transform_body_to_msgs(body) value_hash[:resource_logs].map do |item| item[:scope_logs].map do |sl| sl[:log_records].map do |log| - log[:body][:string_value] + { + 'body' => log[:body][:string_value], + 'severity_number' => log[:severity_number], + 'severity_text' => log[:severity_text] + } end end end.flatten end + + def severity_for(records, body) + record = records.find { |item| item['body'] == body } + record && record['severity_number']&.to_sym + end end diff --git a/spec/unit/loggers/formatter_spec.rb b/spec/unit/loggers/formatter_spec.rb new file mode 100644 index 0000000..26c4427 --- /dev/null +++ b/spec/unit/loggers/formatter_spec.rb @@ -0,0 +1,44 @@ +require 'logger' +require 'stringio' + +require 'spec_helper' + +require 'scout_apm_logging' + +describe ScoutApm::Logging::Loggers::Formatter do + let(:exporter) { OpenTelemetry::SDK::Logs::Export::InMemoryLogRecordExporter.new } + + before do + ScoutApm::Logging::Context.instance + + provider = OpenTelemetry::SDK::Logs::LoggerProvider.new + provider.add_log_record_processor(OpenTelemetry::SDK::Logs::Export::SimpleLogRecordProcessor.new(exporter)) + ScoutApm::Logging::Loggers::OpenTelemetry.logger_provider = provider + end + + { + 'DEBUG' => :SEVERITY_NUMBER_DEBUG, + 'INFO' => :SEVERITY_NUMBER_INFO, + 'WARN' => :SEVERITY_NUMBER_WARN, + 'ERROR' => :SEVERITY_NUMBER_ERROR, + 'FATAL' => :SEVERITY_NUMBER_FATAL, + 'ANY' => :SEVERITY_NUMBER_FATAL, + 'SOMETHING_ELSE' => :SEVERITY_NUMBER_UNSPECIFIED + }.each do |label, expected| + it "emits #{expected} for #{label}" do + described_class.new.call(label, Time.now, nil, 'msg') + + record = exporter.emitted_log_records.last + expect(record.severity_text).to eq(label) + expect(record.severity_number).to eq(OpenTelemetry::Logs::SeverityNumber.const_get(expected)) + end + end + + it 'maps Logger#unknown to FATAL' do + logger = ::Logger.new(StringIO.new) + logger.formatter = described_class.new + logger.unknown('gone') + + expect(exporter.emitted_log_records.last.severity_number).to eq(OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_FATAL) + end +end diff --git a/spec/unit/loggers/logger_spec.rb b/spec/unit/loggers/logger_spec.rb index 8aeb660..1322a95 100644 --- a/spec/unit/loggers/logger_spec.rb +++ b/spec/unit/loggers/logger_spec.rb @@ -5,11 +5,6 @@ require 'scout_apm_logging' -ScoutApm::Logging::Loggers::Formatter.class_exec do - define_method(:emit_log) do |msg, severity, time, attributes_to_log| - end -end - def capture_stdout old_stdout = $stdout $stdout = StringIO.new @@ -20,6 +15,10 @@ def capture_stdout end describe ScoutApm::Logging::Loggers::Logger do + before do + allow_any_instance_of(ScoutApm::Logging::Loggers::Formatter).to receive(:emit_log) + end + it 'should not capture call stack or log line' do ScoutApm::Logging::Context.instance diff --git a/spec/unit/loggers/opentelemetry/log_record_data_compat_spec.rb b/spec/unit/loggers/opentelemetry/log_record_data_compat_spec.rb new file mode 100644 index 0000000..2d4ad3f --- /dev/null +++ b/spec/unit/loggers/opentelemetry/log_record_data_compat_spec.rb @@ -0,0 +1,44 @@ +require 'spec_helper' + +require_relative '../../../../lib/scout_apm/logging/loggers/opentelemetry/opentelemetry' + +describe OpenTelemetry::SDK::Logs::LogRecordData do + let(:exporter) { OpenTelemetry::SDK::Logs::Export::InMemoryLogRecordExporter.new } + + let(:log_record_data) do + provider = OpenTelemetry::SDK::Logs::LoggerProvider.new + provider.add_log_record_processor(OpenTelemetry::SDK::Logs::Export::SimpleLogRecordProcessor.new(exporter)) + + provider.logger(name: 'scout_apm', version: '0.1.0').on_emit( + severity_text: 'INFO', + severity_number: OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_INFO, + attributes: { 'controller' => 'UsersController' }, + timestamp: Time.now, + body: 'Processing by UsersController#index' + ) + + exporter.emitted_log_records.first + end + + it 'responds to the fields read by every supported exporter version' do + expect(log_record_data.total_recorded_attributes).to eq(1) + expect(log_record_data.dropped_attributes_count).to eq(0) + expect(log_record_data).to respond_to(:event_name) + end + + it 'exports through the installed OTLP exporter without raising' do + otlp_exporter = OpenTelemetry::Exporter::OTLP::Logs::LogsExporter.new + # Exporter >= 0.7.0 moved encoding into opentelemetry-exporter-otlp-common. + encoded = if otlp_exporter.respond_to?(:encode, true) + otlp_exporter.send(:encode, [log_record_data]) + else + OpenTelemetry::Exporter::OTLP::Common.as_encoded_elsr([log_record_data]) + end + request = Opentelemetry::Proto::Collector::Logs::V1::ExportLogsServiceRequest.decode(encoded) + record = request.resource_logs.first.scope_logs.first.log_records.first + + expect(record.body.string_value).to eq('Processing by UsersController#index') + expect(record.severity_number).to eq(:SEVERITY_NUMBER_INFO) + expect(record.dropped_attributes_count).to eq(0) + end +end diff --git a/spec/unit/loggers/opentelemetry/log_record_patch_spec.rb b/spec/unit/loggers/opentelemetry/log_record_patch_spec.rb deleted file mode 100644 index bdcda14..0000000 --- a/spec/unit/loggers/opentelemetry/log_record_patch_spec.rb +++ /dev/null @@ -1,38 +0,0 @@ -require 'logger' - -require 'spec_helper' - -require_relative '../../../../lib/scout_apm/logging/loggers/opentelemetry/opentelemetry' - -describe OpenTelemetry::Exporter::OTLP::Logs::LogsExporter do - let(:log_record_data) do - exporter = OpenTelemetry::SDK::Logs::Export::InMemoryLogRecordExporter.new - provider = OpenTelemetry::SDK::Logs::LoggerProvider.new - provider.add_log_record_processor(OpenTelemetry::SDK::Logs::Export::SimpleLogRecordProcessor.new(exporter)) - - provider.logger(name: 'scout_apm', version: '0.1.0').on_emit( - severity_text: 'INFO', - severity_number: ::Logger::Severity::INFO, - attributes: { 'controller' => 'UsersController' }, - timestamp: Time.now, - body: 'Processing by UsersController#index' - ) - - exporter.emitted_log_records.first - end - - describe '#as_otlp_log_record' do - subject(:otlp_log_record) { described_class.new.as_otlp_log_record(log_record_data) } - - it 'encodes the body, severity and attributes' do - expect(otlp_log_record.body.string_value).to eq('Processing by UsersController#index') - expect(otlp_log_record.severity_text).to eq('INFO') - expect(otlp_log_record.severity_number).to eq(:SEVERITY_NUMBER_INFO) - expect(otlp_log_record.attributes.map(&:key)).to eq(['controller']) - end - - it 'reports no dropped attributes when none were dropped' do - expect(otlp_log_record.dropped_attributes_count).to eq(0) - end - end -end