Skip to content

Commit

Permalink
Merge pull request #1536 from DataDog/ivoanjo/remove-puts-logging-fro…
Browse files Browse the repository at this point in the history
…m-profiler

[PROF-3430] Get rid of puts logging during profiler initialization
  • Loading branch information
ivoanjo authored Jun 2, 2021
2 parents c3e56e0 + bb1fd91 commit 0be885d
Show file tree
Hide file tree
Showing 3 changed files with 35 additions and 34 deletions.
2 changes: 2 additions & 0 deletions lib/ddtrace/profiling.rb
Original file line number Diff line number Diff line change
Expand Up @@ -66,6 +66,8 @@ def self.protobuf_loaded_successfully?
require 'google/protobuf'
@protobuf_loaded = true
rescue LoadError => e
# NOTE: We use Kernel#warn here because this code gets run BEFORE Datadog.logger is actually set up.
# In the future it'd be nice to shuffle the logger startup to happen first to avoid this special case.
Kernel.warn(
"[DDTRACE] Error while loading google-protobuf gem. Cause: '#{e.message}' Location: '#{e.backtrace.first}'. " \
'This can happen when google-protobuf is missing its native components. ' \
Expand Down
25 changes: 12 additions & 13 deletions lib/ddtrace/profiling/tasks/setup.rb
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,7 @@ def run
activate_cpu_extensions
setup_at_fork_hooks
rescue StandardError, ScriptError => e
log "[DDTRACE] Main extensions unavailable. Cause: #{e.message} Location: #{e.backtrace.first}"
Datadog.logger.warn { "Profiler extensions unavailable. Cause: #{e.message} Location: #{e.backtrace.first}" }
end
end
end
Expand All @@ -29,23 +29,27 @@ def activate_forking_extensions
if Ext::Forking.supported?
Ext::Forking.apply!
elsif Datadog.configuration.profiling.enabled
# Log warning if profiling was supposed to be activated.
log '[DDTRACE] Forking extensions skipped; forking not supported.'
Datadog.logger.debug('Profiler forking extensions skipped; forking not supported.')
end
rescue StandardError, ScriptError => e
log "[DDTRACE] Forking extensions unavailable. Cause: #{e.message} Location: #{e.backtrace.first}"
Datadog.logger.warn do
"Profiler forking extensions unavailable. Cause: #{e.message} Location: #{e.backtrace.first}"
end
end

def activate_cpu_extensions
if Ext::CPU.supported?
Ext::CPU.apply!
elsif Datadog.configuration.profiling.enabled
# Log warning if profiling was supposed to be activated.
log '[DDTRACE] CPU time profiling skipped because native CPU time is not supported: ' \
Datadog.logger.info do
'CPU time profiling skipped because native CPU time is not supported: ' \
"#{Ext::CPU.unsupported_reason}. Profiles containing Wall time will still be reported."
end
end
rescue StandardError, ScriptError => e
log "[DDTRACE] CPU profiling unavailable. Cause: #{e.message} Location: #{e.backtrace.first}"
Datadog.logger.warn do
"Profiler CPU profiling extensions unavailable. Cause: #{e.message} Location: #{e.backtrace.first}"
end
end

def setup_at_fork_hooks
Expand All @@ -62,16 +66,11 @@ def setup_at_fork_hooks
# Restart profiler, if enabled
Datadog.profiler.start if Datadog.profiler
rescue StandardError => e
log "[DDTRACE] Error during post-fork hooks. Cause: #{e.message} Location: #{e.backtrace.first}"
Datadog.logger.warn { "Error during post-fork hooks. Cause: #{e.message} Location: #{e.backtrace.first}" }
end
end
end
end

def log(message)
# Print to STDOUT for now because logging may not be setup yet...
puts message
end
end
end
end
Expand Down
42 changes: 21 additions & 21 deletions spec/ddtrace/profiling/tasks/setup_spec.rb
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,7 @@
context 'and succeeds' do
it 'applies forking extensions' do
expect(Datadog::Profiling::Ext::Forking).to receive(:apply!)
expect($stdout).to_not receive(:puts)
expect(Datadog.logger).to_not receive(:warn)
activate_forking_extensions
end
end
Expand All @@ -60,9 +60,9 @@
.and_raise(StandardError)
end

it 'displays a warning to $stdout' do
expect($stdout).to receive(:puts) do |message|
expect(message).to include('Forking extensions unavailable')
it 'logs a warning' do
expect(Datadog.logger).to receive(:warn) do |&message|
expect(message.call).to include('forking extensions unavailable')
end

activate_forking_extensions
Expand All @@ -86,8 +86,8 @@

it 'skips forking extensions with warning' do
expect(Datadog::Profiling::Ext::Forking).to_not receive(:apply!)
expect($stdout).to receive(:puts) do |message|
expect(message).to include('Forking extensions skipped')
expect(Datadog.logger).to receive(:debug) do |message|
expect(message).to include('forking extensions skipped')
end

activate_forking_extensions
Expand All @@ -103,7 +103,7 @@

it 'skips forking extensions without warning' do
expect(Datadog::Profiling::Ext::Forking).to_not receive(:apply!)
expect($stdout).to_not receive(:puts)
expect(Datadog.logger).to_not receive(:debug)
activate_forking_extensions
end
end
Expand All @@ -123,7 +123,7 @@
context 'and succeeds' do
it 'applies CPU extensions' do
expect(Datadog::Profiling::Ext::CPU).to receive(:apply!)
expect($stdout).to_not receive(:puts)
expect(Datadog.logger).to_not receive(:warn)
activate_cpu_extensions
end
end
Expand All @@ -135,9 +135,9 @@
.and_raise(StandardError)
end

it 'displays a warning to $stdout' do
expect($stdout).to receive(:puts) do |message|
expect(message).to include('CPU profiling unavailable')
it 'logs a warning' do
expect(Datadog.logger).to receive(:warn) do |&message|
expect(message.call).to include('CPU profiling extensions unavailable')
end

activate_cpu_extensions
Expand All @@ -159,10 +159,10 @@
.and_return(true)
end

it 'skips CPU extensions with warning' do
it 'skips CPU extensions with an info message' do
expect(Datadog::Profiling::Ext::CPU).to_not receive(:apply!)
expect($stdout).to receive(:puts) do |message|
expect(message).to include('CPU time profiling skipped')
expect(Datadog.logger).to receive(:info) do |&message|
expect(message.call).to include('CPU time profiling skipped')
end

activate_cpu_extensions
Expand All @@ -178,7 +178,7 @@

it 'skips CPU extensions without warning' do
expect(Datadog::Profiling::Ext::CPU).to_not receive(:apply!)
expect($stdout).to_not receive(:puts)
expect(Datadog.logger).to_not receive(:warn)
activate_cpu_extensions
end
end
Expand Down Expand Up @@ -224,16 +224,16 @@
context 'when there is an issue starting the profiler' do
before do
expect(Datadog).to receive(:profiler).and_raise('Dummy exception')
allow($stdout).to receive(:puts) # Silence logging during tests
allow(Datadog.logger).to receive(:warn) # Silence logging during tests
end

it 'does not raise any error' do
at_fork_hook.call
end

it 'logs an exception' do
expect($stdout).to receive(:puts) do |message|
expect(message).to include('Dummy exception')
expect(Datadog.logger).to receive(:warn) do |&message|
expect(message.call).to include('Dummy exception')
end

at_fork_hook.call
Expand All @@ -253,16 +253,16 @@
without_partial_double_verification do
expect(Thread.current).to receive(:update_native_ids).and_raise('Dummy exception')
end
allow($stdout).to receive(:puts) # Silence logging during tests
allow(Datadog.logger).to receive(:warn) # Silence logging during tests
end

it 'does not raise any error' do
at_fork_hook.call
end

it 'logs an exception' do
expect($stdout).to receive(:puts) do |message|
expect(message).to include('Dummy exception')
expect(Datadog.logger).to receive(:warn) do |&message|
expect(message.call).to include('Dummy exception')
end

at_fork_hook.call
Expand Down

0 comments on commit 0be885d

Please sign in to comment.