PG Transactional locks not working on Rails 5.2

[jmanian]

I've been using with_advisory_lock for transactional locks on Rails 4.2 for a long time with success. I just upgraded my app to Rails 5.2 and suddenly they're not working anymore. I'm using Postgres.

My use case is to prevent double-creation of a record (very similar to the use described in #42). It looks something like this:

def create_or_update_user(external_user)
  transaction do
    with_advisory_lock("create-user-#{external_user.id}", transaction: true) do
      user = User.find_or_initialize_by(external_id: external_user.id)
      user.update_info(external_user)
      user.save!
    end
  end
end

This code is executed by Sidekiq workers in jobs that are triggered by 3rd party webhooks. Often two jobs will run simultaneously that are trying to run this same method for the same user. On Rails 4.2 the transactional advisory lock would successfully prevent two workers from trying to create the same user record. Now that I'm on Rails 5.2 I'm getting flooded with ActiveRecord::RecordNotUnique errors, meaning that the the locks are not working like they used to. (The table has a unique index in postgres that prevents a duplicate record.)

Does anyone know what might have changed in Rails 5 that could cause this? Did something change with the way that ActiveRecord connects to the database? @mceachen would your comments on #42 apply here? Those were about session-level locks on MySQL so I'm unsure, but the fact that it used to work and now it doesn't is very confusing to me.

---

PS I've noticed that the block isn't necessary for transaction locks, since the lock is released when the transaction ends, so I've also tried the following code and I get the same result. Both of these approaches worked on Rails 4.2:

def create_or_update_user(external_user)
  transaction do
    with_advisory_lock("create-user-#{external_user.id}", transaction: true)
    user = User.find_or_initialize_by(external_id: external_user.id)
    user.update_info(external_user)
    user.save!
  end
end

[schmittsfn]

@jmanian Were you able to resolve the issue? Is this only happening for transactional locks?

[jmanian]

No, I haven't made any progress on this. I'm only seeing it for transactional locks, but we don't use session-level locks very much, so I can't really say.

I also haven't been able to reproduce the issue in a development environment. In all of my testing in development the locks work as expected, both transactional and session-level.

[lucasprag]

Hey @jmanian did you get to any workaround/solution? Do happen to know if upgrading Rails helps?

I'm having the exact same problem and I'd really appreciate if you have anything to share, thank you so much 🙇

[jmanian]

@lucasprag Unfortunately I did not find a solution. I'm still on Rails 5.2, so I don't know if newer versions will help.

I added a bunch of logs to my code that check current_advisory_lock in the places where the lock should be happening, and everything checks out. That's about as far as I got with this.

[jmanian]

I decided to try posting an issue in Rails, we'll see if anyone there has any help.

[jmanian]

I ran another test that I hadn't tried before, where I use two separate rails console sessions in my production environment to acquire the same lock. I had tried this before in my development environment but not production.

The end result is the locks behave as expected in this test.

In the first console I ran this (Team is an ActiveRecord model):

Team.transaction { Team.with_advisory_lock('jeff testing', transaction: true) { sleep(5); Team.find(2) } }

And then immediately after running that, while it was sleeping inside the lock, I ran the same thing in the other console (except without the sleep). The output in the second console is as expected:

   (0.4ms)  BEGIN
   (0.6ms)  SELECT pg_try_advisory_xact_lock(1733956427,0) AS tefee4202a3520daacc36632826326ad8 /* jeff testing */
   (0.5ms)  SELECT pg_try_advisory_xact_lock(1733956427,0) AS t4598f4668078a10b60b56619175dccc1 /* jeff testing */
  # ... repeats for 5 seconds while waiting for the lock
   (1.1ms)  SELECT pg_try_advisory_xact_lock(1733956427,0) AS t7a140cd5092be65eb0053bcabf155bde /* jeff testing */
  Team Load (22.0ms)  SELECT  "teams".* FROM "teams" WHERE "teams"."id" = $1 LIMIT $2  [["id", 2], ["LIMIT", 1]]
   (3.0ms)  COMMIT
=> #<Team id: 2, ...>

So from this I gather that my production app is able to acquire and respect the locks. I'll try to devise more tests to see if I can reproduce the issue in a more controlled way.

[jmanian]

OK I finally figured out what the issue is in my case: caching. The lock is working just fine, but find_or_initialize_by is using the cache to incorrectly decide that the record doesn't exist. I gave a lot more detail here.

This can be solved with ActiveRecord::QueryCache.uncached. Perhaps with_advisory_lock should automatically not use the cache within its block, via uncached. I think this may happen automatically with AR's built-in pessimistic row locking.

[jmanian]

Opened #52 to continue this

[lucasprag]

Thank you so much for investigating this further @jmanian

It was the same case for me and adding a ApplicationRecord.uncached block immediately inside the transaction solved it. 🎉

But in my case I was using a scope with .take. I also tested .where and .find_by, but it was not any different. It seems it's related to all ActiveRecord methods.

I added some logs to compare queries from ActiveRecord and raw SQL queries from ActiveRecord::Base.connection.execute. At some point after getting the lock, my code would run both queries again and I'd only get results from the raw SQL using ActiveRecord::Base.connection.execute.

Again I really appreciate the idea on how to solve it, thanks @jmanian 👍