ActiveJob[+SolidQueue?] job's code log stream broken (with hacky workaround)

[qd3v]

trafficstars

Environment

Provide at least:

• Ruby Version: 3.3.4
• rails (7.2.1)
• semantic_logger (4.16.0)
• rails_semantic_logger (4.17.0)
• solid_queue (0.6.1)

Rails configuration:

    config.active_job.queue_adapter = :solid_queue

    config.log_level                    = ENV![:APP_LOG_LEVEL]
    config.rails_semantic_logger.format = :default

    if ENV![:APP_LOG_TO_STDOUT]
      $stdout.sync = true

      config.rails_semantic_logger.format            = :color
      config.rails_semantic_logger.add_file_appender = false
      config.semantic_logger.add_appender(io: $stdout, formatter: config.rails_semantic_logger.format)
    end

    config.rails_semantic_logger.semantic     = true
    config.rails_semantic_logger.started      = true
    config.rails_semantic_logger.processing   = false
    config.rails_semantic_logger.rendered     = false
    config.rails_semantic_logger.quiet_assets = true

Expected Behavior

Log to $stdout

Actual Behavior

I've been using SM for many years, and that's the first time I have issues, and I think they come from SolidQueue thread model or something. Ok, the problem is SM prints only part of logs: from SolidQueue (supervisor?) but not from the job processing code.

My job class:

module Jobs
  # Base is an ActiveJob::Base subclass, nothing fancy
  class GenerateIdeas < Base
    queue_as :default

    def perform(category_id)
      puts logger.class.name # SemanticLogger::Logger <- ok here

      # Returns  <SemanticLogger::Appender::IO:0x000000012d18d2a0
      # I believe that is the configured one
      puts SemanticLogger.appenders.inspect
      puts SemanticLogger.appenders.count # 1
      logger.fatal("STARTING JOB") # nothing
    end
  end
end

Log dump:

2024-09-02 13:37:28.365143 D [7188:18540] (0.084ms) ActiveRecord -- TRANSACTION -- { :sql => "BEGIN", :allocations => 6, :cached => nil }
2024-09-02 13:37:28.369738 D [7188:18540] (6.058ms) ActiveRecord -- SolidQueue::Process Create -- { :sql => "INSERT INTO \"solid_queue_processes\" (\"kind\", \"last_heartbeat_at\", \"supervisor_id\", \"pid\", \"hostname\", \"metadata\", \"created_at\", \"name\") VALUES ($1, $2, $3, $4, $5, $6, $7, $8) RETURNING \"id\"", :binds => { :kind => "Supervisor(fork)", :last_heartbeat_at => "2024-09-02 09:37:28.296550", :supervisor_id => nil, :pid => 7188, :hostname => "ws.q", :metadata => nil, :created_at => "2024-09-02 09:37:28.360878", :name => "supervisor(fork)-71a95d781f6914449836" }, :allocations => 415, :cached => nil }
2024-09-02 13:37:28.372734 D [7188:18540] (1.182ms) ActiveRecord -- TRANSACTION -- { :sql => "COMMIT", :allocations => 400, :cached => nil }
2024-09-02 13:37:28.374567 I [7188:18540] JOBS -- SolidQueue-0.6.1 Register Supervisor(fork) (76.3ms)  pid: 7188, hostname: "ws.q", process_id: 67, name: "supervisor(fork)-71a95d781f6914449836"
2024-09-02 13:37:28.396726 D [7188:18540] (0.628ms) ActiveRecord -- SolidQueue::ClaimedExecution Load -- { :sql => "SELECT \"solid_queue_claimed_executions\".* FROM \"solid_queue_claimed_executions\" LEFT OUTER JOIN \"solid_queue_processes\" ON \"solid_queue_processes\".\"id\" = \"solid_queue_claimed_executions\".\"process_id\" WHERE \"solid_queue_processes\".\"id\" IS NULL", :allocations => 7, :cached => nil }
2024-09-02 13:37:28.399934 W [7188:18540] JOBS -- SolidQueue-0.6.1 Fail claimed jobs (4.3ms)  job_ids: [], process_ids: []
2024-09-02 13:37:28.402211 I [7188:18540] JOBS -- SolidQueue-0.6.1 Started Supervisor(fork) (127.7ms)  pid: 7188, hostname: "ws.q", process_id: 67, name: "supervisor(fork)-71a95d781f6914449836"
2024-09-02 13:37:28.438936 D [7188:io-worker-1] (1.098ms) ActiveRecord -- SolidQueue::Process Load -- { :sql => "SELECT \"solid_queue_processes\".* FROM \"solid_queue_processes\" WHERE \"solid_queue_processes\".\"last_heartbeat_at\" <= $1 ORDER BY \"solid_queue_processes\".\"id\" ASC LIMIT $2 FOR UPDATE SKIP LOCKED", :binds => { :last_heartbeat_at => "2024-09-02 09:32:28.425749", :limit => 50 }, :allocations => 10, :cached => nil }
2024-09-02 13:37:28.439706 D [7188:io-worker-1] JOBS -- SolidQueue-0.6.1 Prune dead processes (14.0ms)  size: 0
2024-09-02 13:38:28.381268 D [7188:io-worker-1] (0.109ms) ActiveRecord -- TRANSACTION -- { :sql => "BEGIN", :allocations => 5, :cached => nil }
2024-09-02 13:38:28.381692 D [7188:io-worker-1] (0.569ms) ActiveRecord -- SolidQueue::Process Update -- { :sql => "UPDATE \"solid_queue_processes\" SET \"last_heartbeat_at\" = $1 WHERE \"solid_queue_processes\".\"id\" = $2", :binds => { :last_heartbeat_at => "2024-09-02 09:38:28.380277", :id => 67 }, :allocations => 178, :cached => nil }
2024-09-02 13:38:28.385207 D [7188:io-worker-1] (3.314ms) ActiveRecord -- TRANSACTION -- { :sql => "COMMIT", :allocations => 220, :cached => nil }

This code works, but that is not what we all want :)

def perform(category_id)
  logger = Logger.new($stdout)
  logger.fatal("STARTING JOB") # ok
end

After some time of double-checking everything I found workaround: an attempt to re-add $stdout appender resets something, and fix logging:

module Jobs
  class Base < ActiveJob::Base

    before_perform :fix_logging_v4_17

    def fix_logging_v4_17
      # This logs error (attempt to add another console logger) but forces SM to work
      SemanticLogger.add_appender(io: $stdout, formatter: :color)
    end
  end
end

The log message about this dirty hack appears, but at least this works :)

There's even worse hack: call SemanticLogger#sync!.

Thank you for your work!

[kristoph]

Any addition insights to resolve this issue at all?

[reidmorrison]

Does someone in the community that uses Active Job have a solution they want to submit as a PR? Or, even just submit a PR with a failing test for the above scenario?

[bytnar]

2 small cents from me. I'm not sure it is fully on SemanticLogger side. After I switched for test purposes to Sidekiq from SolidQueue, I'm able to see log entries. So maybe it is SolidQueue that passes logger object down to job (thread) in a way that is incompatible with SemanticLogger.

[kristoph]

This is really painful. I basically have to use sync in the jobs :(

[miharekar]

I'm also not able to get SolidQueue logs to go to AppSignal. And the before_perform hack just keeps adding more appenders which is…not ideal 😅

[karlentwistle]

I am also facing the same issue and have used https://github.com/miharekar/visualizer/commit/065b009a21fdaa83c3b89ba90977d4f97533f70e as a workaround.

[karlentwistle]

I had another look at this and think I might have figured out a solution. I remembered from configuring Puma it was required to call SemanticLogger.reopen on worker boot (on_worker_boot) since:

After a process has forked SemanticLogger.reopen must be called to re-open files and re-start the appender thread. Otherwise, logging will appear to stop.

~ https://github.com/reidmorrison/semantic_logger/blob/master/docs/forking.md#process-forking

Reading through the Solid Queue docs it says:

Solid Queue's supervisor will fork a separate process for each supervised worker/dispatcher/scheduler.

~ https://github.com/rails/solid_queue?tab=readme-ov-file#workers-dispatchers-and-scheduler

It also offers four hooks

SolidQueue.on_start
SolidQueue.on_stop

SolidQueue.on_worker_start
SolidQueue.on_worker_stop

~ https://github.com/rails/solid_queue?tab=readme-ov-file#lifecycle-hooks

So I found that by adding

# config/initializers/solid_queue.rb

SolidQueue.on_worker_start do
  # Re-open appenders after forking the process
  SemanticLogger.reopen
end

The logs have started to appear in STDOUT.

[choznerol]

#254 is merged and released. Should this issue be closed 🙏?