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

update_attributes broken w/ postgresql #9418

Closed
ngauthier opened this issue Feb 25, 2013 · 15 comments
Closed

update_attributes broken w/ postgresql #9418

ngauthier opened this issue Feb 25, 2013 · 15 comments

Comments

@ngauthier
Copy link

Reproduce

  1. Make a new edge rails app using rails master
  2. Use pg gem and config database for postgresql
  3. rails g model person name:string
  4. p = Person.create name: "Joe"
  5. p.update_attributes name: "Bob"

Stack trace:

irb(main):003:0> p.update_attributes name: "Bob"
   (0.4ms)  BEGIN
  SQL (0.8ms)  UPDATE "people" SET "name" = '$1', "updated_at" = '$2' WHERE "people"."id" = 1  [["name", "Bob"], ["updated_at", Mon, 25 Feb 2013 17:44:22 UTC +00:00]]
PG::Error: ERROR:  invalid input syntax for type timestamp: "$2"
LINE 1: UPDATE "people" SET "name" = '$1', "updated_at" = '$2' WHERE...
                                                          ^
: UPDATE "people" SET "name" = '$1', "updated_at" = '$2' WHERE "people"."id" = 1
   (0.2ms)  ROLLBACK
ActiveRecord::StatementInvalid: PG::Error: ERROR:  invalid input syntax for type timestamp: "$2"
LINE 1: UPDATE "people" SET "name" = '$1', "updated_at" = '$2' WHERE...
                                                          ^
: UPDATE "people" SET "name" = '$1', "updated_at" = '$2' WHERE "people"."id" = 1
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:757:in `prepare'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:757:in `prepare_statement'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:718:in `exec_cache'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:160:in `block in exec_delete'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:334:in `block in log'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activesupport/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:329:in `log'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:158:in `exec_delete'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:102:in `update'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:14:in `update'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/persistence.rb:447:in `update_record'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/locking/optimistic.rb:70:in `update_record'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/attribute_methods/dirty.rb:74:in `update_record'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/callbacks.rb:307:in `block in update_record'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activesupport/lib/active_support/callbacks.rb:373:in `_run__2929842947684877850__update__callbacks'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activesupport/lib/active_support/callbacks.rb:78:in `run_callbacks'
... 16 levels...
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/transactions.rb:281:in `rollback_active_record_state!'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/transactions.rb:269:in `save'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/persistence.rb:222:in `block in update'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/transactions.rb:326:in `block in with_transaction_returning_status'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:201:in `block in transaction'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:209:in `within_new_transaction'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:201:in `transaction'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/transactions.rb:209:in `transaction'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/transactions.rb:323:in `with_transaction_returning_status'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/activerecord/lib/active_record/persistence.rb:220:in `update'
    from (irb):3
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/railties/lib/rails/commands/console.rb:88:in `start'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/railties/lib/rails/commands/console.rb:9:in `start'
    from /Users/nick/.gems/bundler/gems/rails-d10056087c01/railties/lib/rails/commands.rb:64:in `<top (required)>'
    from script/rails:6:in `require'
    from script/rails:6:in `<main>'irb(main):004:0> 

Related to 45321a6 ?

/cc @tenderlove

xoxo @ngauthier

@joallard
Copy link

Confirming. Bisecting leads to a53935d / 45321a6 aswell, so indeed related to #9246. It has to do with bind parameters escaping, which maybe shouldn't be in PG...

@ngauthier
Copy link
Author

Yeah, I've been digging deep into it. I cleaned up the relevant part to:

        klass = self.class
        conn = klass.connection
        scope = klass.where(klass.arel_table[klass.primary_key].eq(id))

        substitutes = {}
        values = {}
        attributes_with_values.each_with_index do |tuple, i|
          attr, value = tuple
          column       = klass.columns_hash[attr.name]
          substitutes[attr] = conn.substitute_at(column, i)
          values[column] = value
        end

        stmt = scope.arel.compile_update(substitutes)
        conn.update stmt, 'SQL', values

but it's the same bug. I noticed everywhere else there is a pattern involving bind_values << [column, value] but I couldn't get bind_values to work. Any tips on that? Most of the code is about scopes, not generating updates like this.

Also, inserts are not done with a prepared statement, they're the closest thing I could think of to compare to. Anywhere I can look to see how to do substitutions in general?

@ngauthier
Copy link
Author

also /cc @Noemj who wrote the patch, maybe he can lend a hand?

@ngauthier
Copy link
Author

oh, and the patch also removed a null-value test only for postgresql. Meaning that the patch has removed the support for updated values to being null values! Seems like something we shouldn't do. What was the justification for the substitutions in the first place? Performance?

@joallard
Copy link

The select statements work with prepared statements as well; I'm looking into it too.

For Googling purposes, the error I got was:

 ActiveRecord::StatementInvalid:
       PG::Error: ERROR:  bind message supplies 1 parameters, but prepared statement "a4" requires 0
       : UPDATE "agencies" SET "business_id" = '$1' WHERE "agencies"."id" = '092714ad8a3a4ced29edb91d7e6cd65a'

@joallard
Copy link

I think the reason was that changes in arel made some fixes necessary (#9246)

@ngauthier
Copy link
Author

More notes:

If I look immediately above the error, the other subbed requests are not quoted:

  Deck Load (0.9ms)  SELECT "decks".* FROM "decks" WHERE "decks"."user_id" = $1 AND "decks"."slug" = 'testing' LIMIT 1  [["user_id", 1]]
   (0.5ms)  UPDATE "decks" SET "current_slide" = 0, "updated_at" = '$2' WHERE "decks"."id" = 1

So, the sub is being quoted by arel when the update is compiled. And by then it's too late to sub. Also note that in the above it should be "current_slide" = $1 so that is getting dropped too. It's very odd.

@ngauthier
Copy link
Author

More info:

it is the compile_update that is doing the improper quoting, because at that phase it is expecting a full query, but it still is the substitutions.

So, what we need is a way to prepare the arel scope into a sql statement with substitutions before sending it to connection.update. I am not sure how to do this.

Here's the rewrite I'm working with that makes the actions clearer:

klass = self.class
conn = klass.connection
scope = klass.where(klass.arel_table[klass.primary_key].eq(id))

substitutes = {}
values = {}
attributes_with_values.each_with_index do |tuple, i|
  attr, value       = tuple
  column            = klass.columns_hash[attr.name]
  substitutes[attr] = conn.substitute_at(column, i)
  values[column]    = value
end

stmt = scope.arel.compile_update(substitutes)
conn.update stmt, 'SQL', values

@joallard
Copy link

I found it. It's a bug in Arel that escapes on assignment nodes regardless of if the parameter is a SQL literal or not (which it is). I suspect other database engines don't mind escaping while PG takes offense. I'll prepare a fix.

@ngauthier
Copy link
Author

great. Did this make it into the beta? Also I never checked to see if regular save calls trigger it :-/

@ngauthier
Copy link
Author

Looks like it's fixed in the beta. I think that means arel was fixed a while back and maybe we're on old versions of it?

It does look like updates are going through as prepared statements.

@ngauthier
Copy link
Author

Yup, I bet it was bd36f18

Closing.

@joallard
Copy link

Wow, so much time bug-hunting and it had been fixed the whole time. Ha.

@olliwer
Copy link
Contributor

olliwer commented Feb 26, 2013

Right, sorry guys for making the arel changes a bit difficult to read on the pull request. I should have emphasized their importance more.

Also, postgresql null byte handling was not affected by this update. The null bytes won't throw an error but will truncate the rest of the string, which was also the case before. Null byte support was added for sqlite3 due to changing to prepared statements.

The arel changes were indeed necessary for the prepared statements to work, not the other way around.

@janko
Copy link
Contributor

janko commented Jun 13, 2013

It's funny, in 4.0.0.rc2 this bug appears if you have prepared_statements: false in your database.yml. If you don't have it, everything is fine.

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

4 participants