Remove severity-number exporter patch; map severity at emit time

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).

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,

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

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

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'

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

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

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
 

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