Do not spam logs with SQL for super-frequent tasks (#16)

The whole logging configuration had the goal of not outputting too much
SQL into the STDOUT of the process hosting the worker thread, primarily
when using Gouda inside banksvc. But what this comes down to is that we
run very frequent polling calls, which - in turn - perform SQL queries.
These queries can actually be suppressed selectively.

CHANGELOG.md

@@ -52,3 +52,7 @@
 ## [0.1.11] - 2024-07-03
 
 - Fix: make sure the Gouda logger config does not get used during Rails initialization
+
+## [0.1.12] - 2024-07-03
+
+- When doing polling, suppress DEBUG-level messages. This will stop Gouda spamming the logs with SQL in dev/test environments.

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(&blk)
+    # 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, &blk)
+    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

lib/gouda/version.rb

@@ -1,5 +1,5 @@
 # frozen_string_literal: true
 
 module Gouda
-  VERSION = "0.1.11"
+  VERSION = "0.1.12"
 end

lib/gouda/worker.rb

@@ -83,12 +83,13 @@ def initialize(queue_constraint = Gouda::AnyQueue)
     end
 
     def call
-      # return false unless Rails.application # Rails is still booting and there is no application defined
-
       Gouda.config.app_executor.wrap do
-        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 # If the DB connection cannot be checked out etc
+    rescue
+      # It is possible that in this scenario we do not have a database set up yet, for example,
+      # or we are unable to connect to the DB for whatever reason. In that case we should
+      # return `false` so that the worker can poll again later.
       false
     end
   end
@@ -158,13 +159,14 @@ 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.where(id: executing_workload_ids.to_a, state: "executing").update_all(executing_on: worker_id, last_execution_heartbeat_at: Time.now.utc)
+        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
 
         # Find jobs which just hung and clean them up (mark them as "finished" and enqueue replacement workloads if possible)
         Gouda::Workload.reap_zombie_workloads
       rescue => e
         Gouda.instrument(:exception, {exception: e})
-
         warn "Uncaught exception during housekeeping (#{e.class} - #{e}"
       end
 

lib/gouda/workload.rb

@@ -115,9 +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
-          jobs.first.tap do |job|
-            job&.update!(state: "executing", executing_on: executing_on, last_execution_heartbeat_at: Time.now.utc, execution_started_at: Time.now.utc)
-          end
+          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