diff --git a/lib/gouda.rb b/lib/gouda.rb index d1609d5..01c496f 100644 --- a/lib/gouda.rb +++ b/lib/gouda.rb @@ -81,6 +81,20 @@ def self.logger Rails.try(:logger) || ActiveJob::Base.try(:logger) || @fallback_gouda_logger end + def self.suppressing_sql_logs(&) + # This is used for frequently-called methods that poll the DB. If logging is done at a low level (DEBUG) + # those methods print a lot of SQL into the logs, on every poll. While that is useful if + # you collect SQL queries from the logs, in most cases - especially if this is used + # in a side-thread inside Puma - the output might be quite annoying. So silence the + # logger when we poll, but just to INFO. Omitting DEBUG-level messages gets rid of the SQL. + if Gouda::Workload.logger + Gouda::Workload.logger.silence(Logger::INFO, &) + else + # In tests (and at earlier stages of the Rails boot cycle) the global ActiveRecord logger may be nil + yield + end + end + def self.instrument(channel, options, &block) ActiveSupport::Notifications.instrument("#{channel}.gouda", options, &block) end diff --git a/lib/gouda/worker.rb b/lib/gouda/worker.rb index afb390d..4daaec1 100644 --- a/lib/gouda/worker.rb +++ b/lib/gouda/worker.rb @@ -84,12 +84,7 @@ def initialize(queue_constraint = Gouda::AnyQueue) def call Gouda.config.app_executor.wrap do - # This method is called frequently. If logging is done at a low level (DEBUG or other) - # this will print a lot of SQL into the logs, on every poll. While that is useful if - # you collect SQL queries from the logs, in most cases - especially if this is used - # in a side-thread inside Puma - the output might be quite annoying. So silence the - # logger when we poll, but just to INFO. Omitting DEBUG-level messages gets rid of the SQL. - Gouda::Workload.logger.silence(Logger::INFO) { Gouda::Workload.waiting_to_start(queue_constraint: @queue_constraint).none? } + Gouda.suppressing_sql_logs { Gouda::Workload.waiting_to_start(queue_constraint: @queue_constraint).none? } end rescue # It is possible that in this scenario we do not have a database set up yet, for example, @@ -164,7 +159,7 @@ def self.worker_loop(n_threads:, check_shutdown: TrapShutdownCheck.new, queue_co # a stale timestamp can indicate to us that the job was orphaned and is marked as "executing" # even though the worker it was running on has failed for whatever reason. # Later on we can figure out what to do with those jobs (re-enqueue them or toss them) - Gouda::Workload.logger.silence(Logger::INFO) do # these updates will also be very frequent with long-running jobs, and they generate SQL + Gouda.suppressing_sql_logs do # these updates will also be very frequent with long-running jobs Gouda::Workload.where(id: executing_workload_ids.to_a, state: "executing").update_all(executing_on: worker_id, last_execution_heartbeat_at: Time.now.utc) end diff --git a/lib/gouda/workload.rb b/lib/gouda/workload.rb index e9808de..aef39c2 100644 --- a/lib/gouda/workload.rb +++ b/lib/gouda/workload.rb @@ -115,15 +115,9 @@ def self.checkout_and_lock_one(executing_on:, queue_constraint: Gouda::AnyQueue) payload[:retried_checkouts_due_to_concurrent_exec] = 0 uncached do # Necessary because we SELECT with a clock_timestamp() which otherwise gets cached by ActiveRecord query cache transaction do - # This method is called frequently. If logging is done at a low level (DEBUG or other) - # this will print a lot of SQL into the logs, on every poll. While that is useful if - # you collect SQL queries from the logs, in most cases - especially if this is used - # in a side-thread inside Puma - the output might be quite annoying. So silence the - # logger when we poll, but just to INFO. Omitting DEBUG-level messages gets rid of the SQL. - # Now, it might be prudent to add an envvar for enabling this output (to debug Gouda itself, - # or to debug Gouda inside of an application) - we can think about it later. - job = logger.silence(Logger::INFO) { jobs.first } + job = Gouda.suppressing_sql_logs { jobs.first } # Silence SQL output as this gets called very frequently job&.update!(state: "executing", executing_on: executing_on, last_execution_heartbeat_at: Time.now.utc, execution_started_at: Time.now.utc) + job rescue ActiveRecord::RecordNotUnique # It can happen that due to a race the `execution_concurrency_key NOT IN` does not capture # a job which _just_ entered the "executing" state, apparently after we do our SELECT. This will happen regardless