Unique database errors

[EleanorRagone]

Hi there -

I'm having intermittent problems that I'm having trouble replicating, but I figured I'd reach out to you guys and see if you're familiar with it.

Long story short, this is the error:

ActiveRecord::RecordNotUnique: PG::UniqueViolation: ERROR:  duplicate key value violates unique constraint "versions_pkey"

The conditions:

• in development
• in console; I haven't noticed it happening when actually interacting with my application via a browser, but I don't religiously look at every request in the development log
• Rails 4.1
• confounding factor: using multitenancy as implemented by the Apartment gem, which utilizes postgres schemas. I have excluded the "versions" table, though, so this shouldn't be an issue

It's a big problem because this error ends up rolling back my update:

2.1.5 :006 > u.save(validate: false)
   (0.4ms)  BEGIN
  SQL (1.0ms)  UPDATE "public"."users" SET "apartment_roles_mask" = $1, "updated_at" = $2 WHERE "public"."users"."id" = 5  [["apartment_roles_mask", "\"hvremo\"=>\"5\",\"public\"=>\"32\""], ["updated_at
", "2014-12-26 18:54:43.412041"]]
  SQL (33.6ms)  INSERT INTO "versions" ("created_at", "event", "item_id", "item_type", "object") VALUES ($1, $2, $3, $4, $5) RETURNING "id"  [["created_at", "2014-12-26 18:54:43.467064"], ["event", "upd
ate"], ["item_id", 5], ["item_type", "User"], ["object", "---\nid: 5\nfirst_name: Peter\nlast_name: Ragone\nemail: peter@prmtech.com\nusername: '350310'\nold_data: \ncreated_at: 2014-12-26 02:31:32.3762
95000 Z\nupdated_at: 2014-12-26 18:29:09.237037000 Z\nencrypted_password: \"$2a$10$BsdfJlY51q3YRmuKe4MpoONq9hIgS2Lrrh8EQYpG.3IYRpzPtPNtq\"\nreset_password_token: \nreset_password_sent_at: \nremember_cre
ated_at: \nsign_in_count: 3\ncurrent_sign_in_at: 2014-12-26 18:29:09.233149000 Z\nlast_sign_in_at: 2014-12-26 03:50:52.172595000 Z\ncurrent_sign_in_ip: !ruby/object:IPAddr\n  family: 2\n  addr: 21307064
33\n  mask_addr: 4294967295\nlast_sign_in_ip: !ruby/object:IPAddr\n  family: 2\n  addr: 2130706433\n  mask_addr: 4294967295\nconfirmation_token: \nconfirmed_at: 2014-12-26 02:40:15.863417000 Z\nconfirma
tion_sent_at: 2014-12-26 02:39:54.487143000 Z\nunconfirmed_email: \nfailed_attempts: 0\nunlock_token: \nlocked_at: \napartment_roles_mask:\n  hvremo: '5'\n  public: '0'\nflags:\n  new_remo_als_user: 'fa
lse'\n  after_signup_complete: 'true'\n  next_after_signup_step: 'false'\n  email_confirmation_instructions_sent: 'true'\ndefault_region_id: \n"]]
PG::UniqueViolation: ERROR:  duplicate key value violates unique constraint "versions_pkey"
DETAIL:  Key (id)=(1) already exists.
: INSERT INTO "versions" ("created_at", "event", "item_id", "item_type", "object") VALUES ($1, $2, $3, $4, $5) RETURNING "id"
   (0.5ms)  ROLLBACK
ActiveRecord::RecordNotUnique: PG::UniqueViolation: ERROR:  duplicate key value violates unique constraint "versions_pkey"
DETAIL:  Key (id)=(1) already exists.
: INSERT INTO "versions" ("created_at", "event", "item_id", "item_type", "object") VALUES ($1, $2, $3, $4, $5) RETURNING "id"
        from /Users/pragone/.rvm/gems/ruby-2.1.5@remoonline/gems/activerecord-4.1.8/lib/active_record/connection_adapters/postgresql_adapter.rb:834:in `get_last_result'
        from /Users/pragone/.rvm/gems/ruby-2.1.5@remoonline/gems/activerecord-4.1.8/lib/active_record/connection_adapters/postgresql_adapter.rb:834:in `block in exec_cache'
        from /Users/pragone/.rvm/gems/ruby-2.1.5@remoonline/gems/activerecord-4.1.8/lib/active_record/connection_adapters/abstract_adapter.rb:373:in `block in log'
        from /Users/pragone/.rvm/gems/ruby-2.1.5@remoonline/gems/activesupport-4.1.8/lib/active_support/notifications/instrumenter.rb:20:in `instrument'

I re-issue the save command, and everything works fine.

Are you familiar with this condition happening? Can you give me any more insight? I'm happy to try and replicate this more and identify it, but, like I said, it seems to be an intermittent problem.

Edit: Looking at this some more, it seems to be issuing a double-insert into versions; I'm not sure why, when there's clearly only a single update to the users table.

[batter]

I am not familiar with the error unfortunately. What is the 'versions_pkey' constraint they are referring to? Or is that PG's way of referring to a primary key for the versions table? I don't think the versions table would have a primary key by default if you used the base setup from the generator.. just an index. So maybe it's an index duplicate insert, but it shouldn't be a unique index by default so I'm not sure why that would occur.

[batter]

Closing for now, but feel free to follow up if you encounter these issues again.

[tombroomfield]

Hi,
I am also getting this error when I save a previous version in order to rollback.

Thanks,
Tom.

[batter]

What version of PaperTrail are you using?

[rvfx]

I get a similar error. paper_trail (4.0.0.beta2) tries to save my entry while the old one still exists, when I call PaperTrail::Version.find(params[:id]).reify.save!:

INSERT INTO "reservations" ("id", "created_at", "guest_id", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "id" ["id", 15], ["created_at", "2015-03-06 16:54:04.016854"], ["guest_id", 6], ["updated_at", "2015-03-09 10:57:10.457005"]]

PG::UniqueViolation: ERROR: duplicate key value violates unique constraint "reservations_pkey" DETAIL: Key (id)=(15) already exists.

[batter]

Looks like these are issues of your database table sequence falling out of sync or something. This StackOverflow post might give you some help on how to reset the sequence on your table.

Although I do find it a bit strange that it's attempting to do an insert instead of an update on this row, so maybe that's what's going wrong here. When I try this on my local w/ SQLite I get an update statement:

2.0.0-p247 :004 > PaperTrail::Version.find(2).reify.save!
  PaperTrail::Version Load (0.2ms)  SELECT  "versions".* FROM "versions"  WHERE "versions"."id" = ? LIMIT 1  [["id", 2]]
  Widget Load (0.1ms)  SELECT  "widgets".* FROM "widgets"  WHERE "widgets"."id" = ? LIMIT 1  [["id", 1]]
   (0.0ms)  SAVEPOINT active_record_1
  SQL (0.0ms)  UPDATE "widgets" SET "name" = ?, "updated_at" = ? WHERE "widgets"."id" = 1  [["name", "foobar"], ["updated_at", "2015-03-09 16:03:21.239462"]]
  SQL (0.1ms)  INSERT INTO "versions" ("created_at", "event", "item_id", "item_type", "object", "object_changes", "transaction_id") VALUES (?, ?, ?, ?, ?, ?, ?)  [["created_at", "2015-03-09 16:03:21.239462"], ["event", "update"], ["item_id", 1], ["item_type", "Widget"], ["object", "---\nid: 1\nname: bar\na_text: \nan_integer: \na_float: \na_decimal: \na_datetime: \na_time: \na_date: \na_boolean: \nsacrificial_column: \ntype: \ncreated_at: 2015-03-09 16:03:06.105316000 Z\nupdated_at: 2015-03-09 16:03:15.704597000 Z\n"], ["object_changes", "---\nname:\n- bar\n- foobar\nupdated_at:\n- 2015-03-09 16:03:15.704597000 Z\n- 2015-03-09 16:03:21.239462000 Z\n"], ["transaction_id", 1]]
   (0.0ms)  RELEASE SAVEPOINT active_record_1
 => true

So perhaps it's a Postgres / ActiveRecord error. Does this happen for you w/ PaperTrail 3.x and also what version of ActiveRecord are you using?

[rvfx]

I get the same error with version 3.0.7 (ActiveRecord 4.2.0), but I have an idea why PaperTrail tries to insert the row. The entry I want to reset is excluded by a default_scope. ActiveRecord might think the entry was deleted and has to be inserted...

Update:
I don't get an error when I remove the default_scope.

[rvfx]

I looked more closely at the gem's code:
version_concern.rb:8 uses a standard belongs_to association:
belongs_to :item, :polymorphic => true

Thereby any default_scope which is defined in the item's model will be applied. I think it would be an improvement if PaperTrail would use an unscoped query. Otherwise any item "hidden" by default_scope will cause an error.

[batter]

@rvfx - can you try using the :dup => true option arg to the reify method? like so:
PaperTrail::Version.find(params[:id]).reify(dup: true).save!

[rvfx]

No changes with :dup => true. :(

[batter]

Ok what is your suggested adjustment that you think would fix the issue? Drop this approach and do something more along the lines of this?

inheritance_column_name = item_type.constantize.inheritance_column
class_name = attrs[inheritance_column_name].blank? ? item_type : attrs[inheritance_column_name]
klass = class_name.constantize
model = klass.unscoped.find_by_id(item_id) || klass.new

Any chance you can provide a failing test case via a PR or something?

[rvfx]

The unscoped version works great! PR coming up...

[batter]

@rvfx - Did you ever find time to implement this code into something that could be made into a PR? I'm trying to tie of loose ends for 4.x before an official release and I think this would be a good addition, but I'm unsure of exactly what should change since I don't have test cases to duplicate this issue..

[rvfx]

The code you suggested works fine.
Sorry, I haven't found time to make a commit.

[mockdeep]

For what it's worth, I was seeing this issue with a custom subclass in development mode. Rails 6.0.3.6, PaperTrail 12.0.0. I had this class:

class SubjectVersion < PaperTrail::Version
  self.table_name = :subject_versions
end

When I would reset the database with our seeds, there would be 16 records in the subjects_versions table, but for some reason Postgres would have the next id as 2. I instead switched it to include VersionConcern, and things seem to work better at first glance. The next id is 17 and the page that was throwing the error allows me to continue:

class SubjectVersion < ApplicationRecord
  include PaperTrail::VersionConcern
end

[goalaleo]

For what it's worth, I'm also seeing this issue in production with a custom subclass.

PG::UniqueViolation: ERROR:  duplicate key value violates unique constraint "uuid_versions_pkey"
DETAIL:  Key (id)=(50283809) already exists.

class PaperTrail::UuidVersion < PaperTrail::Version
  self.table_name = 'uuid_versions'
end

I wonder if the problem has something to do with not declaring a sequence_name for the subclass, so sequence_name returns the same value. Note that we're also using the base class for models which have serial ids.

> PaperTrail::UuidVersion.sequence_name
=> "public.versions_id_seq"
> PaperTrail::Version.sequence_name
=> "public.versions_id_seq"

However, when I check the latest values for the correct sequences

> ActiveRecord::Base.connection.execute("SELECT last_value FROM versions_id_seq").to_a
=> [{"last_value"=>175167875}]
> ActiveRecord::Base.connection.execute("SELECT last_value FROM uuid_versions_id_seq").to_a
=> [{"last_value"=>50383555}]

And then I check the version id of the latest version for one of our models using Uuid versions

MyModel.order(:created_at).last.versions.sort_by(&:created_at).last.id
=> 50397156

it looks like it's actually using the uuid_versions_id_seq sequence to generate the pk even though PaperTrail::UuidVersion.sequence_name returns "public.versions_id_seq". I'm a bit perplexed on how the used sequence is actually defined :/