Add constant like GoodJob.within_cli? to improve configuration of annoying ActiveRecord logging

[morgoth]

When using newly generated Rails app, which sets by default log level to "DEBUG", the worker process outputs annoying AR logging every second:

D, [2020-09-04T14:46:19.543162 #2280635] DEBUG -- :   GoodJob::Job Load (1.4ms)  SELECT "good_jobs".* FROM "good_jobs" WHERE "good_jobs"."id" IN (WITH "rows" AS (SELECT "good_jobs"."id" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= '2020-09-04 12:46:19.539575' OR "good_jobs"."scheduled_at" IS NULL) ORDER BY priority DESC NULLS LAST) SELECT "rows"."id" FROM "rows" WHERE pg_try_advisory_lock(('x'||substr(md5('good_jobs' || "rows"."id"::text), 1, 16))::bit(64)::bigint) LIMIT $1) ORDER BY priority DESC NULLS LAST  [["LIMIT", 1]]

which creates a lot of noise.

I disabled it by:

# config/environments/{development.rb|production.rb}
config.log_level = ENV["RAILS_LOGGER_LEVEL"] if ENV["RAILS_LOGGER_LEVEL"]

and then in Procfile (or whenever the worker is run):
worker: RAILS_LOGGER_LEVEL="info" bundle exec good_job start

Not sure if this could somehow be integrated into gem itself by some configuration accessor, as this is an issue with global ActiveRecord logging so in fact it is out of scope of GoodJob gem.
If there is no clever way to do it, maybe a mention in doscs how to workaround it would be useful.

[bensheldon]

I think you’re experiencing Rails’s verbose query logging: https://guides.rubyonrails.org/debugging_rails_applications.html#verbose-query-logs

Verbose query logs are turned on by default in development, and (I think) off in production.

I agree, it’s annoying; it also shows up when running in async execution mode too.

There are a couple different approaches one could take:

• Change the log level so DEBUG-level logs are outputted, as you described.

• Changing ActiveRecord::Base.verbose_query_logs = false.

• Making it easier to do either one of those options in configuration when using the $ good_job CLI. e,.g.

  # config/initializers/good_job.rb
  if GoodJob.within_cli? # not a method that currently exists
    ActiveRecord::Base.verbose_query_logs = false
  end

• You can also dial back the poll-interval to something like 1 minute, which would decrease the frequency of the logs.

[morgoth]

As it goes for ActiveRecord::Base.verbose_query_logs = false, it won't tweak this as this config prints the caller of given SQL statement https://github.com/rails/rails/blob/ab4ab090667e96c0e8a2623e33573ae06be14b54/guides/source/debugging_rails_applications.md#verbose-query-logs

I guess having something like GoodJob.within_cli? would be helpful

[bensheldon]

@morgoth whoops, you're correct about ActiveRecord::Base.verbose_query_logs = false. I was thinking that controlled the entirety of the SQL query logging, but it seems like the query logging is simply a :debug-level log.

Thinking more about it, it does straddle the line of Rails configuration and GoodJob. Query logging is an implicit feature of Rails and the Rails logger... and GoodJob is unexpectedly verbose just given that it has to poll on a regular basis.

Your workaround is similar to what I have in my Rails projects:

# config/environments/{development.rb|production.rb}
config.log_level = ENV.fetch("RAILS_LOGGER_LEVEL", "info")

I'll transform this Issue into a feature request for a constant for checking whether configuration is running as part of GoodJob.

# config/initializers/good_job.rb
if GoodJob.within_cli?
  Rails.application.config.log_level = ENV.fetch("RAILS_LOGGER_LEVEL", "info")
end

[minimul]

As mentioned above you can also raise the polling duration to keep the dev log from getting huge: e.g. 1 minute.

GOOD_JOB_POLL_INTERVAL=60 bundle exec good_job start

@bensheldon states that polling can be shut off by setting the interval to -1 but I could not get that to stick, tried:

GOOD_JOB_POLL_INTERVAL=-1
GOOD_JOB_POLL_INTERVAL="-1"

[bensheldon]

@minimul Thanks for the assist and for flagging that problem! I've opened up an Issue #133 to investigate.

[bensheldon]

Revisiting this, there is a method to test whether the current process is running as part of the $ good_job executable:

GoodJob::CLI.within_exe?