silence_polling not working

[anandbait]

I have added config.solid_queue.silence_polling = true in my application.rb I have restarted my server after that. But still I am getting logs as following

solid_queue_1  |   SolidQueue::Pause Pluck (1.4ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue_1  |   TRANSACTION (0.6ms)  BEGIN
solid_queue_1  |   SolidQueue::ReadyExecution Pluck (2.1ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue_1  |   TRANSACTION (0.6ms)  COMMIT
solid_queue_1  |   SolidQueue::Pause Pluck (1.4ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue_1  |   TRANSACTION (0.5ms)  BEGIN
solid_queue_1  |   SolidQueue::ReadyExecution Pluck (2.0ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue_1  |   TRANSACTION (0.5ms)  COMMIT
solid_queue_1  |   SolidQueue::Pause Pluck (1.1ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue_1  |   TRANSACTION (0.5ms)  BEGIN
solid_queue_1  |   SolidQueue::ReadyExecution Pluck (1.8ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue_1  |   TRANSACTION (0.5ms)  COMMIT
solid_queue_1  |   SolidQueue::Pause Pluck (1.6ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue_1  |   TRANSACTION (0.7ms)  BEGIN
solid_queue_1  |   SolidQueue::ReadyExecution Pluck (2.7ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue_1  |   TRANSACTION (0.6ms)  COMMIT
solid_queue_1  |   SolidQueue::Pause Pluck (1.7ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue_1  |   TRANSACTION (0.6ms)  BEGIN
solid_queue_1  |   SolidQueue::ReadyExecution Pluck (2.5ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue_1  |   TRANSACTION (0.6ms)  COMMIT
solid_queue_1  |   SolidQueue::Pause Pluck (1.4ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue_1  |   TRANSACTION (0.7ms)  BEGIN
solid_queue_1  |   SolidQueue::ReadyExecution Pluck (2.5ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue_1  |   TRANSACTION (0.7ms)  COMMIT
solid_queue_1  |   SolidQueue::Pause Pluck (1.9ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue_1  |   TRANSACTION (0.7ms)  BEGIN
solid_queue_1  |   SolidQueue::ReadyExecution Pluck (2.6ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue_1  |   TRANSACTION (0.7ms)  COMMIT
solid_queue_1  |   SolidQueue::Pause Pluck (1.6ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue_1  |   TRANSACTION (0.7ms)  BEGIN
solid_queue_1  |   SolidQueue::ReadyExecution Pluck (2.7ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue_1  |   TRANSACTION (0.7ms)  COMMIT
solid_queue_1  |   SolidQueue::Pause Pluck (1.7ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue_1  |   TRANSACTION (0.7ms)  BEGIN
solid_queue_1  |   SolidQueue::ReadyExecution Pluck (2.7ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue_1  |   TRANSACTION (0.6ms)  COMMIT
solid_queue_1  |   TRANSACTION (0.3ms)  BEGIN
solid_queue_1  |   SolidQueue::ScheduledExecution Pluck (0.9ms)  SELECT "solid_queue_scheduled_executions"."job_id" FROM "solid_queue_scheduled_executions" WHERE "solid_queue_scheduled_executions"."scheduled_at" <= $1 ORDER BY "solid_queue_scheduled_executions"."scheduled_at" ASC, "solid_queue_scheduled_executions"."priority" ASC, "solid_queue_scheduled_executions"."job_id" ASC LIMIT $2 FOR UPDATE SKIP LOCKED  [["scheduled_at", "2024-04-04 05:11:28.597874"], ["LIMIT", 500]]
solid_queue_1  |   TRANSACTION (0.2ms)  COMMIT

Is there anything else I need to do?

[rosa]

Hey @anandbait, no, that should be all 😕 It's very strange it doesn't work for you. Looks like you're using Docker? Is it possible you didn't restart the supervisor there correctly? Or that you're looking at old logs? 😕

[bronzdoc]

I'm experiencing the same issue and I'm also using Docker

[rosa]

Hey @bronzdoc, are you making sure everything is restarted correctly? Could you share a bit more about your setup? For example, your Dockerfile?

[bronzdoc]

@rosa Yes, I have restarted the services multiple times.

I have a service in my docker-compose.yml like this

solid_queue:
  build:
  command: bundle exec rake solid_queue:start
  depends_on:
    - postgres
  volumes:
    - .:/app

solid_queue version: 0.3.0 Docker version: 24.0.6, build ed223bc Docker Compose version: 24.0.6, build ed223bc

And in config/application.rb I added config.solid_queue.silence_polling = true

[wflanagan]

I have this as well. Logging is still present in a Kubernetes/Docker environment.

[anandbait]

Hey @anandbait, no, that should be all 😕 It's very strange it doesn't work for you. Looks like you're using Docker? Is it possible you didn't restart the supervisor there correctly? Or that you're looking at old logs? 😕

I have similar setup as @bronzdoc I restarted docker-compose so the setup should reflect right?

@rosa Can you confirm that while we talk about "polling queries" then those are same queries which I have posted in logs or some other queries?

[rosa]

@rosa Can you confirm that while we talk about "polling queries" then those are same queries which I have posted in logs or some other queries?

Yes, it's exactly those queries that you have posted, the ones that should be silenced. Something must be broken 🤔 We did change the default from false to true for that setting very recently, but that shouldn't have broken it 😕 I'll dig into it.

[namolnad]

Since this topic is under discussion, I've long been curious about the heartbeat queries and whether those should have been silenced as well. Are these to be expected, or should they have been silenced along with all the other queries?

[rosa]

Oh, @namolnad, good question. Those weren't intended to be suppressed with this setting because they're not polling queries or related to polling 🤔 Perhaps the silence_polling setting should be generalized to include those queries, with a different, more generic name 🤔

[anandbait]

@rosa One more observation, I created just a new regular app and in that the queries are silenced by default as expected. So I believe the query silencing is not working with dockerized app.

[rosa]

Thanks @anandbait! That was my suspicion as well, as silencing the queries is working fine for us in several cases 😕

It's really weird that Docker would play a role here! I need to dig more.

[namolnad]

Oh, @namolnad, good question. Those weren't intended to be suppressed with this setting because they're not polling queries or related to polling 🤔 Perhaps the silence_polling setting should be generalized to include those queries, with a different, more generic name 🤔

Ahh that makes sense re: the silence_polling name and intention. Unsure people generally feel this way, but I know I'd be on board for a more generalized name/setting to silence those additional queries (I receive a few complaints from my team from time to time :)). Perhaps just silent = true or silence_queries = true would convey the meaning adequately?

[rosa]

Yes, I think silence_queries would work 👍🏻

[jroes]

Also seeing this behavior, and not running in Docker. I do have a few different things that are plugging into the logging system that might be interfering. I'm on 0.3.0 of the gem, and I have tried both true and false for the config in my application.rb file:

  class Application < Rails::Application
    ...
    config.solid_queue.silence_polling = false

And this is the logging output I'm observing:

solid_queue        |   TRANSACTION (0.2ms)  BEGIN
solid_queue        |   SolidQueue::ReadyExecution Pluck (1.6ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue        |   TRANSACTION (0.2ms)  COMMIT
solid_queue        |   TRANSACTION (0.2ms)  BEGIN
solid_queue        |   SolidQueue::ScheduledExecution Pluck (1.6ms)  SELECT "solid_queue_scheduled_executions"."job_id" FROM "solid_queue_scheduled_executions" WHERE "solid_queue_scheduled_executions"."scheduled_at" <= $1 ORDER BY "solid_queue_scheduled_executions"."scheduled_at" ASC, "solid_queue_scheduled_executions"."priority" ASC, "solid_queue_scheduled_executions"."job_id" ASC LIMIT $2 FOR UPDATE SKIP LOCKED  [["scheduled_at", "2024-04-13 02:00:52.553253"], ["LIMIT", 500]]
solid_queue        |   TRANSACTION (0.2ms)  COMMIT
solid_queue        |   SolidQueue::Pause Pluck (0.8ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue        |   TRANSACTION (0.2ms)  BEGIN
solid_queue        |   SolidQueue::ReadyExecution Pluck (1.4ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue        |   TRANSACTION (0.2ms)  COMMIT
solid_queue        |   SolidQueue::Pause Pluck (0.8ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
solid_queue        |   TRANSACTION (0.3ms)  BEGIN
solid_queue        |   SolidQueue::ReadyExecution Pluck (1.8ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
solid_queue        |   TRANSACTION (1.1ms)  COMMIT

(Running via overmind in this example but same behavior when running standalone)

[jroes]

Sorted it out on my end, in my development.rb I had:

config.logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))

Removing that fixed things for me. As a minor note in case others are unaware, bin/rails s will print logs to stdout, but running puma directly will not.

[namolnad]

Yes, I think silence_queries would work 👍🏻

@rosa I've separated this work into another issue to keep this one focused on the other (seemingly docker-related) problem. New issue here: https://github.com/rails/solid_queue/issues/210

[rbarrera87]

In my case the logs are not being shown in the container logs, however, I am able to bash the container and tail the logs there.

[lylo]

I came across this today while fiddling with log configurations. Turns out if you declare the following (as recommended by the Rails guides) then you get Solid Queue polling logs regardless of what you set silence_polling to:

config.logger = Logger.new(STDOUT)

However if you use ActiveSupport::Logger it works as expected:

config.logger = ActiveSupport::Logger.new(STDOUT)

Note you can use TaggedLogging just fine:

  stdout_logger = ActiveSupport::Logger.new(STDOUT)
  tagged_logger = ActiveSupport::TaggedLogging.new(stdout_logger)

  config.log_tags = [ :request_id ]
  config.logger = tagged_logger

[rosa]

Oh, that makes sense, I suppose, because #silence is provided by Active Support 🤔 But I'm surprised you don't get an error, though...

[rosa]

But I'm surprised you don't get an error, though...

Ahhh, you don't because Rails internally uses ActiveSupport::BroadcastLogger, that broadcasts to a list of loggers, in this case just with Logger.new(STDOUT). I'm surprised now that it doesn't work, though! 😆 I'll dig a bit more.

[rosa]

I'm surprised now that it doesn't work, though! 😆 I'll dig a bit more.

Aha, yes, it's expected. The reason is that #silence simply overrides the log level with error (by default), and ActiveSupport::BroadcastLogger sets the local_level for its list of loggers to that level, for the duration of the block, if the logger responds to local_level=, which Logger doesn't do. So yes, this behaviour using Logger is expected.

[jlvallelonga]

Since this topic is under discussion, I've long been curious about the heartbeat queries and whether those should have been silenced as well. Are these to be expected, or should they have been silenced along with all the other queries?

added a PR for an option to silence the heartbeat logging https://github.com/rails/solid_queue/pull/389. In the meantime, we're using a patch to silence these in HostedGPT: (https://github.com/AllYourBot/hostedgpt/blob/main/config/initializers/solid_queue_extension.rb)

module CustomProcess
  def heartbeat
    # only silence if explicitly set to not log (default to logging)
    # true or not set (or anything else) means log, false means silence
    silence_heartbeat = ENV["SOLID_QUEUE_LOG_HEARTBEAT_ON"] == "false"

    if silence_heartbeat && ActiveRecord::Base.logger
      ActiveRecord::Base.logger.silence { super }
    else
      super
    end
  end
end

Rails.application.config.after_initialize do
  SolidQueue::Process.send(:prepend, CustomProcess)
end