DEBUG-3210 DI: change logging to be appropriate for customer inspection

Failure to enable DI is now a warning (since enabling it must have
been requested by the customer).

Remaining logging calls are now emitted at debug level by default,
making those entries not visible in customer logs.

An internal DI setting is added to reinstate logging of
internal issues at warn level, for developing/debugging DI.

lib/datadog/di/code_tracker.rb

@@ -91,7 +91,7 @@ def start
             # before release.
             if component = DI.current_component # steep:ignore
               raise if component.settings.dynamic_instrumentation.internal.propagate_all_exceptions
-              component.logger.warn("Unhandled exception in script_compiled trace point: #{exc.class}: #{exc}")
+              component.log_warn_internal("Unhandled exception in script_compiled trace point: #{exc.class}: #{exc}")
               component.telemetry&.report(exc, description: "Unhandled exception in script_compiled trace point")
               # TODO test this path
             else

lib/datadog/di/component.rb

@@ -1,5 +1,7 @@
 # frozen_string_literal: true
 
+require_relative 'logging'
+
 module Datadog
   module DI
     # Component for dynamic instrumentation.
@@ -13,12 +15,14 @@ module DI
     # intalled tracepoints and so on. Component will clean up all
     # resources and installed tracepoints upon shutdown.
     class Component
+      include Logging
+
       class << self
         def build(settings, agent_settings, telemetry: nil)
           return unless settings.respond_to?(:dynamic_instrumentation) && settings.dynamic_instrumentation.enabled
 
           unless settings.respond_to?(:remote) && settings.remote.enabled
-            Datadog.logger.debug("Dynamic Instrumentation could not be enabled because Remote Configuration Management is not available. To enable Remote Configuration, see https://docs.datadoghq.com/agent/remote_config")
+            Datadog.logger.warn("Dynamic Instrumentation could not be enabled because Remote Configuration Management is not available. To enable Remote Configuration, see https://docs.datadoghq.com/agent/remote_config")
             return
           end
 
@@ -53,12 +57,12 @@ def environment_supported?(settings)
           # TODO add tests?
           unless settings.dynamic_instrumentation.internal.development
             if Datadog::Core::Environment::Execution.development?
-              Datadog.logger.debug("Not enabling dynamic instrumentation because we are in development environment")
+              Datadog.logger.warn("Not enabling dynamic instrumentation because we are in development environment")
               return false
             end
           end
           if RUBY_ENGINE != 'ruby' || RUBY_VERSION < '2.6'
-            Datadog.logger.debug("Not enabling dynamic instrumentation because of unsupported Ruby version")
+            Datadog.logger.warn("Not enabling dynamic instrumentation because of unsupported Ruby version")
             return false
           end
           true

lib/datadog/di/configuration/settings.rb

@@ -157,6 +157,15 @@ def self.add_settings!(base)
                   o.default false
                 end
 
+                # Increases logging verbosity level from 'debug' to 'warn'
+                # for internal DI diagnostics, i.e. log messages that
+                # should not be written to customers' logs in production but
+                # that are useful when developing DI.
+                option :verbose_logging do |o|
+                  o.type :bool
+                  o.default false
+                end
+
                 # Minimum interval, in seconds, between probe status and
                 # snapshot submissions to the agent. Probe notifier worker will
                 # batch together payloads submitted during each interval.

lib/datadog/di/instrumenter.rb

@@ -3,6 +3,7 @@
 # rubocop:disable Lint/AssignmentInCondition
 
 require 'benchmark'
+require_relative 'logging'
 
 module Datadog
   module DI
@@ -54,6 +55,8 @@ module DI
     #
     # @api private
     class Instrumenter
+      include Logging
+
       def initialize(settings, serializer, logger, code_tracker: nil, telemetry: nil)
         @settings = settings
         @serializer = serializer
@@ -305,13 +308,13 @@ def hook_line(probe, &block)
             end
           rescue => exc
             raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions
-            logger.warn("Unhandled exception in line trace point: #{exc.class}: #{exc}")
+            log_warn_internal("Unhandled exception in line trace point: #{exc.class}: #{exc}")
             telemetry&.report(exc, description: "Unhandled exception in line trace point")
             # TODO test this path
           end
         rescue => exc
           raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions
-          logger.warn("Unhandled exception in line trace point: #{exc.class}: #{exc}")
+          log_warn_internal("Unhandled exception in line trace point: #{exc.class}: #{exc}")
           telemetry&.report(exc, description: "Unhandled exception in line trace point")
           # TODO test this path
         end
@@ -357,7 +360,7 @@ def hook(probe, &block)
           hook_line(probe, &block)
         else
           # TODO add test coverage for this path
-          logger.warn("Unknown probe type to hook: #{probe}")
+          log_warn_internal("Unknown probe type to hook: #{probe}")
         end
       end
 
@@ -368,7 +371,7 @@ def unhook(probe)
           unhook_line(probe)
         else
           # TODO add test coverage for this path
-          logger.warn("Unknown probe type to unhook: #{probe}")
+          log_warn_internal("Unknown probe type to unhook: #{probe}")
         end
       end
 

lib/datadog/di/logging.rb

@@ -0,0 +1,30 @@
+# frozen_string_literal: true
+
+module Datadog
+  module DI
+    # Logging for DI
+    module Logging
+      # Logs an internal warning message.
+      # When verbose logging is enabled, the logging happens at warn level.
+      # When verbose logging is disabled, the logging happens at debug level
+      # (which is how the rest of the library is reporting its internal
+      # warnings/errors).
+      def log_warn_internal(msg)
+        if settings.dynamic_instrumentation.internal.verbose_logging
+          logger.warn(msg)
+        else
+          logger.debug(msg)
+        end
+      end
+
+      # Logs an internal informational message.
+      # When verbose logging is enabled, the logging happens at info level.
+      # When verbose logging is disabled, nothing is logged.
+      def log_info_internal(msg)
+        if settings.dynamic_instrumentation.internal.verbose_logging
+          logger.info(msg)
+        end
+      end
+    end
+  end
+end

lib/datadog/di/probe_manager.rb

@@ -3,6 +3,7 @@
 # rubocop:disable Lint/AssignmentInCondition
 
 require 'monitor'
+require_relative 'logging'
 
 module Datadog
   module DI
@@ -15,6 +16,8 @@ module DI
     #
     # @api private
     class ProbeManager
+      include Logging
+
       def initialize(settings, instrumenter, probe_notification_builder,
         probe_notifier_worker, logger, telemetry: nil)
         @settings = settings
@@ -32,7 +35,7 @@ def initialize(settings, instrumenter, probe_notification_builder,
           install_pending_method_probes(tp.self)
         rescue => exc
           raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions
-          logger.warn("Unhandled exception in definition trace point: #{exc.class}: #{exc}")
+          log_warn_internal("Unhandled exception in definition trace point: #{exc.class}: #{exc}")
           telemetry&.report(exc, description: "Unhandled exception in definition trace point")
           # TODO test this path
         end
@@ -120,7 +123,7 @@ def add_probe(probe)
           # In "propagate all exceptions" mode we will try to instrument again.
           raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions
 
-          logger.warn("Error processing probe configuration: #{exc.class}: #{exc}")
+          log_warn_internal("Error processing probe configuration: #{exc.class}: #{exc}")
           telemetry&.report(exc, description: "Error processing probe configuration")
           # TODO report probe as failed to agent since we won't attempt to
           # install it again.
@@ -160,7 +163,7 @@ def remove_other_probes(probe_ids)
                 raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions
                 # Silence all exceptions?
                 # TODO should we propagate here and rescue upstream?
-                logger.warn("Error removing probe #{probe.id}: #{exc.class}: #{exc}")
+                log_warn_internal("Error removing probe #{probe.id}: #{exc.class}: #{exc}")
                 telemetry&.report(exc, description: "Error removing probe")
               end
             end
@@ -190,7 +193,7 @@ def remove_other_probes(probe_ids)
                 rescue => exc
                   raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions
 
-                  logger.warn("Error installing probe after class is defined: #{exc.class}: #{exc}")
+                  log_warn_internal("Error installing probe after class is defined: #{exc.class}: #{exc}")
                   telemetry&.report(exc, description: "Error installing probe after class is defined")
                 end
               end

lib/datadog/di/probe_notifier_worker.rb

@@ -1,6 +1,7 @@
 # frozen_string_literal: true
 
 require_relative '../core/semaphore'
+require_relative 'logging'
 
 module Datadog
   module DI
@@ -23,6 +24,8 @@ module DI
     #
     # @api private
     class ProbeNotifierWorker
+      include Logging
+
       def initialize(settings, transport, logger, telemetry: nil)
         @settings = settings
         @telemetry = telemetry
@@ -77,7 +80,7 @@ def start
             rescue => exc
               raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions
 
-              logger.warn("Error in probe notifier worker: #{exc.class}: #{exc} (at #{exc.backtrace.first})")
+              log_warn_internal("Error in probe notifier worker: #{exc.class}: #{exc} (at #{exc.backtrace.first})")
               telemetry&.report(exc, description: "Error in probe notifier worker")
             end
             @lock.synchronize do
@@ -185,7 +188,7 @@ def io_in_progress?
             queue = send("#{event_type}_queue")
             # TODO determine a suitable limit via testing/benchmarking
             if queue.length > 100
-              logger.warn("#{self.class.name}: dropping #{event_type} because queue is full")
+              log_warn_internal("#{self.class.name}: dropping #{event_type} because queue is full")
             else
               queue << event
             end
@@ -242,7 +245,7 @@ def set_sleep_remaining
               end
             rescue => exc
               raise if settings.dynamic_instrumentation.internal.propagate_all_exceptions
-              logger.warn("failed to send #{event_name}: #{exc.class}: #{exc} (at #{exc.backtrace.first})")
+              log_warn_internal("failed to send #{event_name}: #{exc.class}: #{exc} (at #{exc.backtrace.first})")
               # Should we report this error to telemetry? Most likely failure
               # to send is due to a network issue, and trying to send a
               # telemetry message would also fail.
@@ -253,7 +256,7 @@ def set_sleep_remaining
           # Normally the queue should only be consumed in this method,
           # however if anyone consumes it elsewhere we don't want to block
           # while consuming it here. Rescue ThreadError and return.
-          logger.warn("Unexpected #{event_name} queue underflow - consumed elsewhere?")
+          log_warn_internal("Unexpected #{event_name} queue underflow - consumed elsewhere?")
           telemetry&.report(exc, description: "Unexpected #{event_name} queue underflow")
         ensure
           @lock.synchronize do

lib/datadog/di/remote.rb

@@ -51,7 +51,7 @@ def receivers(telemetry)
                     probe = ProbeBuilder.build_from_remote_config(probe_spec)
                     payload = component.probe_notification_builder.build_received(probe)
                     component.probe_notifier_worker.add_status(payload)
-                    component.logger.info("Received probe from RC: #{probe.type} #{probe.location}")
+                    component.log_info_internal("Received probe from RC: #{probe.type} #{probe.location}")
 
                     begin
                       # TODO test exception capture
@@ -60,7 +60,7 @@ def receivers(telemetry)
                     rescue => exc
                       raise if component.settings.dynamic_instrumentation.internal.propagate_all_exceptions
 
-                      component.logger.warn("Unhandled exception adding probe in DI remote receiver: #{exc.class}: #{exc}")
+                      component.log_warn_internal("Unhandled exception adding probe in DI remote receiver: #{exc.class}: #{exc}")
                       component.telemetry&.report(exc, description: "Unhandled exception adding probe in DI remote receiver")
 
                       # If a probe fails to install, we will mark the content
@@ -81,7 +81,7 @@ def receivers(telemetry)
                   rescue => exc
                     raise if component.settings.dynamic_instrumentation.internal.propagate_all_exceptions
 
-                    component.logger.warn("Unhandled exception handling probe in DI remote receiver: #{exc.class}: #{exc}")
+                    component.log_warn_internal("Unhandled exception handling probe in DI remote receiver: #{exc.class}: #{exc}")
                     component.telemetry&.report(exc, description: "Unhandled exception handling probe in DI remote receiver")
 
                     content.errored("Error applying dynamic instrumentation configuration: #{exc.class.name} #{exc.message}: #{Array(exc.backtrace).join("\n")}")
@@ -95,7 +95,7 @@ def receivers(telemetry)
               rescue => exc
                 raise if component.settings.dynamic_instrumentation.internal.propagate_all_exceptions
 
-                component.logger.warn("Unhandled exception removing probes in DI remote receiver: #{exc.class}: #{exc}")
+                component.log_warn_internal("Unhandled exception removing probes in DI remote receiver: #{exc.class}: #{exc}")
                 component.telemetry&.report(exc, description: "Unhandled exception removing probes in DI remote receiver")
               end
             end

spec/datadog/di/instrumenter_spec.rb

@@ -11,6 +11,7 @@
   mock_settings_for_di do |settings|
     allow(settings.dynamic_instrumentation).to receive(:enabled).and_return(true)
     allow(settings.dynamic_instrumentation.internal).to receive(:untargeted_trace_points).and_return(false)
+    allow(settings.dynamic_instrumentation.internal).to receive(:verbose_logging).and_return(true)
     allow(settings.dynamic_instrumentation).to receive(:max_capture_depth).and_return(2)
     allow(settings.dynamic_instrumentation).to receive(:max_capture_attribute_count).and_return(2)
     allow(settings.dynamic_instrumentation).to receive(:max_capture_string_length).and_return(100)

spec/datadog/di/probe_manager_spec.rb

@@ -9,6 +9,7 @@ class ProbeManagerSpecTestClass; end
   mock_settings_for_di do |settings|
     allow(settings.dynamic_instrumentation).to receive(:enabled).and_return(true)
     allow(settings.dynamic_instrumentation.internal).to receive(:propagate_all_exceptions).and_return(false)
+    allow(settings.dynamic_instrumentation.internal).to receive(:verbose_logging).and_return(true)
   end
 
   let(:instrumenter) do

spec/datadog/di/remote_spec.rb

@@ -92,6 +92,7 @@
       mock_settings_for_di do |settings|
         allow(settings.dynamic_instrumentation).to receive(:enabled).and_return(true)
         allow(settings.dynamic_instrumentation.internal).to receive(:propagate_all_exceptions).and_return(false)
+        allow(settings.dynamic_instrumentation.internal).to receive(:verbose_logging).and_return(true)
       end
 
       let(:serializer) do
@@ -144,8 +145,7 @@
         end
 
         it 'calls probe manager to add a probe' do
-          expect(component).to receive(:logger).and_return(logger)
-          expect(logger).to receive(:info) do |message|
+          expect(component).to receive(:log_info_internal) do |message|
             expect(message).to match(/Received probe/)
           end
 
@@ -162,15 +162,13 @@
         context 'probe addition raises an exception' do
           it 'logs warning and consumes the exception' do
             expect(component).to receive(:telemetry).and_return(telemetry)
-            expect(component).to receive(:logger).and_return(logger)
-            expect(logger).to receive(:info) do |message|
+            expect(component).to receive(:log_info_internal) do |message|
               expect(message).to match(/Received probe/)
             end
 
-            expect(logger).to receive(:warn) do |msg|
+            expect(component).to receive(:log_warn_internal) do |msg|
               expect(msg).to match(/Unhandled exception.*Runtime error from test/)
             end
-            expect(component).to receive(:logger).and_return(logger)
             expect(telemetry).to receive(:report)
 
             expect(probe_manager).to receive(:add_probe).and_raise("Runtime error from test")
@@ -186,17 +184,15 @@
 
         it 'calls probe manager to remove stale probes' do
           allow(component).to receive(:telemetry)
-          expect(component).to receive(:logger).and_return(logger)
-          expect(logger).to receive(:info) do |message|
+          expect(component).to receive(:log_info_internal) do |message|
             expect(message).to match(/Received probe/)
           end
 
-          expect(logger).to receive(:warn) do |msg|
+          expect(component).to receive(:log_warn_internal) do |msg|
             expect(msg).to match(/Unhandled exception.*Runtime error from test/)
           end
 
           allow(probe_manager).to receive(:add_probe).and_raise("Runtime error from test")
-          expect(component).to receive(:logger).and_return(logger)
           expect(component).to receive(:probe_notification_builder).and_return(probe_notification_builder)
           expect(probe_notification_builder).to receive(:build_received)
           expect(component).to receive(:probe_notifier_worker).and_return(probe_notifier_worker)
@@ -209,27 +205,24 @@
         context 'probe removal raises an exception' do
           it 'logs warning and consumes the exception' do
             expect(component).to receive(:telemetry).and_return(telemetry).at_least(:once)
-            expect(component).to receive(:logger).and_return(logger)
-            expect(logger).to receive(:info) do |message|
+            expect(component).to receive(:log_info_internal) do |message|
               expect(message).to match(/Received probe/)
             end
 
-            expect(logger).to receive(:warn) do |msg|
+            expect(component).to receive(:log_warn_internal) do |msg|
               expect(msg).to match(/Unhandled exception.*Runtime error 1 from test/)
             end
             expect(telemetry).to receive(:report)
 
             allow(probe_manager).to receive(:add_probe).and_raise("Runtime error 1 from test")
-            expect(component).to receive(:logger).and_return(logger)
             expect(component).to receive(:probe_notification_builder).and_return(probe_notification_builder)
             expect(probe_notification_builder).to receive(:build_received)
             expect(component).to receive(:probe_notifier_worker).and_return(probe_notifier_worker)
             expect(probe_notifier_worker).to receive(:add_status)
 
-            expect(logger).to receive(:warn) do |msg|
+            expect(component).to receive(:log_warn_internal) do |msg|
               expect(msg).to match(/Unhandled exception.*Runtime error 2 from test/)
             end
-            expect(component).to receive(:logger).and_return(logger)
             expect(telemetry).to receive(:report)
 
             expect(probe_manager).to receive(:remove_other_probes).with(['11']).and_raise("Runtime error 2 from test")