Sinatra - missing trace_id when trying to correlate logs with traces

[mwoskowicz]

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?"

1. Download both files.
2. executechmod +x reproduce_script.sh
3. execute ./reproduce_script.sh
4. 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

[mwoskowicz]

Hey, did anyone have any chance to look at this? I hope the reproduction script is helpful.

[delner]

Hi @mwoskowicz! Thanks for sharing (and the bump.)

I've asked our engineering team to take a look, see if we can better understand the issue. Someone should check in soon; if not, do feel free to bump this again.

(Also, really awesome that you included all that detail above! That will be super helpful :) )