Merge pull request #3899 from DataDog/tonycthsu/telemetry_log_instrum…

…entation

Add telemetry logs for instrumentations

lib/datadog/tracing/contrib/action_pack/action_controller/instrumentation.rb

@@ -7,6 +7,7 @@
 require_relative '../utils'
 require_relative '../../rack/middlewares'
 require_relative '../../analytics'
+require_relative '../../../../core/telemetry/logger'
 
 module Datadog
   module Tracing
@@ -43,6 +44,7 @@ def start_processing(payload)
               span.set_tag(Tracing::Metadata::Ext::TAG_OPERATION, Ext::TAG_OPERATION_CONTROLLER)
             rescue StandardError => e
               Datadog.logger.error(e.message)
+              Datadog::Core::Telemetry::Logger.report(e)
             end
 
             def finish_processing(payload)
@@ -81,10 +83,13 @@ def finish_processing(payload)
               end
             rescue StandardError => e
               Datadog.logger.error(e.message)
+              Datadog::Core::Telemetry::Logger.report(e)
             end
 
             # Instrumentation for ActionController::Metal
             module Metal
+              # TODO: Refactor this method to avoid using async API that splits the logic
+              # into two different methods (`start_processing` and `finish_processing`)
               def process_action(*args)
                 # mutable payload with a tracing context that is used in two different
                 # signals; it propagates the request span so that it can be finished

lib/datadog/tracing/contrib/active_record/configuration/resolver.rb

@@ -2,6 +2,7 @@
 
 require_relative '../../configuration/resolver'
 require_relative 'makara_resolver'
+require_relative '../../../../core/telemetry/logger'
 
 module Datadog
   module Tracing
@@ -72,10 +73,12 @@ def resolve(db_config)
               #
               # `db_config` input may contain sensitive information such as passwords,
               # hence provide a succinct summary for the error logging.
+              #
               Datadog.logger.error(
                 'Failed to resolve ActiveRecord database configuration. '\
                 "Cause: #{e.class.name} Source: #{Array(e.backtrace).first}"
               )
+              Core::Telemetry::Logger.report(e, description: 'Failed to resolve ActiveRecord database configuration')
 
               nil
             end
@@ -95,6 +98,7 @@ def parse_matcher(matcher)
                 "Failed to resolve key #{matcher.inspect}. " \
                 "Cause: #{e.class.name} Source: #{Array(e.backtrace).first}"
               )
+              Core::Telemetry::Logger.report(e, description: 'Failed to resolve key')
 
               nil
             end

lib/datadog/tracing/contrib/elasticsearch/patcher.rb

@@ -93,11 +93,16 @@ def perform_request(*args)
                   span.resource = "#{method} #{quantized_url}"
                   Contrib::SpanAttributeSchema.set_peer_service!(span, Ext::PEER_SERVICE_SOURCES)
                 rescue StandardError => e
+                  # TODO: Refactor the code to streamline the execution without ensure
                   Datadog.logger.error(e.message)
+                  Datadog::Core::Telemetry::Logger.report(e)
                 ensure
                   # the call is still executed
                   response = super
-                  span.set_tag(Tracing::Metadata::Ext::HTTP::TAG_STATUS_CODE, response.status)
+
+                  if response && response.respond_to?(:status)
+                    span.set_tag(Tracing::Metadata::Ext::HTTP::TAG_STATUS_CODE, response.status)
+                  end
                 end
               end
               response

lib/datadog/tracing/contrib/grape/endpoint.rb

@@ -1,6 +1,7 @@
 # frozen_string_literal: true
 
 require_relative '../../../core'
+require_relative '../../../core/telemetry/logger'
 require_relative '../../metadata/ext'
 require_relative '../analytics'
 require_relative '../rack/ext'
@@ -64,6 +65,7 @@ def endpoint_start_process(_name, _start, _finish, _id, payload)
               Thread.current[KEY_RUN] = true
             rescue StandardError => e
               Datadog.logger.error(e.message)
+              Datadog::Core::Telemetry::Logger.report(e)
             end
 
             def endpoint_run(name, start, finish, id, payload)
@@ -107,6 +109,7 @@ def endpoint_run(name, start, finish, id, payload)
               end
             rescue StandardError => e
               Datadog.logger.error(e.message)
+              Datadog::Core::Telemetry::Logger.report(e)
             end
 
             # Status code resolution is tied to the exception handling
@@ -150,6 +153,7 @@ def endpoint_start_render(*)
               Thread.current[KEY_RENDER] = true
             rescue StandardError => e
               Datadog.logger.error(e.message)
+              Datadog::Core::Telemetry::Logger.report(e)
             end
 
             def endpoint_render(name, start, finish, id, payload)
@@ -174,6 +178,7 @@ def endpoint_render(name, start, finish, id, payload)
               end
             rescue StandardError => e
               Datadog.logger.error(e.message)
+              Datadog::Core::Telemetry::Logger.report(e)
             end
 
             def endpoint_run_filters(name, start, finish, id, payload)
@@ -212,6 +217,7 @@ def endpoint_run_filters(name, start, finish, id, payload)
               end
             rescue StandardError => e
               Datadog.logger.error(e.message)
+              Datadog::Core::Telemetry::Logger.report(e)
             end
 
             private

lib/datadog/tracing/contrib/http/instrumentation.rb

@@ -6,6 +6,7 @@
 require_relative '../analytics'
 require_relative '../http_annotation_helper'
 require_relative '../utils/quantization/http'
+require_relative '../../../core/telemetry/logger'
 
 module Datadog
   module Tracing
@@ -30,23 +31,19 @@ def request(req, body = nil, &block)
               return super(req, body, &block) if Contrib::HTTP.should_skip_tracing?(req)
 
               Tracing.trace(Ext::SPAN_REQUEST, on_error: method(:annotate_span_with_error!)) do |span, trace|
-                begin
-                  span.service = service_name(host, request_options, client_config)
-                  span.type = Tracing::Metadata::Ext::HTTP::TYPE_OUTBOUND
-                  span.resource = req.method
-
-                  if Tracing.enabled? && !Contrib::HTTP.should_skip_distributed_tracing?(client_config)
-                    Contrib::HTTP.inject(trace, req)
-                  end
-
-                  # Add additional request specific tags to the span.
-                  annotate_span_with_request!(span, req, request_options)
-                rescue StandardError => e
-                  Datadog.logger.error("error preparing span for http request: #{e}")
-                ensure
-                  response = super(req, body, &block)
+                span.service = service_name(host, request_options, client_config)
+                span.type = Tracing::Metadata::Ext::HTTP::TYPE_OUTBOUND
+                span.resource = req.method
+
+                if Tracing.enabled? && !Contrib::HTTP.should_skip_distributed_tracing?(client_config)
+                  Contrib::HTTP.inject(trace, req)
                 end
 
+                # Add additional request specific tags to the span.
+                annotate_span_with_request!(span, req, request_options)
+
+                response = super(req, body, &block)
+
                 # Add additional response specific tags to the span.
                 annotate_span_with_response!(span, response, request_options)
 
@@ -91,6 +88,9 @@ def annotate_span_with_request!(span, request, request_options)
               )
 
               Contrib::SpanAttributeSchema.set_peer_service!(span, Ext::PEER_SERVICE_SOURCES)
+            rescue StandardError => e
+              Datadog.logger.error("error preparing span from http request: #{e}")
+              Datadog::Core::Telemetry::Logger.report(e)
             end
 
             def annotate_span_with_response!(span, response, request_options)
@@ -103,6 +103,9 @@ def annotate_span_with_response!(span, response, request_options)
               span.set_tags(
                 Datadog.configuration.tracing.header_tags.response_tags(response)
               )
+            rescue StandardError => e
+              Datadog.logger.error("error preparing span from http response: #{e}")
+              Datadog::Core::Telemetry::Logger.report(e)
             end
 
             def annotate_span_with_error!(span, error)

lib/datadog/tracing/contrib/httpclient/instrumentation.rb

@@ -4,6 +4,7 @@
 require_relative '../http'
 require_relative '../analytics'
 require_relative '../http_annotation_helper'
+require_relative '../../../core/telemetry/logger'
 
 module Datadog
   module Tracing
@@ -36,7 +37,8 @@ def do_get_block(req, proxy, conn, &block)
                   # Add additional request specific tags to the span.
                   annotate_span_with_request!(span, req, request_options)
                 rescue StandardError => e
-                  logger.error("error preparing span for httpclient request: #{e}, Source: #{e.backtrace}")
+                  Datadog.logger.error("error preparing span for httpclient request: #{e}, Source: #{e.backtrace}")
+                  Datadog::Core::Telemetry::Logger.report(e)
                 ensure
                   res = super
                 end
@@ -114,10 +116,6 @@ def analytics_enabled?(request_options)
               Contrib::Analytics.enabled?(request_options[:analytics_enabled])
             end
 
-            def logger
-              Datadog.logger
-            end
-
             def should_skip_distributed_tracing?(client_config)
               return !client_config[:distributed_tracing] if client_config && client_config.key?(:distributed_tracing)
 

lib/datadog/tracing/contrib/httprb/instrumentation.rb

@@ -4,6 +4,7 @@
 require_relative '../http'
 require_relative '../analytics'
 require_relative '../http_annotation_helper'
+require_relative '../../../core/telemetry/logger'
 
 module Datadog
   module Tracing
@@ -35,6 +36,7 @@ def perform(req, options)
                   annotate_span_with_request!(span, req, request_options)
                 rescue StandardError => e
                   logger.error("error preparing span for http.rb request: #{e}, Source: #{e.backtrace}")
+                  Datadog::Core::Telemetry::Logger.report(e)
                 ensure
                   res = super(req, options)
                 end

lib/datadog/tracing/contrib/opensearch/patcher.rb

@@ -6,6 +6,7 @@
 require_relative '../ext'
 require_relative '../integration'
 require_relative '../patcher'
+require_relative '../../../core/telemetry/logger'
 
 module Datadog
   module Tracing
@@ -81,6 +82,8 @@ def perform_request(method, path, params = {}, body = nil, headers = nil)
                   Contrib::SpanAttributeSchema.set_peer_service!(span, Ext::PEER_SERVICE_SOURCES)
                 rescue StandardError => e
                   Datadog.logger.error(e.message)
+                  Datadog::Core::Telemetry::Logger.report(e)
+                  # TODO: Refactor the code to streamline the execution without ensure
                 ensure
                   begin
                     response = super
@@ -90,12 +93,16 @@ def perform_request(method, path, params = {}, body = nil, headers = nil)
                     raise
                   end
                   # Set post-response tags
-                  span.set_tag(Tracing::Metadata::Ext::HTTP::TAG_STATUS_CODE, response.status)
-                  if response.headers['content-length']
-                    span.set_tag(
-                      OpenSearch::Ext::TAG_RESPONSE_CONTENT_LENGTH,
-                      response.headers['content-length'].to_i
-                    )
+                  if response
+                    if response.respond_to?(:status)
+                      span.set_tag(Tracing::Metadata::Ext::HTTP::TAG_STATUS_CODE, response.status)
+                    end
+                    if response.respond_to?(:headers) && (response.headers || {})['content-length']
+                      span.set_tag(
+                        OpenSearch::Ext::TAG_RESPONSE_CONTENT_LENGTH,
+                        response.headers['content-length'].to_i
+                      )
+                    end
                   end
                 end
               end

lib/datadog/tracing/contrib/patcher.rb

@@ -1,6 +1,7 @@
 # frozen_string_literal: true
 
 require_relative '../../core/utils/only_once'
+require_relative '../../core/telemetry/logger'
 
 module Datadog
   module Tracing
@@ -49,8 +50,8 @@ def patch
           # Processes patching errors. This default implementation logs the error and reports relevant metrics.
           # @param e [Exception]
           def on_patch_error(e)
-            # Log the error
             Datadog.logger.error("Failed to apply #{patch_name} patch. Cause: #{e} Location: #{Array(e.backtrace).first}")
+            Datadog::Core::Telemetry::Logger.report(e, description: "Failed to apply #{patch_name} patch")
 
             @patch_error_result = {
               type: e.class.name,

spec/datadog/tracing/contrib/active_record/configuration/resolver_spec.rb

@@ -106,6 +106,15 @@
       let(:matcher) { 'bala boom!' }
 
       it 'does not resolves' do
+        expect(Datadog.logger).to receive(:error) do |message|
+          expect(message).to match(/failed to resolve/i)
+        end
+
+        expect(Datadog::Core::Telemetry::Logger).to receive(:report).with(
+          an_instance_of(URI::InvalidURIError),
+          description: 'Failed to resolve key'
+        )
+
         add
 
         expect(resolver.configurations).to be_empty
@@ -328,6 +337,11 @@
           expect(message).not_to match(/password/i)
         end
 
+        expect(Datadog::Core::Telemetry::Logger).to receive(:report).with(
+          an_instance_of(URI::InvalidURIError),
+          description: 'Failed to resolve ActiveRecord database configuration'
+        )
+
         is_expected.to be_nil
       end
     end

spec/datadog/tracing/contrib/grape/tracer_spec.rb

@@ -688,6 +688,7 @@
       before do
         Datadog.configure { |c| c.tracing.enabled = false }
         expect(Datadog.logger).to_not receive(:error)
+        expect(Datadog::Core::Telemetry::Logger).to_not receive(:report)
       end
 
       it 'runs the endpoint request without tracing' do