Sidekiq perform_in and perform_at don't produce process spans with child propagation_style

[patatepartie]

Description of the bug

Using Sidekiq with Sidekiq's instrumentation propagation_style set to :child, when delaying the execution of a worker using perform_in(sec, params) or perform_at(timestamp, params), a span is produced for the enqueueing (send) but no span is ever produced for the execution itself (process).

If propagation_style is not set (it defaults to link), the span for process will be produced.

Executing the worker asynchronously, with perform_async(params), works correctly regardless of the value of propagation_style.

Share details about your runtime

Operating system details: Linux, Debian 10.10 (in docker) RUBY_ENGINE: "ruby" RUBY_VERSION: "3.0.1" RUBY_DESCRIPTION: "ruby 3.0.1p64 (2021-04-05 revision 0fb782ee38) [x86_64-linux]"

Share a simplified reproduction if possible

docker run -ti --rm -w /perform_in_bug_report ruby:3.0.1-buster bash
gem install rails
rails new --skip-git --skip-keeps --skip-action-mailer --skip-action-mailbox --skip-action-text --skip-active-record --skip-active-job --skip-active-storage --skip-action-cable --skip-asset-pipeline --skip-javascript --skip-hotwire --skip-jbuilder --skip-test --skip-system-test --skip-bootsnap --skip-bundle .
bundle add opentelemetry-api opentelemetry-sdk opentelemetry-instrumentation-sidekiq sidekiq
apt-get update && apt-get install -y vim redis
mkdir app/workers

# config/initializers/opentelemetry.rb
span_processor = OpenTelemetry::SDK::Trace::Export::SimpleSpanProcessor.new(
  OpenTelemetry::SDK::Trace::Export::ConsoleSpanExporter.new
)

OpenTelemetry::SDK.configure do |c|
  c.add_span_processor(span_processor)
  c.use 'OpenTelemetry::Instrumentation::Sidekiq', {
    propagation_style: :child,
    span_naming: :job_class
  }
end

# app/workers/example_worker.rb
class ExampleWorker
  include Sidekiq::Worker

  sidekiq_options retry: 0

  def perform(id)
    OpenTelemetry::Trace.current_span.set_attribute('worker.parameters.id', id)
  end
end

redis-server &
bundle exec sidekiq &

bin/rails c
> ExampleWorker.perform_async(1)
> ExampleWorker.perform_in(1.second, 1)

The perform_async call will show a span for ExampleWorker send and another for ExampleWorker process, while the perform_in call will only show a span for ExampleWorker send.

[patatepartie]

In the end, I was able to make it work, to a satisfying level, by configuring trace_poller_enqueue: true. Delayed executions and also retried jobs (which I discovered later had the same issue), will now get traces.

Those will be children of Sidekiq::Scheduled::Poller#enqueue and the process spans will not be correlated to the original send spans, unfortunately, but that's good enough for my case.

I think the documentation of the library is lacking. There is no description of what the options do or how they interact with each other, and we have to dig into the code of both the instrumentation and instrumented libraries, to understand what's going on.

[plantfansam]

Thanks for the report and the feedback on docs @patatepartie! I have made an issue to improve the docs for sidekiq instrumentation.

[patatepartie]

Thank you @plantfansam. Let me know if there's anything I can do to help.

[mbm-c]

Those will be children of Sidekiq::Scheduled::Poller#enqueue and the process spans will not be correlated to the original send spans, unfortunately, but that's good enough for my case.

Is there any way to correlate spans with original send spans?