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

"WARNING: you don't own a lock of type ExclusiveLock" in Development #388

Closed
newbenji opened this issue Sep 29, 2021 · 15 comments
Closed

"WARNING: you don't own a lock of type ExclusiveLock" in Development #388

newbenji opened this issue Sep 29, 2021 · 15 comments

Comments

@newbenji
Copy link

First of all great job.
Working on migration some jobs to good_job.
but i get this warning out.

WARNING: you don't own a lock of type ExclusiveLock

But i cant find documentation to support it, or im not good at finding it

@bensheldon
Copy link
Owner

@newbenji hmm, that's unexpected for you to receive that warning:

WARNING: you don't own a lock of type ExclusiveLock

The warning is output by the database adapter. It means that the current database connection (thread) is trying to unlock an Advisory Lock that does not exist.

Can you say more about where you're seeing this?

@newbenji
Copy link
Author

newbenji commented Sep 29, 2021 via email

@bensheldon
Copy link
Owner

Are you seeing this in your development environment, or in production?

Could you try adding this to an initializer (config/initializers/good_job.rb):

# Output Postgres notifications through Rails.logger instead of stderr
ActiveSupport.on_load :active_record do
  ActiveRecord::ConnectionAdapters::AbstractAdapter.set_callback :checkout, :before, lambda { |conn|
    raw_connection = conn.raw_connection
    next unless raw_connection.respond_to? :set_notice_receiver

    raw_connection.set_notice_receiver do |result|
      Rails.logger.info(result.error_message)
    end
  }
end

...and then share the logs that are produced (the initializer above will make sure that the Postgres warning shows up in the logs, rather than going to stderr).

Also, I wrote out some of these hints too for some lock causing problems I've run across: #329 (comment)

@mchristen
Copy link

I see this in my development environment! It seems to happen around the times I change code and the code reloading takes place.

@bensheldon
Copy link
Owner

bensheldon commented Sep 30, 2021

Thank you @mchristen! I was able to reproduce it in development with code reloading. When a Rails reloads the code, the database connection that is used to take the initial advisory lock is not the same connection used to release the lock. I'm only seeing this when code reloading is enabled , not in a Production configuration (fhew!)

I will put together a fix for this.

Relates to #95 which has a lot of early reloading lessons.

@bensheldon bensheldon changed the title Advisory lock WARNING: you don't own a lock of type ExclusiveLock Sep 30, 2021
@bensheldon bensheldon changed the title WARNING: you don't own a lock of type ExclusiveLock "WARNING: you don't own a lock of type ExclusiveLock" in Development Sep 30, 2021
@bensheldon
Copy link
Owner

bensheldon commented Sep 30, 2021

I have a fix for this released: https://github.com/bensheldon/good_job/releases/tag/v2.3.1

@newbenji
Copy link
Author

newbenji commented Oct 4, 2021

thx awsome and fast response. i must aggree i only saw the error on development

@mikehale
Copy link

I'm seeing this when running in development mode and using the external execution mode.

@bensheldon
Copy link
Owner

@mikehale hmm, that's unexpected because nothing should be taking an advisory lock with external execution mode. Could you tell me where it's coming from? Something like adding a puts caller in the set_notice_receiver

ActiveSupport.on_load :active_record do
  ActiveRecord::ConnectionAdapters::AbstractAdapter.set_callback :checkout, :before, lambda { |conn|
    raw_connection = conn.raw_connection
    next unless raw_connection.respond_to? :set_notice_receiver

    raw_connection.set_notice_receiver do |result|
      puts caller # <-- the new thing
    end
  }
end

@mikehale
Copy link

mikehale commented Mar 12, 2024

Steps to reproduce:

  1. Start web and worker processes in development mode using the following initializer:
Rails.application.configure do
  ActiveSupport.on_load :active_record do
    ActiveRecord::ConnectionAdapters::AbstractAdapter.set_callback :checkout, :before, lambda { |conn|
      raw_connection = conn.raw_connection
      next unless raw_connection.respond_to? :set_notice_receiver

      raw_connection.set_notice_receiver do |result|
        puts caller # <-- the new thing
      end
    }
  end

  config.good_job = {
    smaller_number_is_higher_priority: true,
    execution_mode: :external,
    enable_cron: true,
  }
end
  1. Enqueue a pile of jobs to be worked
  2. While the jobs are being worked modify one of my controllers
  3. Notice the worker log output pause
  4. Make a request to said controller
  5. Wait about 30 seconds for the worker log output to resume and see the following:
[GoodJob] [76101] [GoodJob::Scheduler(queues=* max_threads=5)-thread-1] Executed GoodJob fb05c4c7-b848-4482-ba8b-80b99501eeaa
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql_adapter.rb:894:in `exec_params'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql_adapter.rb:894:in `block (2 levels) in exec_no_cache'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql_adapter.rb:893:in `block in exec_no_cache'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.2/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract_adapter.rb:1143:in `log'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql_adapter.rb:892:in `exec_no_cache'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql_adapter.rb:872:in `execute_and_clear'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:64:in `internal_exec_query'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/database_statements.rb:142:in `exec_query'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/query_cache.rb:25:in `exec_query'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.24.0/app/models/concerns/good_job/advisory_lockable.rb:229:in `advisory_unlock_key'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.24.0/app/models/concerns/good_job/advisory_lockable.rb:327:in `advisory_unlock'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.24.0/app/models/concerns/good_job/advisory_lockable.rb:178:in `block in with_advisory_lock'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.24.0/app/models/concerns/good_job/advisory_lockable.rb:177:in `each'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.24.0/app/models/concerns/good_job/advisory_lockable.rb:177:in `with_advisory_lock'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/relation/delegation.rb:79:in `block in with_advisory_lock'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/relation.rb:929:in `_scoping'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/relation.rb:467:in `scoping'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/relation/delegation.rb:79:in `with_advisory_lock'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.24.0/app/models/good_job/execution.rb:268:in `perform_with_advisory_lock'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/relation/delegation.rb:79:in `block in perform_with_advisory_lock'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/relation.rb:929:in `_scoping'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/relation.rb:467:in `scoping'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.2/lib/active_record/relation/delegation.rb:79:in `perform_with_advisory_lock'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.24.0/lib/good_job/job_performer.rb:33:in `next'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.24.0/lib/good_job/scheduler.rb:272:in `block (2 levels) in create_task'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.2/lib/active_support/reloader.rb:77:in `block in wrap'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.2/lib/active_support/execution_wrapper.rb:92:in `wrap'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.2/lib/active_support/reloader.rb:74:in `wrap'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.24.0/lib/good_job/scheduler.rb:271:in `block in create_task'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `loop'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'
/Users/mhale/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'

@finchi
Copy link

finchi commented Apr 1, 2024

Also getting this warning, in combination with WARNING: there is already a transaction in progress.
But as far as I can tell, only in combination with testing on gitlab ci.

Was not able to reproduce it in development/test on my local machine or in production.

The annoying part is, that when it happens on gitlab ci, that the runner will lock up completely, until I kill the runner, or it gets killed after 1h by the timeout

It only startet to appear, after I introduced code with a lot of after_commit calls

@klevo
Copy link

klevo commented Apr 4, 2024

I'm also getting the WARNING: you don't own a lock of type ExclusiveLock in a parallelized test suite (214 tests in parallel using 12 processes). In the output its preceded by messages like message type 0x49 arrived from server while idle.

It happens every 5 runs or so.

GoodJob uses stock configuration, no modifications. Rails 7.1.3.2, PostgreSQL 16.2, good_job 3.27.3.

Screenshot 2024-04-04 at 14 07 14

I wonder whether we should open a new issue?

@klevo
Copy link

klevo commented Apr 4, 2024

If I disable parallelization I don't observe the above issue.

@bensheldon
Copy link
Owner

Maybe open a new issue for better visibility if it is only related to test parallelization.

Briefly, I imagine that some part of GoodJob is being set up (maybe in the initial process that manages the subprocesses?) and then it's losing its database connection. That error basically means "GoodJob expected this database connection to hold an advisory lock, but it doesn't" which probably means the initial database connection was closed and a new one was opened in its place.

@klevo
Copy link

klevo commented Apr 5, 2024

Maybe open a new issue for better visibility if it is only related to test parallelization.

Briefly, I imagine that some part of GoodJob is being set up (maybe in the initial process that manages the subprocesses?) and then it's losing its database connection. That error basically means "GoodJob expected this database connection to hold an advisory lock, but it doesn't" which probably means the initial database connection was closed and a new one was opened in its place.

Thanks @bensheldon . I'll see if I can create some test codebase to reliably reproduce the issue and then open an issue.

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

6 participants