Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add rails automatic log injection with semantic logger via patching #1566

Merged
merged 16 commits into from
Jul 8, 2021

Conversation

ericmustin
Copy link
Contributor

This PR adds patching of the semantic_logger gem as part of the rails automatic log injection functionality. As semantic_logger is among the most popular ruby logging libraries, it makes sense to try to support log/trace correlation here instead of forcing users to rely on doing this manually.

Still have to test some behavior as, afaik, while Datadog automatically knows to look for named_tags.dd.(trace|span)_id as the correct key for trace/log correlation, this feature (named_tags.* as a reserved attribute, may not apply to all organisations since they may have created their reserved attributes before this field was added as a default field. If that's the case we'll need to update the documentation here (since we can't removed the named_tags portion of the logs), with some screenshots/step-by-step instructions for how to update the log ingestion pipelines/mapping for this field.

@ericmustin ericmustin requested a review from a team June 24, 2021 19:11
@@ -67,7 +68,7 @@ def add_logger(app)
# Instead, we patch Lograge `custom_options` internals directly
# as part of Rails framework patching
# and just flag off the warning log here.
should_warn = false if app.config.respond_to?(:lograge)
should_warn = false if app.config.respond_to?(:lograge) || defined?(::SemanticLogger)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not too familiar with this line, so I read the comment above and it refers to lograre and custom_options.

How does this apply to sematic logger?

Or I guess a better request: do you think it makes sense to update the comment above to explain why this is needed for semantic logger as well?

Rakefile Outdated
@@ -39,7 +39,8 @@ namespace :spec do

RSpec::Core::RakeTask.new(:rails) do |t, args|
t.pattern = 'spec/ddtrace/contrib/rails/**/*_spec.rb'
t.exclude_pattern = 'spec/ddtrace/contrib/rails/**/*{active_job,disable_env,redis_cache,auto_instrument}*_spec.rb'
t.exclude_pattern = 'spec/ddtrace/contrib/rails/**/*{active_job,disable_env,redis_cache,auto_instrument,semanti'\
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You might want to split this line at a word separator, instead of the middle of semantic :)

@@ -68,6 +69,14 @@ namespace :spec do
t.rspec_opts = args.to_a.join(' ')
end

# rails_semantic_logger is the dog at the dog park that doesnt play nicely with other
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like this comment

Comment on lines +12 to +15
# v4 had a migration to `named_tags` instead of `payload`
# and has been out for almost 5 years at this point
# it's probably reasonable to nudge users to using modern ruby libs
MINIMUM_VERSION = Gem::Version.new('4.0.0')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

Comment on lines 31 to 33
# We should probably just never auto enabled log injection as part of auto instrumentation
# TODO: abstract out the log injection related instrumentation into it's own module so we dont
# keep having to do these funky workarounds
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we have such cases today in Ruby, but there might be a well-behaved logging library that we can always safely patch in order to inject logs correlation safely.

I understand that this is not the case here, but I don't think We should probably just never auto enabled log injection as part of auto instrumentation in general.

@@ -32,6 +33,7 @@
end

let(:initialize_block) do
$stdout.sync = true
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you know why this is needed?

I ask because this is a global change that will outlive this test execution, and has impact on other subsequent tests.

Comment on lines 45 to 46
if Rails.version >= '4.0'
context 'with Semantic Logger' do
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can clean this up a bit by using the if: argument for RSpec:

it 'does not error on reporting health metrics', if: Datadog::Statsd::VERSION < '5.0.0' do

# force flush
SemanticLogger.flush

expect(logs).to include(spans[0].trace_id.to_s)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it makes sense to cover all fields, as this is brand new code introduced by this PR:

              dd: {
                trace_id: correlation.trace_id.to_s,
                span_id: correlation.span_id.to_s,
                env: correlation.env.to_s,
                service: correlation.service.to_s,
                version: correlation.version.to_s
              },
              ddsource: ['ruby']

@ericmustin ericmustin changed the title [wip] Add rails automatic log injection with semantic logger via patching Add rails automatic log injection with semantic logger via patching Jul 6, 2021
Copy link
Member

@marcotc marcotc left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:shipit:!

@codecov-commenter
Copy link

Codecov Report

Merging #1566 (913f40e) into master (b196dc3) will increase coverage by 0.00%.
The diff coverage is 100.00%.

Impacted file tree graph

@@           Coverage Diff            @@
##           master    #1566    +/-   ##
========================================
  Coverage   98.24%   98.25%            
========================================
  Files         886      894     +8     
  Lines       42687    42878   +191     
========================================
+ Hits        41939    42130   +191     
  Misses        748      748            
Impacted Files Coverage Δ
lib/ddtrace.rb 100.00% <100.00%> (ø)
lib/ddtrace/contrib/rails/framework.rb 100.00% <100.00%> (ø)
lib/ddtrace/contrib/rails/patcher.rb 100.00% <100.00%> (ø)
.../contrib/semantic_logger/configuration/settings.rb 100.00% <100.00%> (ø)
lib/ddtrace/contrib/semantic_logger/ext.rb 100.00% <100.00%> (ø)
...ddtrace/contrib/semantic_logger/instrumentation.rb 100.00% <100.00%> (ø)
lib/ddtrace/contrib/semantic_logger/integration.rb 100.00% <100.00%> (ø)
lib/ddtrace/contrib/semantic_logger/patcher.rb 100.00% <100.00%> (ø)
...ace/contrib/rails/rails_log_auto_injection_spec.rb 100.00% <100.00%> (ø)
...rails/rails_semantic_logger_auto_injection_spec.rb 100.00% <100.00%> (ø)
... and 12 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update b196dc3...913f40e. Read the comment docs.

@ericmustin ericmustin merged commit edb8b89 into master Jul 8, 2021
@ericmustin ericmustin deleted the add_semantic_logger_via_patching branch July 8, 2021 23:45
@github-actions github-actions bot added this to the 0.51.0 milestone Jul 8, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants