Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

silence_polling not working #198

Open
anandbait opened this issue Apr 4, 2024 · 22 comments
Open

silence_polling not working #198

anandbait opened this issue Apr 4, 2024 · 22 comments

Comments

@anandbait
Copy link

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
Copy link
Member

rosa commented Apr 4, 2024

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
Copy link

bronzdoc commented Apr 5, 2024

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

@rosa
Copy link
Member

rosa commented Apr 5, 2024

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

@bronzdoc
Copy link

bronzdoc commented Apr 5, 2024

@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
Copy link

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

@anandbait
Copy link
Author

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
Copy link
Member

rosa commented Apr 7, 2024

@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
Copy link
Contributor

namolnad commented Apr 7, 2024

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?

image

@rosa
Copy link
Member

rosa commented Apr 10, 2024

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
Copy link
Author

@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
Copy link
Member

rosa commented Apr 10, 2024

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
Copy link
Contributor

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
Copy link
Member

rosa commented Apr 10, 2024

Yes, I think silence_queries would work 👍🏻

@jroes
Copy link

jroes commented Apr 13, 2024

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
Copy link

jroes commented Apr 13, 2024

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
Copy link
Contributor

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: #210

@rbarrera87
Copy link

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
Copy link

lylo commented Sep 16, 2024

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
Copy link
Member

rosa commented Sep 16, 2024

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
Copy link
Member

rosa commented Sep 16, 2024

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
Copy link
Member

rosa commented Sep 16, 2024

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
Copy link

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?

image

added a PR for an option to silence the heartbeat logging #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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

9 participants