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

Easier Rails log correlation #673

Merged
merged 2 commits into from
Jan 17, 2019
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
40 changes: 33 additions & 7 deletions docs/GettingStarted.md
Original file line number Diff line number Diff line change
Expand Up @@ -1627,14 +1627,16 @@ correlation.trace_id # => 0
correlation.span_id # => 0
```

#### For logging
#### For logging in Ruby applications

To add correlation IDs to your logger, simply add a log formatter which retrieve the correlation IDs via `Datadog.tracer.active_correlation`, then add them to the message.
To add correlation IDs to your logger, add a log formatter which retrieves the correlation IDs with `Datadog.tracer.active_correlation`, then add them to the message.

To properly correlate with Datadog logging, be sure the following is present:

- `dd.trace_id=<trace_id>`: Where `<trace_id>` is `Datadog.tracer.active_correlation.trace_id`. `0` if no trace active.
- `dd.span_id=<span_id>`: Where `<span_id>` is `Datadog.tracer.active_correlation.span_id`. `0` if no trace active.
- `dd.trace_id=<TRACE_ID>`: Where `<TRACE_ID>` is equal to `Datadog.tracer.active_correlation.trace_id` or `0` if no trace is active.
- `dd.span_id=<SPAN_ID>`: Where `<SPAN_ID>` is equal to `Datadog.tracer.active_correlation.span_id` or `0` if no trace is active.

By default, `Datadog::Correlation::Identifier#to_s` will return `dd.trace_id=<TRACE_ID> dd.span_id=<SPAN_ID>`.

An example of this in practice:

Expand All @@ -1645,10 +1647,34 @@ require 'logger'
logger = Logger.new(STDOUT)
logger.progname = 'my_app'
logger.formatter = proc do |severity, datetime, progname, msg|
# Returns Datadog::Correlation::Identifier
ids = Datadog.tracer.active_correlation
"[#{datetime}][#{progname}][#{severity}][dd.trace_id=#{ids.trace_id} dd.span_id=#{ids.span_id}] #{msg}\n"
"[#{datetime}][#{progname}][#{severity}][#{Datadog.tracer.active_correlation}] #{msg}\n"
end

# When no trace is active
logger.warn('This is an untraced operation.')
# [2019-01-16 18:38:41 +0000][my_app][WARN][dd.trace_id=0 dd.span_id=0] This is an untraced operation.

# When a trace is active
Datadog.tracer.trace('my.operation') { logger.warn('This is a traced operation.') }
# [2019-01-16 18:38:41 +0000][my_app][WARN][dd.trace_id=8545847825299552251 dd.span_id=3711755234730770098] This is a traced operation.
```

#### For logging in Rails applications

Rails applications which are configured with a `ActiveSupport::TaggedLogging` logger can append correlation IDs as tags to log output. The default Rails logger implements this tagged logging, making it easier to add correlation tags.

In your Rails environment configuration file, add the following:

```ruby
Rails.application.configure do
config.log_tags = [proc { Datadog.tracer.active_correlation.to_s }]
end

# Web requests will produce:
# [dd.trace_id=7110975754844687674 dd.span_id=7518426836986654206] Started GET "/articles" for 172.22.0.1 at 2019-01-16 18:50:57 +0000
# [dd.trace_id=7110975754844687674 dd.span_id=7518426836986654206] Processing by ArticlesController#index as */*
# [dd.trace_id=7110975754844687674 dd.span_id=7518426836986654206] Article Load (0.5ms) SELECT "articles".* FROM "articles"
# [dd.trace_id=7110975754844687674 dd.span_id=7518426836986654206] Completed 200 OK in 7ms (Views: 5.5ms | ActiveRecord: 0.5ms)
```

### OpenTracing
Expand Down
4 changes: 4 additions & 0 deletions lib/ddtrace/correlation.rb
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,10 @@ def initialize(*args)
self.trace_id = trace_id || 0
self.span_id = span_id || 0
end

def to_s
"dd.trace_id=#{trace_id} dd.span_id=#{span_id}"
end
end
end.freeze

Expand Down
2 changes: 2 additions & 0 deletions spec/ddtrace/correlation_spec.rb
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@
is_expected.to be_a_kind_of(Datadog::Correlation::Identifier)
expect(correlation_ids.trace_id).to be 0
expect(correlation_ids.span_id).to be 0
expect(correlation_ids.to_s).to eq('dd.trace_id=0 dd.span_id=0')
end
end

Expand All @@ -33,6 +34,7 @@
is_expected.to be_a_kind_of(Datadog::Correlation::Identifier)
expect(correlation_ids.trace_id).to eq(trace_id)
expect(correlation_ids.span_id).to eq(span_id)
expect(correlation_ids.to_s).to eq("dd.trace_id=#{trace_id} dd.span_id=#{span_id}")
end
end
end
Expand Down