Leaking unrelated scopes #14003

Open
dnagir opened this Issue Feb 10, 2014 · 27 comments

Projects

None yet

9 participants

@dnagir
Contributor
dnagir commented Feb 10, 2014

See the repro:

gem 'activerecord', '4.0.2'
require 'active_record'
require 'minitest/autorun'
require 'logger'

ActiveRecord::Base.logger = Logger.new(STDOUT)
ActiveRecord::Base.establish_connection(
  :adapter  => 'postgresql',
  :database => 'x'
)

ActiveRecord::Schema.define do
  create_table :users, :force => true do |t|
  end
  create_table :projects, :force => true do |t|
    t.integer :user_id
  end
end

class User < ActiveRecord::Base
  has_many :projects
end

class Project < ActiveRecord::Base
  belongs_to :user

  def self.accessible_to(u)
    where(id: u.projects.select(:id)) # simplified for this example only
  end
end


class TestMe < MiniTest::Unit::TestCase
  def test_leaking_scope
    user = User.create!
    Project.where("1=1").accessible_to(user)
    print user
  end

  def test_no_scope_thus_not_leaking
    user = User.create!
    print user
  end


  def print(user)
    puts "-"*30, user.projects.to_sql, "-"*30
  end
end

with the output:

-- create_table(:users, {:force=>true})
D, [2014-02-10T17:04:02.461922 #8901] DEBUG -- :    (1.5ms)  DROP TABLE "users"
D, [2014-02-10T17:04:02.464266 #8901] DEBUG -- :    (2.2ms)  CREATE TABLE "users" ("id" serial primary key) 
   -> 0.0188s
-- create_table(:projects, {:force=>true})
D, [2014-02-10T17:04:02.465910 #8901] DEBUG -- :    (0.8ms)  DROP TABLE "projects"
D, [2014-02-10T17:04:02.467515 #8901] DEBUG -- :    (1.5ms)  CREATE TABLE "projects" ("id" serial primary key, "user_id" integer) 
   -> 0.0032s
MiniTest::Unit::TestCase is now Minitest::Test. From tmp/test.rb:33:in `<main>'
Run options: --seed 33760

# Running:

D, [2014-02-10T17:04:02.532025 #8901] DEBUG -- :    (0.2ms)  BEGIN
D, [2014-02-10T17:04:02.538572 #8901] DEBUG -- :   SQL (0.8ms)  INSERT INTO "users" DEFAULT VALUES RETURNING "id"
D, [2014-02-10T17:04:02.539088 #8901] DEBUG -- :    (0.1ms)  COMMIT
------------------------------
SELECT "projects".* FROM "projects"  WHERE (1=1) AND "projects"."user_id" = $1
------------------------------
.D, [2014-02-10T17:04:02.549907 #8901] DEBUG -- :    (0.1ms)  BEGIN
D, [2014-02-10T17:04:02.550536 #8901] DEBUG -- :   SQL (0.2ms)  INSERT INTO "users" DEFAULT VALUES RETURNING "id"
D, [2014-02-10T17:04:02.550806 #8901] DEBUG -- :    (0.1ms)  COMMIT
------------------------------
SELECT "projects".* FROM "projects"  WHERE "projects"."user_id" = $1
------------------------------
.

Finished in 0.025384s, 78.7898 runs/s, 0.0000 assertions/s.

2 runs, 0 assertions, 0 failures, 0 errors, 0 skips

NOTE the printed WHERE caluses in both tests. One includes the where conditions created on a totally unrelated scope.

This is potentially a critical bug (unless I'm blind and don't see something important) which can affect the whole application by yielding some very unexpected results.
Those issues may be extremely hard to track down with some data leaking out.

So I would probably even consider this a security issue.

Can reproduce on all published Rails 4 versions, including 4.1.0.beta1.

@dnagir
Contributor
dnagir commented Feb 10, 2014

Just thumbs up on this...
If one is lucky, then the nested query will only bring the parent scope's data.

In my case that is killing the performance though because there are additional nested scans for every subquery.

In other cases, the query will be just invalid, especially if the bindings are used and will be missing then.

So yeah, leaking state is no good!

@pftg
Contributor
pftg commented Feb 10, 2014

@dnagir may you provide your expected SLQ statements for Project.where("1=1").accessible_to(user)

@dnagir
Contributor
dnagir commented Feb 10, 2014

Paul you seriously asking that. Just confused :(
The nested subquery should not include the condition from the main one (1=1
should only appear once in the main query). Please note that after using
that scope the association user.projects is broken too.
On 10 Feb 2014 17:35, "Paul Nikitochkin" notifications@github.com wrote:

@dnagir https://github.com/dnagir may you provide your expected SLQ
statements for Project.where("1=1").accessible_to(user)


Reply to this email directly or view it on GitHubhttps://github.com/rails/rails/issues/14003#issuecomment-34604151
.

@pftg
Contributor
pftg commented Feb 10, 2014

@dnagir sorry, I missed your print method, which as for me should be inlined into the tests to show the explicitly the problem.

@pftg
Contributor
pftg commented Feb 10, 2014

Confirmed for rails 4.0.2 and master.

@pftg
Contributor
pftg commented Feb 10, 2014

By the way:

 def test_leaking_scope_passed
    user = User.create!
    Project.where('1=1').where(id: user.projects.select(:id))
    print user
  end

this example passed!

@dnagir
Contributor
dnagir commented Feb 10, 2014

Well, yes. And? We can't inline all the scopes as a workaround.
On 10 Feb 2014 20:24, "Paul Nikitochkin" notifications@github.com wrote:

By the way:

def test_leaking_scope_passed
user = User.create!
Project.where('1=1').where(id: user.projects.select(:id))
print user
end

this example passed!


Reply to this email directly or view it on GitHubhttps://github.com/rails/rails/issues/14003#issuecomment-34612256
.

@pftg
Contributor
pftg commented Feb 10, 2014

And also there is funny moment:

  def test_leaking_scope
    user = User.create!
    user.projects

    Project.where('1=1').accessible_to(user)

    refute_includes user.projects.to_sql, '1=1'
  end

passed!

@pftg
Contributor
pftg commented Feb 10, 2014

I'm working on this issue, will back with solution soon.

@senny
Member
senny commented Feb 10, 2014

Could this be related to: https://gist.github.com/senny/6425163 ?

@pftg
Contributor
pftg commented Feb 10, 2014

@senny I think very similar

@senny
Member
senny commented Feb 10, 2014

@pftg note that the gist I linked is "expected" behavior and won't be fixed. As you are traversing an association this ticket might qualify as a bug. The association proxy could unscope it's query.

/cc @rafaelfranca

@senny senny added the activerecord label Feb 10, 2014
@rafaelfranca
Member

Yes. This is expected behavior.

Project.where("1=1").accessible_to(user)

Is equal to:

Project.where("1=1")scoping do
  Project.accessible_to(user)
end

So the where clause will be applied.

If you don't want the chain to be applied you need to use unscoped

@rafaelfranca rafaelfranca reopened this Feb 10, 2014
@rafaelfranca
Member

@senny just pointed we misunderstood the issue. The problem is not the Project.where("1=1").accessible_to(user) but the user.projects.to_sql called below.

So indeed, this looks like an issue.

@pftg
Contributor
pftg commented Feb 10, 2014
@pftg
Contributor
pftg commented Feb 10, 2014

After user.projects called in scoping block, it copied all where_values, but if I have build reflection out of scoping block, it works fine like in last my example:

  user = User.create!
  user.projects

  Project.where('1=1').accessible_to(user)
@senny senny added this to the 4.0.3 milestone Feb 10, 2014
@senny senny added the regression label Feb 10, 2014
@pftg
Contributor
pftg commented Feb 10, 2014

@senny I think caches problem was reported before, about saving current_scope with the same base_class but for different owners like this. I'm trying to find similar issue.

@tenderlove
Member

This is a dup of #13466. We have a student working on a fix for this here.

@dnagir
Contributor
dnagir commented Feb 10, 2014

@tenderlove watch out, it may not be a duplicate because #13466 reports it was broken in Rails 4.0.2 but I can reproduce this issue since Rails 4.0.0.
So while they may look similar, the underlying problems could be a little different.

Just FYI.

@jefflai2 jefflai2 referenced this issue in friends-of-rails/rails Feb 11, 2014
Closed

Scope Evaluation Rework #4

@jefflai2
Contributor

Can someone confirm that the actual query used is affected? Reason why I ask is, if I change the test so that the actual query values are used, e.g...

def print(user)
    puts "-"*30, user.projects, "-"*30
  end

then the console output is:

-- create_table(:users, {:force=>true})
D, [2014-02-16T01:50:46.093172 #53845] DEBUG -- :    (16.5ms)  DROP TABLE "users"
D, [2014-02-16T01:50:46.096945 #53845] DEBUG -- :    (3.4ms)  CREATE TABLE "users" ("id" serial primary key) 
   -> 0.0609s
-- create_table(:projects, {:force=>true})
D, [2014-02-16T01:50:46.099531 #53845] DEBUG -- :    (1.2ms)  DROP TABLE "projects"
D, [2014-02-16T01:50:46.102131 #53845] DEBUG -- :    (2.3ms)  CREATE TABLE "projects" ("id" serial primary key, "user_id" integer) 
   -> 0.0050s
MiniTest::Unit::TestCase is now Minitest::Test. From bugtest2.rb:33:in `<main>'
Run options: --seed 10489

# Running:

D, [2014-02-16T01:50:46.148501 #53845] DEBUG -- :    (0.1ms)  BEGIN
D, [2014-02-16T01:50:46.152673 #53845] DEBUG -- :   SQL (0.6ms)  INSERT INTO "users" DEFAULT VALUES RETURNING "id"
D, [2014-02-16T01:50:46.153501 #53845] DEBUG -- :    (0.4ms)  COMMIT
------------------------------
D, [2014-02-16T01:50:46.181783 #53845] DEBUG -- :   Project Load (0.5ms)  SELECT "projects".* FROM "projects"  WHERE "projects"."user_id" = $1  [["user_id", 1]]
------------------------------
.D, [2014-02-16T01:50:46.185274 #53845] DEBUG -- :    (0.2ms)  BEGIN
D, [2014-02-16T01:50:46.186360 #53845] DEBUG -- :   SQL (0.3ms)  INSERT INTO "users" DEFAULT VALUES RETURNING "id"
D, [2014-02-16T01:50:46.187070 #53845] DEBUG -- :    (0.4ms)  COMMIT
------------------------------
D, [2014-02-16T01:50:46.188338 #53845] DEBUG -- :   Project Load (0.2ms)  SELECT "projects".* FROM "projects"  WHERE "projects"."user_id" = $1  [["user_id", 2]]
------------------------------
.

Finished in 0.048197s, 41.4964 runs/s, 0.0000 assertions/s.

According to the debug output, the actual query being run appears to be correct (nothing is actually printed only because there are no records matching the query). If so, the problem may be an inconsistency with the cached value returned by to_sql. Just thinking out loud, I could be wrong?

@jefflai2
Contributor

This modified gist

gem 'activerecord'
require 'active_record'
require 'minitest/autorun'
require 'logger'

ActiveRecord::Base.logger = Logger.new(STDOUT)
ActiveRecord::Base.establish_connection(
  :adapter  => 'postgresql',
  :database => 'jeffersonlai'
)

ActiveRecord::Schema.define do
  create_table :users, :force => true do |t|
  end
  create_table :projects, :force => true do |t|
    t.integer :user_id
  end
end

class User < ActiveRecord::Base
  has_many :projects
end

class Project < ActiveRecord::Base
  belongs_to :user

  def self.accessible_to(u)
    # Force the entire query to be evaluated
    where(id: u.projects.select(:id).to_a) # simplified for this example only
  end
end

class TestMe < MiniTest::Unit::TestCase
  def setup
    @user = User.create!
    # Adds a Project record that would actually match the query
    Project.create!(:user => @user)
  end

  def test_leaking_scope
    Project.where("1=1").accessible_to(@user)
    print @user
  end

  def test_no_scope_thus_not_leaking
    print @user
  end

  def print(user)
    puts "-"*30 
    # This doesn't cause the query to execute
    puts "to_sql Query: #{user.projects.to_sql}"
    # This does
    puts "Query Results: #{user.projects.to_a}"
    puts "-"*30
  end

end

generates

-- create_table(:users, {:force=>true})
D, [2014-02-17T17:38:54.355543 #69659] DEBUG -- :    (2.9ms)  DROP TABLE "users"
D, [2014-02-17T17:38:54.360074 #69659] DEBUG -- :    (4.2ms)  CREATE TABLE "users" ("id" serial primary key) 
   -> 0.0374s
-- create_table(:projects, {:force=>true})
D, [2014-02-17T17:38:54.363270 #69659] DEBUG -- :    (1.6ms)  DROP TABLE "projects"
D, [2014-02-17T17:38:54.365955 #69659] DEBUG -- :    (2.4ms)  CREATE TABLE "projects" ("id" serial primary key, "user_id" integer) 
   -> 0.0057s
MiniTest::Unit::TestCase is now Minitest::Test. From bugtest2.rb:33:in `<main>'
Run options: --seed 27127

# Running:

D, [2014-02-17T17:38:54.406709 #69659] DEBUG -- :    (0.1ms)  BEGIN
D, [2014-02-17T17:38:54.410903 #69659] DEBUG -- :   SQL (0.7ms)  INSERT INTO "users" DEFAULT VALUES RETURNING "id"
D, [2014-02-17T17:38:54.411734 #69659] DEBUG -- :    (0.5ms)  COMMIT
D, [2014-02-17T17:38:54.420370 #69659] DEBUG -- :    (0.2ms)  BEGIN
D, [2014-02-17T17:38:54.425880 #69659] DEBUG -- :   SQL (0.6ms)  INSERT INTO "projects" ("user_id") VALUES ($1) RETURNING "id"  [["user_id", 1]]
D, [2014-02-17T17:38:54.426738 #69659] DEBUG -- :    (0.5ms)  COMMIT
D, [2014-02-17T17:38:54.437169 #69659] DEBUG -- :   Project Load (0.4ms)  SELECT "projects"."id" FROM "projects"  WHERE (1=1) AND "projects"."user_id" = $1  [["user_id", 1]]
------------------------------
to_sql 'Query': SELECT "projects".* FROM "projects"  WHERE (1=1) AND "projects"."user_id" = $1
D, [2014-02-17T17:38:54.444675 #69659] DEBUG -- :   Project Load (0.3ms)  SELECT "projects".* FROM "projects"  WHERE "projects"."user_id" = $1  [["user_id", 1]]
Query Results: [#<Project id: 1, user_id: 1>]
------------------------------
.D, [2014-02-17T17:38:54.445688 #69659] DEBUG -- :    (0.2ms)  BEGIN
D, [2014-02-17T17:38:54.446923 #69659] DEBUG -- :   SQL (0.5ms)  INSERT INTO "users" DEFAULT VALUES RETURNING "id"
D, [2014-02-17T17:38:54.447754 #69659] DEBUG -- :    (0.4ms)  COMMIT
D, [2014-02-17T17:38:54.448393 #69659] DEBUG -- :    (0.1ms)  BEGIN
D, [2014-02-17T17:38:54.449517 #69659] DEBUG -- :   SQL (0.2ms)  INSERT INTO "projects" ("user_id") VALUES ($1) RETURNING "id"  [["user_id", 2]]
D, [2014-02-17T17:38:54.450212 #69659] DEBUG -- :    (0.4ms)  COMMIT
------------------------------
to_sql 'Query': SELECT "projects".* FROM "projects"  WHERE "projects"."user_id" = $1
D, [2014-02-17T17:38:54.451690 #69659] DEBUG -- :   Project Load (0.3ms)  SELECT "projects".* FROM "projects"  WHERE "projects"."user_id" = $1  [["user_id", 2]]
Query Results: [#<Project id: 2, user_id: 2>]
------------------------------
.

Finished in 0.051543s, 38.8026 runs/s, 0.0000 assertions/s.

2 runs, 0 assertions, 0 failures, 0 errors, 0 skips

The query actually executed is as expected, while the string generated by to_sql is not.

@rafaelfranca rafaelfranca modified the milestone: 4.0.5, 4.0.4 Mar 10, 2014
@rafaelfranca rafaelfranca added regression and removed regression labels Mar 17, 2014
@rafaelfranca rafaelfranca modified the milestone: 4.0.6, 4.0.5 Mar 17, 2014
@jefflai2
Contributor

This is actually a problem with the cached CollectionProxy object retaining the scope it is created in, including the where condition(s).

@matthewd matthewd self-assigned this Mar 29, 2014
@rafaelfranca rafaelfranca modified the milestone: 4.0.6, 4.0.7 May 21, 2014
@rafaelfranca rafaelfranca reopened this Aug 7, 2014
@PikachuEXE
Contributor

Will this be fixed in 4.2.*?

@PikachuEXE
Contributor

I wish this got reviewed before 5.0.0 release :)

@rails-bot rails-bot added the stale label Jun 26, 2015
@rails-bot

This issue has been automatically marked as stale because it has not been commented on for at least
three months.

The resources of the Rails team are limited, and so we are asking for your help.

If you can still reproduce this error on the 4-2-stable, 4-1-stable branches or on master,
please reply with all of the information you have about it in order to keep the issue open.

Thank you for all your contributions.

@rafaelfranca rafaelfranca added pinned and removed stale labels Aug 25, 2015
@PikachuEXE
Contributor

I still have this issue in 5.0.1

Using the same script I posted in #16420
http://pastebin.com/3Fw2VSxD

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment