Sidekiq ECS based logging - Trace/Log Correlation

Elastic Observability APM
1

Hi :wave: :slight_smile:

Is there some documentation about how to setup Trace - Log correlation for Sidekiq based background jobs. For the Rails API server we are using ECS Logger with following setup:

# config/environments/production.rb

# Prepend all log lines with the following tags.
config.log_tags = [:request_id, proc { ElasticAPM.log_ids }]

config.logger = EcsLogging::Logger.new($stdout)

I did take a look at ecs-logging-ruby/logger.rb at master · elastic/ecs-logging-ruby · GitHub and thought just setting the Sidekiq.logger to the ECS logger should be enough, but that does not seem to work out.

# config/initializers/sidekiq.rb

Sidekiq.configure_server do |config|
  # https://github.com/mperham/sidekiq/wiki/Reliability
  config.super_fetch!
  config.reliable_scheduler!

  log_level                        = ENV.fetch("LOG_LEVEL") { "debug" }
  Sidekiq.logger                   = EcsLogging::Logger.new($stdout)
  Sidekiq.logger.level             = Logger.const_get(log_level.upcase)
  Rails.logger                     = Sidekiq.logger
  ChatbotService::Logging.logger   = Sidekiq.logger
  ActionCable.server.config.logger = Sidekiq.logger
  ActiveRecord::Base.logger        = Sidekiq.logger
end

Even though ElasticAPM is enabled, the logs from background jobs still do not contain transaction.id, trace.id and span.id.

{"@timestamp":"2021-09-02T08:37:20.755Z","log.level":"INFO","message":"start","ecs.version":"1.4.0"}
{"@timestamp":"2021-09-02T08:37:20.913Z","log.level":"INFO","message":"Syncing intent Setup_help with uid: xxx","ecs.version":"1.4.0"}
{"@timestamp":"2021-09-02T08:37:21.710Z","log.level":"INFO","message":"done","ecs.version":"1.4.0"}

With the normal Sidekiq logger the logs contain way more useful information as well (jid, tid, pid, which worker class is used):

2021-09-02T08:54:20.289Z pid=1 tid=3tmh class=IntentFetchWorker jid=dc7d9e39caec48590fe19c23 INFO: start
2021-09-02T08:54:20.299Z pid=1 tid=3tmh class=IntentFetchWorker jid=dc7d9e39caec48590fe19c23 INFO: Syncing intent Setup_help with uid: xxx
2021-09-02T08:54:20.977Z pid=1 tid=3tmh class=IntentFetchWorker jid=dc7d9e39caec48590fe19c23 elapsed=0.688 INFO: done

If its a desired feature to use ECS formatting for background jobs I could try to invest some time to implement a sidekiq specific formatter/logger, similar to Sidekiq-Logging-JSON/json.rb at master · Springest/Sidekiq-Logging-JSON · GitHub which still adheres to ECS format (at least where possible), also I would need to understand why the current ECS logger does not append tracing related ids altough Elastic APM is enabled.

1 Like
2

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.