Merge pull request #3468 from DataDog/ivoanjo/backport-reduce-logger-…

…verbosity

Backport "Reduce startup logs verbosity" to master

Steepfile

@@ -70,7 +70,6 @@ target :ddtrace do
   ignore 'lib/datadog/core/configuration/option_definition_set.rb'
   ignore 'lib/datadog/core/configuration/options.rb'
   ignore 'lib/datadog/core/configuration/settings.rb'
-  ignore 'lib/datadog/core/diagnostics/environment_logger.rb'
   ignore 'lib/datadog/core/diagnostics/health.rb'
   ignore 'lib/datadog/core/encoding.rb'
   ignore 'lib/datadog/core/environment/container.rb'

lib/datadog/core/configuration/components.rb

@@ -81,6 +81,7 @@ def build_telemetry(settings, agent_settings, logger)
 
         def initialize(settings)
           @logger = self.class.build_logger(settings)
+          @environment_logger_extra = {}
 
           # This agent_settings is intended for use within Core. If you require
           # agent_settings within a product outside of core you should extend
@@ -90,11 +91,13 @@ def initialize(settings)
           @remote = Remote::Component.build(settings, agent_settings)
           @tracer = self.class.build_tracer(settings, logger: @logger)
 
-          @profiler = Datadog::Profiling::Component.build_profiler_component(
+          @profiler, profiler_logger_extra = Datadog::Profiling::Component.build_profiler_component(
             settings: settings,
             agent_settings: agent_settings,
             optional_tracer: @tracer,
           )
+          @environment_logger_extra.merge!(profiler_logger_extra) if profiler_logger_extra
+
           @runtime_metrics = self.class.build_runtime_metrics_worker(settings)
           @health_metrics = self.class.build_health_metrics(settings)
           @telemetry = self.class.build_telemetry(settings, agent_settings, logger)
@@ -116,7 +119,7 @@ def startup!(settings)
             @logger.debug('Profiling is disabled')
           end
 
-          Core::Diagnostics::EnvironmentLogger.collect_and_log!
+          Core::Diagnostics::EnvironmentLogger.collect_and_log!(@environment_logger_extra)
         end
 
         # Shuts down all the components in use.

lib/datadog/core/diagnostics/environment_logger.rb

@@ -1,8 +1,8 @@
 # frozen_string_literal: true
 
-require 'date'
 require 'json'
 require 'rbconfig'
+require 'time'
 
 module Datadog
   module Core
@@ -58,9 +58,10 @@ def rspec?
       module EnvironmentLogger
         extend EnvironmentLogging
 
-        def self.collect_and_log!
+        def self.collect_and_log!(extra_fields = nil)
           log_once! do
             data = EnvironmentCollector.collect_config!
+            data = data.merge(extra_fields) if extra_fields
             log_configuration!('CORE', data.to_json)
           end
         rescue => e
@@ -91,7 +92,7 @@ def collect_config!
 
           # @return [String] current time in ISO8601 format
           def date
-            DateTime.now.iso8601
+            Time.now.utc.iso8601
           end
 
           # Best portable guess of OS information.

lib/datadog/profiling.rb

@@ -130,7 +130,6 @@ def self.allocation_count # rubocop:disable Lint/NestedMethodDefinition (On purp
       require_relative 'profiling/collectors/idle_sampling_helper'
       require_relative 'profiling/collectors/stack'
       require_relative 'profiling/collectors/thread_context'
-      require_relative 'profiling/diagnostics/environment_logger'
       require_relative 'profiling/stack_recorder'
       require_relative 'profiling/exporter'
       require_relative 'profiling/flush'

lib/datadog/profiling/component.rb

@@ -8,11 +8,7 @@ module Component
       # * Code Hotspots panel in the trace viewer, as well as scoping a profile down to a span
       # * Endpoint aggregation in the profiler UX, including normalization (resource per endpoint call)
       def self.build_profiler_component(settings:, agent_settings:, optional_tracer:) # rubocop:disable Metrics/MethodLength
-        require_relative '../profiling/diagnostics/environment_logger'
-
-        Profiling::Diagnostics::EnvironmentLogger.collect_and_log!
-
-        return unless settings.profiling.enabled
+        return [nil, { profiling_enabled: false }] unless settings.profiling.enabled
 
         # Workaround for weird dependency direction: the Core::Configuration::Components class currently has a
         # dependency on individual products, in this case the Profiler.
@@ -32,7 +28,8 @@ def self.build_profiler_component(settings:, agent_settings:, optional_tracer:)
         # done, then profiling may not be loaded, and thus to avoid this issue we do a require here (which is a
         # no-op if profiling is already loaded).
         require_relative '../profiling'
-        return unless Profiling.supported?
+
+        return [nil, { profiling_enabled: false }] unless Profiling.supported?
 
         # Activate forking extensions
         Profiling::Tasks::Setup.new.run
@@ -76,7 +73,7 @@ def self.build_profiler_component(settings:, agent_settings:, optional_tracer:)
         transport = build_profiler_transport(settings, agent_settings)
         scheduler = Profiling::Scheduler.new(exporter: exporter, transport: transport, interval: upload_period_seconds)
 
-        Profiling::Profiler.new(worker: worker, scheduler: scheduler)
+        [Profiling::Profiler.new(worker: worker, scheduler: scheduler), { profiling_enabled: true }]
       end
 
       private_class_method def self.build_thread_context_collector(settings, recorder, optional_tracer, timeline_enabled)

sig/datadog/core/diagnostics/environment_logger.rbs

@@ -10,7 +10,7 @@ module Datadog
         def log_once!: () ?{ () -> untyped } -> (false | untyped)
         def log?: () -> untyped
 
-        REPL_PROGRAM_NAMES: ::Array["irb" | "pry"]
+        REPL_PROGRAM_NAMES: ::Array[::String]
 
         def repl?: () -> untyped
 
@@ -19,7 +19,7 @@ module Datadog
       module EnvironmentLogger
         extend EnvironmentLogging
 
-        def self.collect_and_log!: () -> untyped
+        def self.collect_and_log!: (untyped extra_fields) -> untyped
       end
       module EnvironmentCollector
         def self.collect_config!: () -> { date: untyped, os_name: untyped, version: untyped, lang: untyped, lang_version: untyped, env: untyped, service: untyped, dd_version: untyped, debug: untyped, tags: untyped, runtime_metrics_enabled: untyped, vm: untyped, health_metrics_enabled: untyped }

sig/datadog/profiling/component.rbs

@@ -5,7 +5,7 @@ module Datadog
         settings: untyped,
         agent_settings: Datadog::Core::Configuration::AgentSettingsResolver::AgentSettings,
         optional_tracer: Datadog::Tracing::Tracer?,
-      ) -> Datadog::Profiling::Profiler?
+      ) -> [Datadog::Profiling::Profiler?, {profiling_enabled: bool}]
 
       def self.build_thread_context_collector: (
         untyped settings,

spec/datadog/core/configuration/components_spec.rb

@@ -35,6 +35,8 @@
   let(:remote) { instance_double(Datadog::Core::Remote::Component, start: nil, shutdown!: nil) }
   let(:telemetry) { instance_double(Datadog::Core::Telemetry::Client) }
 
+  let(:environment_logger_extra) { { hello: 123, world: '456' } }
+
   include_context 'non-development execution environment'
 
   before do
@@ -70,7 +72,7 @@
         settings: settings,
         agent_settings: agent_settings,
         optional_tracer: tracer,
-      ).and_return(profiler)
+      ).and_return([profiler, environment_logger_extra])
 
       expect(described_class).to receive(:build_runtime_metrics_worker)
         .with(settings)
@@ -1082,7 +1084,7 @@
             settings: settings,
             agent_settings: agent_settings,
             optional_tracer: anything,
-          ).and_return(profiler)
+          ).and_return([profiler, environment_logger_extra])
         end
 
         it do
@@ -1131,6 +1133,15 @@
         end
       end
     end
+
+    it 'calls the EnvironmentLogger' do
+      expect(Datadog::Profiling::Component).to receive(:build_profiler_component)
+        .and_return([nil, environment_logger_extra])
+
+      expect(Datadog::Core::Diagnostics::EnvironmentLogger).to receive(:collect_and_log!).with(environment_logger_extra)
+
+      startup!
+    end
   end
 
   describe '#shutdown!' do

spec/datadog/core/diagnostics/environment_logger_spec.rb

@@ -9,7 +9,7 @@
   subject(:env_logger) { described_class }
 
   before do
-    allow(DateTime).to receive(:now).and_return(DateTime.new(2020))
+    allow(Time).to receive(:now).and_return(Time.new(2020))
 
     # Resets "only-once" execution pattern of `collect_and_log!`
     env_logger.instance_variable_set(:@executed, nil)
@@ -21,6 +21,23 @@
     subject(:collect_and_log!) { env_logger.collect_and_log! }
 
     let(:logger) { instance_double(Datadog::Core::Logger) }
+    let(:expected_logger_result) do
+      {
+        'date' => '2020-01-01T00:00:00Z',
+        'os_name' => (include('x86_64').or include('i686').or include('aarch64').or include('arm')),
+        'version' => DDTrace::VERSION::STRING,
+        'lang' => 'ruby',
+        'lang_version' => match(/[23]\./),
+        'env' => nil,
+        'service' => be_a(String),
+        'dd_version' => nil,
+        'debug' => false,
+        'tags' => nil,
+        'runtime_metrics_enabled' => false,
+        'vm' => be_a(String),
+        'health_metrics_enabled' => false,
+      }
+    end
 
     before do
       allow(env_logger).to receive(:rspec?).and_return(false) # Allow rspec to log for testing purposes
@@ -35,21 +52,7 @@
       collect_and_log!
       expect(logger).to have_received(:info).with start_with('DATADOG CONFIGURATION - CORE') do |msg|
         json = JSON.parse(msg.partition('- CORE -')[2].strip)
-        expect(json).to match(
-          'date' => '2020-01-01T00:00:00+00:00',
-          'os_name' => (include('x86_64').or include('i686').or include('aarch64').or include('arm')),
-          'version' => DDTrace::VERSION::STRING,
-          'lang' => 'ruby',
-          'lang_version' => match(/[23]\./),
-          'env' => nil,
-          'service' => be_a(String),
-          'dd_version' => nil,
-          'debug' => false,
-          'tags' => nil,
-          'runtime_metrics_enabled' => false,
-          'vm' => be_a(String),
-          'health_metrics_enabled' => false,
-        )
+        expect(json).to match(expected_logger_result)
       end
     end
 
@@ -104,6 +107,31 @@
         expect(logger).to have_received(:warn).with start_with('Failed to collect core environment information')
       end
     end
+
+    context 'when extra fields are provided' do
+      let(:extra_fields) { { hello: 123, world: '456' } }
+
+      subject(:collect_and_log!) { env_logger.collect_and_log!(extra_fields) }
+
+      it 'includes the base fields' do
+        collect_and_log!
+        expect(logger).to have_received(:info).with start_with('DATADOG CONFIGURATION - CORE') do |msg|
+          json = JSON.parse(msg.partition('- CORE -')[2].strip)
+          expect(json).to include(expected_logger_result)
+        end
+      end
+
+      it 'includes the extra fields' do
+        collect_and_log!
+        expect(logger).to have_received(:info).with start_with('DATADOG CONFIGURATION - CORE') do |msg|
+          json = JSON.parse(msg.partition('- CORE -')[2].strip)
+          expect(json).to include(
+            'hello' => 123,
+            'world' => '456',
+          )
+        end
+      end
+    end
   end
 
   describe Datadog::Core::Diagnostics::EnvironmentCollector do
@@ -114,7 +142,7 @@
 
       it 'with a default core' do
         is_expected.to match(
-          date: '2020-01-01T00:00:00+00:00',
+          date: '2020-01-01T00:00:00Z',
           os_name: (include('x86_64').or include('i686').or include('aarch64').or include('arm')),
           version: DDTrace::VERSION::STRING,
           lang: 'ruby',

spec/datadog/profiling/component_spec.rb

@@ -23,12 +23,12 @@
     context 'when profiling is not supported' do
       before { allow(Datadog::Profiling).to receive(:supported?).and_return(false) }
 
-      it { is_expected.to be nil }
+      it { is_expected.to eq [nil, { profiling_enabled: false }] }
     end
 
     context 'by default' do
       it 'does not build a profiler' do
-        is_expected.to be nil
+        is_expected.to eq [nil, { profiling_enabled: false }]
       end
     end
 
@@ -38,7 +38,7 @@
       end
 
       it 'does not build a profiler' do
-        is_expected.to be nil
+        is_expected.to eq [nil, { profiling_enabled: false }]
       end
     end
 
@@ -50,6 +50,10 @@
         allow(profiler_setup_task).to receive(:run)
       end
 
+      it 'builds a profiler instance' do
+        expect(build_profiler_component).to match([instance_of(Datadog::Profiling::Profiler), { profiling_enabled: true }])
+      end
+
       context 'when using the new CPU Profiling 2.0 profiler' do
         it 'initializes a ThreadContext collector' do
           allow(Datadog::Profiling::Collectors::CpuAndWallTimeWorker).to receive(:new)