Description
Current behaviour
I have a sinatra app. By default, Sinatra app is a rack application and rack comes with its Rack::CommonLogger. when I configure logging with Rack::CommonLogger, I get these logs in DD:
127.0.0.1 - - [16/May/2024:09:52:44 +0200] "GET / HTTP/1.1" 200 - 0.0332
127.0.0.1 - - [16/May/2024:09:52:49 +0200] "GET / HTTP/1.1" 200 - 0.0295
I enabled tracing for my app. I want to correlate these logs with traces, as currently they're not correlated at all. As far as I understand, these logs must have span_id and trace_id printed out. At least that's how it works for my other applications, in Rails etc. To do so, I've created my own logger that appends Datadog::Tracing.log_correlation to every message Rack::CommonLogger wanted to log. (class MyLogger in config.ru file)
Problem:
When trying to print Datadog::Tracing.log_correlation along with the rest of the log, the trace_id and span_id are always 0(in other words, not set). They are not set even if I pass X_DATADOG_TRACE_ID in headers. What I noticed is that if I turn off tracing, then trace_id is correctly inherited from the headers. That looks like a bug.
I can't turn off tracing, because then the app is not traced, so I'm losing a lot of info about my sidekiqs, redises, etc. But with tracing enabled, I can't correlate logs, as trace_id is always 0.
Reproduction steps along with DD setup codes are below.
Expected behaviour
My expectation would be that the trace_id is set and I can correlate logs with traces. If I am doing something wrong here, I'd happy to hear suggestions how to correlate logs with traces correctly.
Steps to reproduce
config.ru file - basic minimal setup
# frozen_string_literal: true
require 'bundler/inline'
if ENV["INSTALL_GEMS"]
gemfile(true) do
source 'https://rubygems.org'
gem "rack"
gem 'ddtrace', "1.23.0"
gem 'sinatra'
end
else
require "ddtrace"
require "sinatra"
Datadog.configure do |c|
c.tracing.enabled = ENV['TRACING_FLAG'] == 'true'
c.tracing.partial_flush.enabled = true
c.version = "123"
c.tracing.instrument :redis, service_name: 'ourApp-redis'
c.tracing.instrument :sequel, service_name: 'ourApp-sequel'
c.tracing.instrument :sidekiq, service_name: 'ourApp-sidekiq'
c.tracing.instrument :sinatra, service_name: 'ourApp-sinatra'
end
class MyLogger < Logger
# Overrides logger's << method, which is used in Rack::CommonLogger - to output the dd.trace along with the original 'msg'.
def <<(msg)
msg.gsub!("\n", '')
msg += " #{Datadog::Tracing.log_correlation}\n"
super(msg)
end
end
module Api
class Base < Sinatra::Application
get '/' do
end
end
end
configure do
logger = MyLogger.new("./sinatra.log")
use Rack::CommonLogger, logger
end
run Api::Base
end
reproduce_script.sh
#!/bin/sh
# Prepare app - install gems and rackup
INSTALL_GEMS=true ruby config.ru
gem install rackup
# RUN WITH c.tracing.enabled = true
TRACING_FLAG=true rackup config.ru &
PID=$!; sleep 5
curl -X GET 127.0.0.1:9292/ --header "X_DATADOG_TRACE_ID: 999" --header "X_DATADOG_PARENT_ID: 998"
kill "$PID" # Kill the process with TRACING_FLAG=TRUE
# RUN WITH c.tracing.enabled = false
TRACING_FLAG=false rackup config.ru &
PID=$! ; sleep 5
curl -X GET 127.0.0.1:9292/ --header "X_DATADOG_TRACE_ID: 999" --header "X_DATADOG_PARENT_ID: 998"
kill "$PID"
echo "\n \n"
echo "Now, look at sinatra.log:"
echo "The first request has c.tracing.enabled = true but it doesnt have any trace(trace_id=0)"
echo "The second request has c.tracing.enabled = false but has correct trace_id from the header"
cat sinatra.log
echo "\nWhy is the trace_id not forwarded in the headers when c.tracing.enabled = true?"
- Download both files.
- execute
chmod +x reproduce_script.sh - execute
./reproduce_script.sh - Look at sinatra.log
Here is the outcome of the script:
As you can see, with tracing.enabled = true dd.trace_ids are zeros, even if I try to set their values by passing headers in the curl command
(curl -X GET 127.0.0.1:9292/ --header "X_DATADOG_TRACE_ID: 999" --header "X_DATADOG_PARENT_ID: 998")
Environment
- datadog version: 1.23.0
- Configuration block (
Datadog.configure ...):
Datadog.configure do |c|
c.tracing.enabled = ENV['TRACING_FLAG'] == 'true'
c.tracing.partial_flush.enabled = true
c.version = "123"
c.tracing.instrument :redis, service_name: 'ourApp-redis'
c.tracing.instrument :sequel, service_name: 'ourApp-sequel'
c.tracing.instrument :sidekiq, service_name: 'ourApp-sidekiq'
c.tracing.instrument :sinatra, service_name: 'ourApp-sinatra'
end
- Ruby version: 3.3.1
- Relevant library versions:
✗ gem info rack | grep rack
rack (3.0.11)
✗ gem info ddtrace | grep ddtrace
ddtrace (1.23.0)
✗ gem info sinatra | grep sinatra
sinatra (4.0.0)
This error is kinda connected to #2666
