Correlating Ruby Logs and Traces

Trace correlation

In many cases, such as logging, it may be useful to correlate trace IDs to other events or data streams, for easier cross-referencing.

Logging in Rails applications

Automatic injection

For Rails applications using the default logger (ActiveSupport::TaggedLogging), lograge, or semantic_logger, trace ID injection is automatically configured. You need to add a trace remapper to connect the relevant logs with the traces.

Manual injection

To add correlation IDs to your logger, add a log formatter which retrieves the correlation IDs with Datadog::Tracing.correlation, then add them to the message.

To properly correlate with Datadog logging, be sure the following is present in the log message, in order as they appear:

  • dd.env=<ENV>: Where <ENV> is equal to Datadog::Tracing.correlation.env. Omit if no environment is configured.
  • dd.service=<SERVICE>: Where <SERVICE> is equal to Datadog::Tracing.correlation.service. Omit if no default service name is configured.
  • dd.version=<VERSION>: Where <VERSION> is equal to Datadog::Tracing.correlation.version. Omit if no application version is configured.
  • dd.trace_id=<TRACE_ID>: Where <TRACE_ID> is equal to Datadog::Tracing.correlation.trace_id or 0 if no trace is active during logging.
  • dd.span_id=<SPAN_ID>: Where <SPAN_ID> is equal to Datadog::Tracing.correlation.span_id or 0 if no trace is active during logging.

By default, Datadog::Tracing.log_correlation will return dd.env=<ENV> dd.service=<SERVICE> dd.version=<VERSION> dd.trace_id=<TRACE_ID> dd.span_id=<SPAN_ID>.

If a trace is not active and the application environment & version is not configured, it will return dd.service= dd.trace_id=0 dd.span_id=0.

An example of this in practice:

require 'ddtrace'
require 'logger'

Datadog.configure do |c|
  c.env = 'production'
  c.service = 'billing-api'
  c.version = '2.5.17'
end

logger = Logger.new(STDOUT)
logger.progname = 'my_app'
logger.formatter  = proc do |severity, datetime, progname, msg|
  "[#{datetime}][#{progname}][#{severity}][#{Datadog::Tracing.log_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.env=production dd.service=billing-api dd.version=2.5.17 dd.trace_id=0 dd.span_id=0] This is an untraced operation.

# When a trace is active
Datadog::Tracing.trace('my.operation') { logger.warn('This is a traced operation.') }
# [2019-01-16 18:38:41 +0000][my_app][WARN][dd.env=production dd.service=billing-api dd.version=2.5.17 dd.trace_id=8545847825299552251 dd.span_id=3711755234730770098] This is a traced operation.

Further Reading

Additional helpful documentation, links, and articles:

Correlate request logs with traces automaticallyBLOG more more Ease troubleshooting with cross product correlation.GUIDE more more