Polling logging can be noisy. Ways to redirect or silence?

[andynu]

The logging that I find particularly noisy is related to polling.

In production, when execution_mode is :async, the following query happens every 10 seconds by default.

2024-01-18 22:02:15.124 #1896689 DEBUG |   GoodJob::Execution Load (8.0ms)  SELECT "good_jobs".* FROM "good_jobs" WHERE "good_jobs"."id" IN (WITH "rows" AS MATERIALIZED ( SELECT "good_jobs"."id", "good_jobs"."active_job_id" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= '2024-01-18 22:02:15.115219' OR "good_jobs"."scheduled_at" IS NULL) ORDER BY priority DESC NULLS LAST, "good_jobs"."created_at" ASC ) SELECT "rows"."id" FROM "rows" WHERE pg_try_advisory_lock(('x' || substr(md5('good_jobs' || '-' || "rows"."active_job_id"::text), 1, 16))::bit(64)::bigint) LIMIT $1) ORDER BY priority DESC NULLS LAST, "good_jobs"."created_at" ASC  [["LIMIT", 1]] 

In a quiet application, this query piles up in the logs.

I'm curious if we could change something to quiet this down.

Some options that come to mind:

• Use BaseRecord#with_logger_silenced just for this query.
• Allow swapping out of the ActiveRecord logger for GoodJob models.
• Allow defining a good_jobs logfile path, and moving all good_jobs logging out of production.log into its own.

I think it is very important to retain logs of the jobs being executed, and any ActiveRecord logging related to the jobs itself.

Just a thought, happy to work with you on it. Thank you so much for this wonderful library.

[bensheldon]

Thanks for opening this issue. My initial thought on it is that it's tricky:

GoodJob's polling query is the same query used by all other mechanisms to "fetch and lock the next job" i.e. it's the same query that happens after on LISTEN/NOTIFY trigger too. The query for polling could be silenced, but that would make jobs that are executed by polling have an inconsistent query log.

My thought would be to add an option to silence (or change the reporting level to Error) of all of GoodJob's Active Record queries, which would just leave the logs that happen as part of Active Job.

Allow swapping out of the ActiveRecord logger for GoodJob models.

I tried doing something really naive like this and it didn't have the affect I wanted, so it probably would need to be dug into.

# config/initializers/good_job.rb
ActiveSupport.on_load(:good_job_base_record) do
  GoodJob::BaseRecord.logger = Logger.new(IO::NULL)
end

[zarqman]

@bensheldon, I've explored this too and ran into the same issue with logger= not working as expected. If I recall correctly, it's because logging actually happens via LogSubscriber instrumentation which directly uses ActiveRecord::Base.logger. That's arguably something that should be changed in ActiveRecord itself, but I haven't dug into whether that's even feasible.

Some kind of silence{ ... } block might still work.

@andynu, we ended up conditionally disabling the ActiveRecord logs. That might be viable in development if you run GJ in a separate process (eg: via foreman). If you run GJ inside the main Rails process or log ActiveRecord queries in production, then this won't be helpful.

if GoodJob::CLI.within_exe && Rails.env.development? && !ENV['ALL_LOGS']
  ActiveRecord::LogSubscriber.detach_from :active_record
end

[zarqman]

FWIW, just happened to see that SolidQueue is using silence, so that should be viable: https://github.com/basecamp/solid_queue/blob/main/lib/solid_queue/processes/poller.rb

[andynu]

Ben, I see what you mean. I tried assorted on_load hooks, and was unable to effectively silence the logger that way. I do think that approach is a lovely idea, if something like that worked then the library user would have lots of control.

ActiveSupport.on_load(:good_job_base_record) do
  warn 'silencing good job logs'
  #GoodJob::BaseRecord.logger = Logger.new(IO::NULL)
  GoodJob::BaseRecord.logger = Logger.new('log/good_job-initializer.log', 'daily')
end

ActiveSupport.on_load(:active_record) do
  warn 'silencing good job logs - via active record'
  #GoodJob::BaseRecord.logger = Logger.new(IO::NULL)
  GoodJob::BaseRecord.logger = Logger.new('log/good_job-initializer-br.log', 'daily')
  GoodJobRecord.logger = Logger.new('log/good_job-initializer-gjr.log', 'daily')
  GoodJob::Job.logger = Logger.new('log/good_job-initializer-gjj.log', 'daily')
  GoodJob::Execution.logger = Logger.new('log/good_job-initializer-gje.log', 'daily')
end

None of these were effective.

Trying to debug a little:

# app/models/good_job/execution.rb:268
      query = unfinished.dequeueing_ordered(parsed_queues).only_scheduled.limit(1)
      warn "query: #{query.logger.inspect}"
      query.with_advisory_lock(select_limit: queue_select_limit) do |executions|

What I found especially odd was that I could see the logger configuration change as I introduced those different on_load logger overrides. They would appear on the active relation above, but never affected the actual logging when that query was executed. I don't really understand why yet (timing? threads?).

As @zarqman suggests a silence block can effectively silence a particular query.

# app/models/good_job/execution.rb:268
      ActiveRecord::Base.silence{
        unfinished.dequeueing_ordered(parsed_queues).only_scheduled.limit(1)
      }.with_advisory_lock(select_limit: queue_select_limit) do |executions|

However, that is ultra specific. And having a configuration option for one specific query may be too niche a need. Maybe there are a set of queries that together it might make sense to have a collective silence feature for, but it is not quite as nice as being able to swap out the logger.

I do think that if there were a way to just reset the logger used on GoodJob::Exectution and GoodJob::Process models, that would be ideal.