search

teampoltergeist / poltergeist

A PhantomJS driver for Capybara
MIT License
2.5k stars 414 forks source link

[Capybara::Poltergeist::TimeoutError] Another brick. #656

Closed charlespernet closed 9 years ago

charlespernet commented 9 years ago

Hey, i'am bringing another Timeout issue. I know that the topic had been spoken many times, I've already read the threads. I already tried to precompile my assets in Test environment and extend the timeout option.

By the way I noticed something really strange that I haven't seen in any previous post. Whenever I run my tests for the first time, like after a computer reboot, the first test passes, the second one timeout. The strangest part is that if I run the same test file a second time immediately after, the first test will Timeout...

Another information is that these tests were all passing few days ago, and i didn't upgrade my rails or ruby version from that time.

just after reboot

capture d ecran 2015-09-21 a 15 49 50

few seconds after

capture d ecran 2015-09-21 a 15 51 00

This error looks hard to reproduce, one colleague here doesn't meet the issue...

here is my test, even if it's very basic

require'rails_helper'

feature 'MoralPerson visits dashboard' do
  before(:each) do
    @moral_person = create(:moral_person, :confirmed)
    @moral_person.update(password: 'plopplop', password_confirmation: 'plopplop')

    visit user_session_path
    fill_in 'user_email', with: @moral_person.email
    fill_in 'user_password', with: 'plopplop'
    click_on 'Connexion'
  end

  scenario 'a MoralPerson visits his profile' do
    click_link('Mon profil')
    expect(page).to have_content 'MON ENTREPRISE'
  end

  scenario 'a MoralPerson visits his wallet' do
    VCR.use_cassette('dashboard/moral_person_wallet') do
      click_link('Mon Portefeuille')
    end
    expect(page).to_not have_content 'Avant acompte sur Impôt  sur le  revenu  (24%) et prélèvements sociaux (15,5%)'
  end

  scenario 'a MoralPerson visits his contacts' do
    click_link('Mes coordonnées')
    expect(page).to have_content 'MON SIÈGE SOCIAL'
  end
end

ruby version ruby 2.1.2p95 (2014-05-08 revision 45877) [x86_64-darwin14.0]

rails version Rails 4.1.6

It's my first issue submission so I hope I included every information needed. I am not sure about how to use the remote debugging tool in this case, I tried to include it but nothing changed, and I don't have any more logs to include.

I am conscious that this issue had been posted many times before but didn't find anything helpful, I hope that my contribution can help others.

I am here to bring any other information if you think something is lacking.

Thank you for the time spent reading my issue.

Here are the tests logs :

(0.2ms)  BEGIN
  SQL (1.3ms)  INSERT INTO `companies` (`banner_brand`, `capital_currency`, `commercial_court`, `created_at`, `legal_form`, `name`, `share_capital`, `siren`, `updated_at`) VALUES ('Fournier et Roussel', 'Rolland GIE', 'Lefebvre et Laurent', '2015-09-21 14:24:12', 'EIRL', 'Prevost et Breton', 'Remy et Gonzalez', '347 355 708 00224', '2015-09-21 14:24:12')
   (0.8ms)  COMMIT
   (0.2ms)  BEGIN
  SQL (0.2ms)  INSERT INTO `addresses` (`city`, `country`, `created_at`, `post_code`, `street`, `updated_at`) VALUES ('Dunkerque14', 'France', '2015-09-21 14:24:12', '20710', 'Passage Joubert', '2015-09-21 14:24:12')
   (0.3ms)  COMMIT
   (0.1ms)  BEGIN
  User Exists (0.3ms)  SELECT  1 AS one FROM `users`  WHERE `users`.`email` = BINARY 'noah@bernard.eu' LIMIT 1
  Stamp Load (0.5ms)  SELECT  `stamps`.* FROM `stamps`  WHERE `stamps`.`name` = 'moral_people' LIMIT 1
  Stamp Load (0.4ms)  SELECT  `stamps`.* FROM `stamps`  WHERE `stamps`.`name` = 'moral_people' LIMIT 1
  SQL (0.3ms)  INSERT INTO `stamps` (`created_at`, `name`, `updated_at`, `value`) VALUES ('2015-09-21 14:24:13', 'moral_people', '2015-09-21 14:24:13', 0)
  Stamp Load (0.3ms)  SELECT  `stamps`.* FROM `stamps`  WHERE `stamps`.`id` = 1 LIMIT 1 FOR UPDATE
  SQL (0.4ms)  UPDATE `stamps` SET `updated_at` = '2015-09-21 14:24:13', `value` = 1 WHERE `stamps`.`id` = 1
  SQL (0.3ms)  INSERT INTO `users` (`accept_smoney_terms`, `accepts_terms`, `birthdate`, `civility`, `confirmed_at`, `created_at`, `email`, `encrypted_password`, `first_name`, `last_name`, `mobile_phone`, `phone`, `pseudo`, `type`, `uniq_stamp`, `updated_at`) VALUES (1, 1, '1991-02-01', 0, '2015-09-21 14:24:12', '2015-09-21 14:24:12', 'noah@bernard.eu', '$2a$04$tVIp1Lz4GMnf5yD6EUQ1XujpYyoQQOkWP9SY6pJEPp9P8bRw0aLfK', 'Jeanne', 'Martin', '+33783589442', '+33 7 83 58 94 42', 'JeanneM', 'MoralPerson', 'MP1', '2015-09-21 14:24:12')
  SQL (0.3ms)  UPDATE `addresses` SET `updated_at` = '2015-09-21 14:24:13', `user_id` = 1 WHERE `addresses`.`id` = 1
  SQL (0.3ms)  UPDATE `companies` SET `owner_id` = 1, `owner_type` = 'User', `updated_at` = '2015-09-21 14:24:13' WHERE `companies`.`id` = 1
  User Exists (0.6ms)  SELECT  1 AS one FROM `users`  WHERE (`users`.`email` = BINARY 'noah@bernard.eu' AND `users`.`id` != 1) LIMIT 1
  SQL (0.4ms)  UPDATE `users` SET `accept_smoney_terms` = 1, `accepts_terms` = 1, `birthdate` = '1991-02-01', `civility` = 0, `confirmed_at` = '2015-09-21 14:24:12', `created_at` = '2015-09-21 14:24:12', `email` = 'noah@bernard.eu', `encrypted_password` = '$2a$04$tVIp1Lz4GMnf5yD6EUQ1XujpYyoQQOkWP9SY6pJEPp9P8bRw0aLfK', `first_name` = 'Jeanne', `id` = 1, `last_name` = 'Martin', `mobile_phone` = '+33783589442', `phone` = '+33 7 83 58 94 42', `pseudo` = 'JeanneM', `smoney_generated_id` = 'CR-F', `type` = 'MoralPerson', `uniq_stamp` = 'MP1', `updated_at` = '2015-09-21 14:24:12' WHERE `users`.`id` = 1
   (1.3ms)  COMMIT
   (0.1ms)  BEGIN
  SQL (0.5ms)  UPDATE `users` SET `encrypted_password` = '$2a$04$nnir9o2hMQF3EEXdDLzH5.ufn8QA1jF2Ut.mRPZt5kn3fEAiiDrwW', `updated_at` = '2015-09-21 14:24:13' WHERE `users`.`id` = 1
   (0.5ms)  COMMIT
Started GET "/users/sign_in" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Processing by Devise::SessionsController#new as HTML
  Rendered components/_flash.html.erb (0.8ms)
  Rendered devise/shared/_links.html.erb (1.1ms)
  Rendered devise/sessions/new.html.erb within layouts/application (41.4ms)
  Rendered layouts/_modal_login.html.erb (2.6ms)
  Rendered layouts/_modal_signup.html.erb (4.1ms)
  Rendered layouts/_modal_newsletter.html.erb (0.7ms)
  Rendered layouts/_header.html.erb (19.8ms)
  Rendered layouts/_footer_script.html.erb (1.1ms)
  Rendered layouts/_footer.html.erb (4.4ms)
  Rendered scripts/_google_tag_manager.html.erb (0.7ms)
  Rendered scripts/_main.html.erb (2.3ms)
Completed 200 OK in 136ms (Views: 100.4ms | ActiveRecord: 0.0ms)
Started GET "/assets/application.css" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/modernizr.custom.js" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/footer_script.js" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/footer_stylesheet.css" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/logo-top-white-slogan.png" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/logo-credit-fr.png" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/logo-top-white.png" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/macaron_pfp_2015.png" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/logo_pfp_blanc.png" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/RobotoSlab-Regular-webfont.woff" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/RobotoSlab-Bold-webfont.woff" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/RobotoSlab-Light-webfont.woff" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/RobotoSlab-Thin-webfont.woff" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/Montserrat-Regular-webfont.woff" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/Montserrat-Bold-webfont.woff" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/fontawesome-webfont.woff?v=4.4.0" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started GET "/assets/bkg.jpg" for 127.0.0.1 at 2015-09-21 16:24:18 +0200
Started POST "/users/sign_in" for 127.0.0.1 at 2015-09-21 16:24:31 +0200Processing by Devise::SessionsController#create as HTML
  Parameters: {"utf8"=>"✓", "user"=>{"email"=>"noah@bernard.eu", "password"=>"[FILTERED]", "remember_me"=>"0"}, "commit"=>"Connexion"}
  User Load (0.4ms)  SELECT  `users`.* FROM `users`  WHERE `users`.`email` = 'noah@bernard.eu'  ORDER BY `users`.`id` ASC LIMIT 1
   (0.1ms)  BEGIN
  Address Load (0.3ms)  SELECT  `addresses`.* FROM `addresses`  WHERE `addresses`.`user_id` = 1 LIMIT 1
  SQL (0.5ms)  UPDATE `users` SET `current_sign_in_at` = '2015-09-21 14:24:31', `current_sign_in_ip` = '127.0.0.1', `last_sign_in_at` = '2015-09-21 14:24:31', `last_sign_in_ip` = '127.0.0.1', `sign_in_count` = 1, `updated_at` = '2015-09-21 14:24:31' WHERE `users`.`id` = 1
   (0.6ms)  COMMIT
Redirected to http://127.0.0.1:54727/tableau-de-bord/synthese
Completed 302 Found in 81ms (ActiveRecord: 6.2ms)
Started GET "/tableau-de-bord/synthese" for 127.0.0.1 at 2015-09-21 16:24:31 +0200
Processing by AccountsController#synthesis as HTML
  User Load (0.5ms)  SELECT  `users`.* FROM `users`  WHERE `users`.`id` = 1  ORDER BY `users`.`id` ASC LIMIT 1
  Rendered components/_flash.html.erb (0.3ms)
  -- MISSING METHOD on #<MoralPerson:0x007ffc11d47168> = type
  Rendered components/dashboard/_sleeping_money.html.erb (0.9ms)
   (0.5ms)  SELECT SUM(`pledges`.`amount`) AS sum_id FROM `pledges` INNER JOIN `campaigns` ON `campaigns`.`id` = `pledges`.`campaign_id` LEFT OUTER JOIN `campaigns` `campaigns_pledges_join` ON `campaigns_pledges_join`.`id` = `pledges`.`campaign_id` LEFT OUTER JOIN `loan_requests` ON `loan_requests`.`id` = `campaigns_pledges_join`.`loan_request_id` LEFT OUTER JOIN `project_pages` ON `project_pages`.`loan_request_id` = `loan_requests`.`id` LEFT OUTER JOIN `users` ON `users`.`id` = `loan_requests`.`project_owner_id` AND `users`.`type` IN ('ProjectOwner') WHERE `pledges`.`contributor_id` = 1 AND `campaigns`.`is_active` = 1
  Rendered components/dashboard/_balance_blocked_money.html.erb (15.6ms)
   (0.4ms)  SELECT COUNT(*) FROM `loan_contributions`  WHERE `loan_contributions`.`contributor_id` = 1
   (0.3ms)  SELECT SUM(`loan_contributions`.`amount`) AS sum_id FROM `loan_contributions`  WHERE `loan_contributions`.`contributor_id` = 1
  LoanContribution Load (0.3ms)  SELECT `loan_contributions`.* FROM `loan_contributions`  WHERE `loan_contributions`.`contributor_id` = 1
  CACHE (0.0ms)  SELECT `loan_contributions`.* FROM `loan_contributions`  WHERE `loan_contributions`.`contributor_id` = 1  [["contributor_id", 1]]
  Rendered components/dashboard/_wallet_default_analysis.html.erb (16.7ms)
  Rendered dashboard/moral_people/synthesis.html.erb within layouts/account (99.3ms)
  -- MISSING METHOD on #<MoralPerson:0x007ffc11d47168> = email
  -- MISSING METHOD on #<MoralPerson:0x007ffc11d47168> = remember_me
  Rendered layouts/_modal_login.html.erb (2.9ms)
  -- MISSING METHOD on #<MoralPerson:0x007ffc11d47168> = email
  -- MISSING METHOD on #<MoralPerson:0x007ffc11d47168> = remember_me
  Rendered layouts/_modal_signup.html.erb (3.4ms)
  Rendered layouts/_modal_newsletter.html.erb (0.2ms)
  Rendered layouts/_header.html.erb (28.4ms)
  Rendered layouts/_account_menu.html.erb (8.4ms)
  Rendered layouts/_footer_script.html.erb (0.3ms)
  Rendered layouts/_footer.html.erb (1.8ms)
Completed 200 OK in 259ms (Views: 135.3ms | ActiveRecord: 12.3ms)
charlespernet commented 9 years ago

Hi again, after a whole afternoon tracking the issue, I discovered that the problem came from my phantomjs version ... It was not up to date ...

If you have any issue with Poltergeist timing out, just double check your phantomjs version. It's like I've lost an entire day trying to figure it out...

I hope I could save someone's else