Skip to content

Nil results with multiple connections (cucumber) #2943

Closed
jasonm opened this Issue Sep 8, 2011 · 33 comments
@jasonm
jasonm commented Sep 8, 2011

We just upgraded an application to 3.1, and see a consistent issue in the test suite (cucumber, capybara, selenium).

Seeing issue #1339 we upgraded to the 3-1-stable branch, but this did not fix our issue.

Since we are using capybara, there are two PG connections active. Each is constructed here, in PostgreSQLAdapter#connect https://github.com/rails/rails/blob/5ed3e6a61f/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb#L1032 One connection is initialized during rails boot, the other by Capybara::Server#boot (in a separate thread).

The issue only shows up when we use direct model access (e.g. creating models via a Factory, or looking models up) after interacting with the app through capybara. If we place all direct model access before the web interactions, the error doesn't happen.

If I patch aforementioned private method PostgreSQLAdapter#connect to use the same PGconn object for both connections, then the error does not happen:

    # Connects to a PostgreSQL server and sets up the adapter depending on the
    # connected server's characteristics.
    def connect
      # Commented out the original line:
      # @connection = PGconn.connect(*@connection_parameters)
      #
      # And replaced it with:
      $global_pg_connection ||= PGconn.connect(*@connection_parameters)
      @connection = $global_pg_connection

The full error:

Scenario: Canceling editing the worry score after an error                      # features/user/edit_patient_worry_score.feature:66
  Given the following patient exists:                                           # factory_girl-2.0.5/lib/factory_girl/step_definitions.rb:99
    | first_name | middle_name | last_name | Practice       |
    | Wayne      | Mark        | Rooney    | Name: Beantown |
    NoMethodError: undefined method `fields' for nil:NilClass: SELECT  1 FROM "patients"  WHERE ("patients"."last_name" = 'Rooney' AND "patients"."first_name" = 'Wayne' AND "patients"."dob" = '1914-11-24 18:50:15.500542') LIMIT 1 (ActiveRecord::StatementInvalid)
    /Users/jason/dev/rails/activesupport/lib/active_support/whiny_nil.rb:48:in `method_missing'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:594:in `block in exec_query'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:244:in `block in log'
    /Users/jason/dev/rails/activesupport/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:239:in `log'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:590:in `exec_query'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:1078:in `select'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:18:in `select_all'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:63:in `select_all'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:24:in `select_one'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:30:in `select_value'
    /Users/jason/dev/rails/activerecord/lib/active_record/relation/finder_methods.rb:203:in `exists?'
    /Users/jason/dev/rails/activerecord/lib/active_record/validations/uniqueness.rb:33:in `validate_each'
    /Users/jason/dev/rails/activemodel/lib/active_model/validator.rb:153:in `block in validate'
    /Users/jason/dev/rails/activemodel/lib/active_model/validator.rb:150:in `each'
    /Users/jason/dev/rails/activemodel/lib/active_model/validator.rb:150:in `validate'
    /Users/jason/dev/rails/activesupport/lib/active_support/callbacks.rb:302:in `_callback_before_137'
    /Users/jason/dev/rails/activesupport/lib/active_support/callbacks.rb:476:in `_run_validate_callbacks'
    /Users/jason/dev/rails/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'
    /Users/jason/dev/rails/activemodel/lib/active_model/validations.rb:212:in `run_validations!'
    /Users/jason/dev/rails/activemodel/lib/active_model/validations/callbacks.rb:53:in `block in run_validations!'
    /Users/jason/dev/rails/activesupport/lib/active_support/callbacks.rb:390:in `_run_validation_callbacks'
    /Users/jason/dev/rails/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'
    /Users/jason/dev/rails/activemodel/lib/active_model/validations/callbacks.rb:53:in `run_validations!'
    /Users/jason/dev/rails/activemodel/lib/active_model/validations.rb:179:in `valid?'
    /Users/jason/dev/rails/activerecord/lib/active_record/validations.rb:69:in `valid?'
    /Users/jason/dev/rails/activerecord/lib/active_record/validations.rb:77:in `perform_validations'
    /Users/jason/dev/rails/activerecord/lib/active_record/validations.rb:56:in `save!'
    /Users/jason/dev/rails/activerecord/lib/active_record/attribute_methods/dirty.rb:33:in `save!'
    /Users/jason/dev/rails/activerecord/lib/active_record/transactions.rb:246:in `block in save!'
    /Users/jason/dev/rails/activerecord/lib/active_record/transactions.rb:295:in `block in with_transaction_returning_status'
    /Users/jason/dev/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
    /Users/jason/dev/rails/activerecord/lib/active_record/transactions.rb:208:in `transaction'
    /Users/jason/dev/rails/activerecord/lib/active_record/transactions.rb:293:in `with_transaction_returning_status'
    /Users/jason/dev/rails/activerecord/lib/active_record/transactions.rb:246:in `save!'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/factory_girl-2.0.5/lib/factory_girl/proxy/create.rb:9:in `result'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/factory_girl-2.0.5/lib/factory_girl/factory.rb:93:in `run'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/factory_girl-2.0.5/lib/factory_girl/syntax/methods.rb:54:in `create'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/factory_girl-2.0.5/lib/factory_girl/step_definitions.rb:102:in `block (4 levels) in <top (required)>'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/factory_girl-2.0.5/lib/factory_girl/step_definitions.rb:100:in `each'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/factory_girl-2.0.5/lib/factory_girl/step_definitions.rb:100:in `block (3 levels) in <top (required)>'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/core_ext/instance_exec.rb:48:in `instance_exec'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/core_ext/instance_exec.rb:48:in `block in cucumber_instance_exec'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/core_ext/instance_exec.rb:69:in `cucumber_run_with_backtrace_filtering'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/core_ext/instance_exec.rb:36:in `cucumber_instance_exec'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/rb_support/rb_step_definition.rb:62:in `invoke'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/step_match.rb:25:in `invoke'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/step_invocation.rb:59:in `invoke'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/step_invocation.rb:38:in `accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:99:in `block in visit_step'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:163:in `broadcast'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:98:in `visit_step'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/step_collection.rb:15:in `block in accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/step_collection.rb:14:in `each'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/step_collection.rb:14:in `accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:93:in `block in visit_steps'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:163:in `broadcast'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:92:in `visit_steps'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/scenario.rb:55:in `block (2 levels) in accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime.rb:79:in `block (2 levels) in with_hooks'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime.rb:95:in `before_and_after'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime.rb:78:in `block in with_hooks'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime/support_code.rb:120:in `call'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime/support_code.rb:120:in `block (3 levels) in around'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/language_support/language_methods.rb:13:in `block in around'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/language_support/language_methods.rb:95:in `call'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/language_support/language_methods.rb:95:in `execute_around'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/language_support/language_methods.rb:12:in `around'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime/support_code.rb:119:in `block (2 levels) in around'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime/support_code.rb:117:in `call'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime/support_code.rb:117:in `around'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime.rb:90:in `around'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime.rb:77:in `with_hooks'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/scenario.rb:53:in `block in accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/scenario.rb:108:in `with_visitor'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/scenario.rb:47:in `accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:51:in `block in visit_feature_element'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:163:in `broadcast'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:50:in `visit_feature_element'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/feature.rb:43:in `block in accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/feature.rb:42:in `each'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/feature.rb:42:in `accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:20:in `block in visit_feature'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:163:in `broadcast'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:19:in `visit_feature'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/features.rb:29:in `block in accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/features.rb:17:in `each'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/features.rb:17:in `each'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/features.rb:28:in `accept'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:14:in `block in visit_features'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:163:in `broadcast'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/ast/tree_walker.rb:13:in `visit_features'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/runtime.rb:45:in `run!'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/cli/main.rb:43:in `execute!'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/lib/cucumber/cli/main.rb:20:in `execute'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-1.0.3/bin/cucumber:14:in `<top (required)>'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/bin/cucumber:19:in `load'
    /Users/jason/.rvm/gems/ruby-1.9.2-p290/bin/cucumber:19:in `<main>'
    features/user/edit_patient_worry_score.feature:67:in `Given the following patient exists:'
@jasonm
jasonm commented Sep 8, 2011

OSX 10.6.8, ruby 1.9.2-p290, exhibited on both rails 3.1.0 released and 3-1-stable branch, exhibited on postgres 8.4.2 and 9.0.3.

Full output of bundle show: https://gist.github.com/154fa86952d70703c3ff

@jasonm
jasonm commented Sep 8, 2011

I actually just saw the error again, even monkeypatching #connect to re-use the same connection object, but it's intermittent.

@jasonm
jasonm commented Sep 8, 2011

I also occasionally see:

Validation failed: Last Name has already been taken (ActiveRecord::RecordInvalid)

as if a ROLLBACK between test cases didn't happen, or didn't happen at the right time. This is with the patch to re-use the same connection object.

@jasonm
jasonm commented Sep 8, 2011

We are using DatabaseCleaner with :transaction strategy.

Another thing that comes to mind, it may or may not be relevant that Capybara::Server (who opens the second PGconn) does so in a new Thread. https://github.com/jnicklas/capybara/blob/master/lib/capybara/server.rb#L64-66

@sorentwo
sorentwo commented Sep 8, 2011

I can confirm this same set of behaviors (it was rarely the same exact error twice, more often it rotated between 3-4 various database fields / validation errors). This was starting with Rails 3.1 beta 5.

Because it was beta I assumed the issue was with DatabaseCleaner / PG lagging, and ended up switching to SQLite for testing in the meantime.

Now I feel like a bad OS citizen.

@hgmnz
hgmnz commented Sep 8, 2011

(@jasonm and I are pairing on this)

We've removed the $global_pg_connection hack.

Another interesting fact: I see a BEGIN on the logs, but no COMMIT. This means that the first connection starts a transaction and writes a bunch of data in the test's setup (using DMA), but the second transaction queries the database for that data (say, render a page and expect to see stuff), but the data is not visible to it because the transaction that wrote it hasn't committed it, and the transaction isolation provided by postgres MVCC is making those rows invisible to the second transaction.

@jasonm
jasonm commented Sep 8, 2011

Just an update: we're still seeing this. We've tried to repro in a standalone app https://github.com/jasonm/rails-issue-2943-sample-app but haven't been able to yet.

@hgmnz
hgmnz commented Sep 9, 2011

Regarding my earlier comment, when using DatabaseCleaner's transaction strategy you'll never see a COMMIT during the execution of the test. ActiveRecord::ConnectionAdapters::DatabaseStatements detects that there is a running transaction and only ever emulates nested transactions with save points - sorry if this caused any indirection.

So, the transaction isolation issue I described above is more of a feature than a bug. I'm not sure why this didn't come up in this app when it was running rails 3.0.x, but using the truncate strategy instead solves that problem.

The issue continues to be mainly around mixing DMA and web interactions within a test.

@jasonm
jasonm commented Sep 12, 2011

cc @halogenandtoast @sikachu - discussed this in campfire and IRL today

@halogenandtoast

For the record this also happens with the :truncation strategy

@halogenandtoast

running bundle exec cucumber features/test.feature on https://github.com/halogenandtoast/rails-issue-2943-sample-app will either generate this error:

@javascript
  Scenario: Test failure                                # features/test.feature:4
    Given I am signed in as "user@example.com/password" # features/step_definitions/user_steps.rb:1
    And the following list exists:                      # factory_girl-2.1.0/lib/factory_girl/step_definitions.rb:99
      | title | user                   |
      | fails | email: foo@example.com |

 NoMethodError: undefined method `fields' for nil:NilClass:           SELECT DISTINCT(attr.attname)
            FROM pg_attribute attr
            INNER JOIN pg_depend dep ON attr.attrelid = dep.refobjid AND attr.attnum = dep.refobjsubid
            INNER JOIN pg_constraint cons ON attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1]
            WHERE cons.contype = 'p'
              AND dep.refobjid = $1::regclass
   (ActiveRecord::StatementInvalid)
  features/test.feature:6:in `And the following list exists:'

Failing Scenarios:
cucumber features/test.feature:4 # Scenario: Test failure

or it will lock up after the first step. Every now and then it will succeed so run it a few times.

Using
PostgreSQL 9.0.4 on x86_64-apple-darwin11.0.0, compiled by GCC i686-apple-darwin11-llvm-gcc-4.2 (GCC) 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2335.15.00), 64-bit

And pg (0.11.0)

@jasonm
jasonm commented Sep 13, 2011

Thanks, Matt. I can repro with that sample app, intermittently; sometimes it freezes, sometimes it gives that error, and sometimes it passes.

@tenderlove any thoughts on how we could move forward on this?

@tenderlove
Ruby on Rails member

@jasonm can you try this against the 3-1-stable branch? I've added some changes there that may impact this.

@jasonm
jasonm commented Sep 13, 2011

Hey @tenderlove thanks - I just bumped the sample app's Gemfile to 3-1-stable, but I still see the same issue. Still intermittent, still a handful of different errors that show up, although I hadn't seen this one yet:

[master][~/dev/rails-issue-2943-sample-app] bundle exec cucumber features/test.feature
Using the default profile...
DEPRECATION WARNING: class_inheritable_attribute is deprecated, please use class_attribute method instead. Notice their behavior are slightly different, so refer to class_attribute documentation first. (called from <class:Base> at /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-rails-1.0.4/lib/cucumber/rails/hooks/active_record.rb:3)
DEPRECATION WARNING: class_inheritable_attribute is deprecated, please use class_attribute method instead. Notice their behavior are slightly different, so refer to class_attribute documentation first. (called from <class:Base> at /Users/jason/.rvm/gems/ruby-1.9.2-p290/gems/cucumber-rails-1.0.4/lib/cucumber/rails/hooks/active_record.rb:3)
Feature: Test failure

  @javascript
  Scenario: Test failure                                # features/test.feature:4
    Given I am signed in as "user@example.com/password" # features/step_definitions/user_steps.rb:1
    And the following list exists:                      # factory_girl-2.1.0/lib/factory_girl/step_definitions.rb:99
      | title | user                   |
      | fails | email: foo@example.com |
      PGError: another command is already in progress
      : INSERT INTO "users" ("created_at", "current_sign_in_at", "current_sign_in_ip", "email", "encrypted_password", "last_sign_in_at", "last_sign_in_ip", "remember_created_at", "reset_password_sent_at", "reset_password_token", "sign_in_count", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12) RETURNING "id" (ActiveRecord::StatementInvalid)
      features/test.feature:6:in `And the following list exists:'

Failing Scenarios:
cucumber features/test.feature:4 # Scenario: Test failure

1 scenario (1 failed)
2 steps (1 failed, 1 passed)
0m1.871s
@jgn
jgn commented Sep 13, 2011

Changing the pool to 1 gets a consistent pass:

test: &test
adapter: postgresql
encoding: unicode
database: fails_test
pool: 1
username:
password:

@jasonm
jasonm commented Sep 13, 2011

Changing the pool size to 1 doesn't work - I consistently get a 500 response from the app to the test process, and the underlying exception is:

could not obtain a database connection within 5 seconds.  The max pool size is currently 1; consider increasing it.
@jgn
jgn commented Sep 13, 2011
@hgmnz
hgmnz commented Sep 13, 2011

I just confirmed that setting the pool size to 1 on the sample app did not fix the issue, and in the real app it completely breaks the suite as @jasonm mentioned.

@jasonm
jasonm commented Sep 13, 2011

Tail log/test.log and look for "Completed 500" responses. I've added logging into the ShowExceptions middleware https://gist.github.com/3a4f22fae0bc62041aa7 L59-66 that outputs the "could not obtain a database connection..."

@sorentwo
@jgn
jgn commented Sep 13, 2011

What is the fail looking like to you? I repeatedly get . . .

1 scenario (1 passed)
2 steps (2 passed)
0m6.591s

@jgn
jgn commented Sep 13, 2011

OK, I see it. Drag.

@jgn
jgn commented Sep 13, 2011

@hgimenez Have you noted your experience deallocating the cached statements?

@jasonm
jasonm commented Sep 15, 2011

@tenderlove hmm... any other ideas for moving forward? We've had to roll back to 3.0.10 - placing direct model access before web interactions in the cucumber suite ended up not resolving the issue; it still happens intermittently without that (it just seems like the most straightforward way to repro it in a small sample).

@rubiety
rubiety commented Sep 16, 2011

I'm also having this issue - just ran into it today. The problem for me is that it's very intermittent (less than half of the time), so hard to pin down. I haven't done any digging as deep as @jayunit but wanted to just point out the issue isn't specific to him or his environment.

@bwbuchanan

This may be an instance of cucumber/cucumber-rails#166

@jdelStrother

Might be worth pointing out that cucumber made some changes to shared_connection a couple of days ago here - cucumber/cucumber-rails@4e90fe0 - but I'm still skeptical that's the correct fix. I believe that approach has unresolvable threading problems, and ended up disabling that shared connection (cucumber/cucumber-rails#166 (comment)).

That said, I use the mysql & mysql2 adapter, so that may all be totally irrelevant to this particular issue.

@ClayShentrup

Any news from the devs on this? We can't upgrade to Rails 3.1 due to it (apparently).

@Metallord

I have the same problem on sqlite3 and mysql (mysql2 gem) using rspec. It seems that EVERY sql query is cached and doesn't return after each spec. So it runs slower and slower until it reaches the pool limit and then just throws too many connections exception. I will try doing ActiveRecord::Base.clear_stale_cached_connections! after each test later today, but even if it worked it would be just a workaround.

EDIT:

Ok, so ActiveRecord::Base.connection_handler.clear_all_connections! doesn't fix it. It helps a little but not much.

I cranked up the pool to 100 and ran the test suite with 'mysqladmin -u root -p processlist' in a separate terminal in the background. What I saw was pure serenity. Processes sleeping so calmly... Ok but seriously - each request added more such things:

| Id  | User | Host      | db   | Command | Time | State | Info             |
+-----+------+-----------+-----------+---------+------+-------+-------------+
| 886 | root | localhost | test | Sleep   | 9    |       |                  |

Around 10 per request, but the number wasn't consistent. This also happens in development btw. Someone please check if it is a symptom of this issue or something else. Also disabling images in the browser decreased the number of these sleepers significantly...

@ClayShentrup

I had what I thought was the same issue, and this was the offending commit. Reverting it got my tests green again.

cucumber/cucumber-rails@30e5e36

@Metallord

So anybody else getting the sleeping processes in mysql, or should I keep looking?

@jasonm
jasonm commented Nov 4, 2011

My original issue is addressed by the resolution in cucumber/cucumber-rails#166 and cucumber/cucumber-rails#182 and not a rails issue.

I've forked @halogenandtoast's app that reproduces the issue, updated cucumber-rails to the git master, included the following in my cucumber features/support/env.rb:

Cucumber::Rails::Database.javascript_strategy = :truncation

and it passes consistently. Fork pushed here: https://github.com/jasonm/rails-issue-2943-sample-app-1

If folks are encountering other bugs, they should be split out into other issues.

@jasonm jasonm closed this Nov 4, 2011
@woahdae
woahdae commented Nov 9, 2011

Note that this is carry-over from this mysql2 issue and not related to cucumber. I'm experiencing this in staging (read: faux production settings).

This mysql2 issue might now be an AR issue due to Rails 3.1 taking over the Mysql2 adapter, and has yet to be solved or reliably replicated (am trying myself).

For now it's worth noting that the app I'm experiencing it on does connection manipulation during the request cycle, and this issue seems to be a race condition.

On line 687:

...
result = @connection.query(sql)
...

result is sometimes coming back nil, but in a debugger after that line, re-querying returns a result. Given that, it's might also be a mysql2 issue, depending on whether that's expected behavior or not given the default Rails configuration.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.