Timing of test failure output

Skip to first unread message

Jack Royal-Gordon

Apr 5, 2021, 11:42:51 AMApr 5
to rs...@googlegroups.com
In troubleshooting a system test that is failing, the debugging output from my controller is mixed in with RSpec’s output. I’m guessing that has to do with RSpec capturing terminal output, but it has me wondering if the test is failing before the code has a chance to complete.

The test is of a drag-and-drop operation on screen that results in an Ajax call to the app, followed by activity on screen once the Ajax call completes successfully. The ajax call deletes one record and moves it’s children to another record. I added two debugging statements: one at the beginning of the controller action, dumping the params, and the other after the database changes have been made, stating that the parent record has been deleted. The output looks as follows:

Source = 38347; target = 38360


  1) SKUs Screen Draggable and Droppable actions when dragging and droppng a book on another book with confirmation updates the database correctly
     Failure/Error: expect(source.reload).to be_destroyed, "Source book not destroyed"
       Source book not destroyed
     params: <ActionController::Parameters {"verb"=>"MoveBook", "source_id"=>"book_38347", "dest_id"=>"book_38360", "ts"=>"1617589502334", "controller"=>"books", "action"=>"modify", "format"=>"js"} permitted: false>
book deleted
[Screenshot]: tmp/screenshots/failures_r_spec_example_groups_sk_us_screen_draggable_and_droppable_actions_when_dragging_and_droppng_a_book_on_another_book_with_confirmation_updates_the_database_correctly_752.png

The green highlighted text is output by the test spec before it really gets going. The other two highlighted segments of text are the two troubleshooting outputs from the controller action called via Ajax. Note that they are output after the failure message and before the screen shot message. I find this extremely suspicious. Can I conclude from this that the test failed before the controller action had a chance to run?

FWIW, here is the test (there is other setup code above this, but nothing that should affect the flow through the test (the second “it” is the one causing the failure — the first one succeeds):

    describe "when dragging and droppng a book on another book" do
      let!(:source) { user.books.first }
      let!(:target) { user.books.second }
      let!(:source_control) { page.find("#book_#{source.id} .book_title label") }
      let!(:target_control) { page.find("#book_#{target.id}") }
      let!(:source_skus) { source.skus.map(&:id).to_set }
      let!(:target_skus) { target.skus.map(&:id).to_set }

      describe "with confirmation" do
        before do
          puts "Source = #{source.id}; target = #{target.id}"
          accept_confirm do
        it 'changes the display correctly' do
          expect(page).to_not have_selector("#book_#{source.id}"), "Source book still exists on page"
          for sku in source.skus
            expect(page).to have_selector("#book_#{target.id} #sku_#{sku.id}"), "Source SKU not found within target book"
        it 'updates the database correctly' do
          expect(source.reload).to be_destroyed, "Source book not destroyed"
          new_target_skus = target.skus.reload.map(&:id).to_set
          expect(new_target_skus).to include(*source_skus), "Some Source SKUs not moved to target"
          expect(new_target_skus).to include(*target_skus), "Some target SKUs lost during the move"

Note: When the drop occurs, a “confirm” modal dialog is displayed requiring the user to confirm the operation.

Phil Pirozhkov

Apr 5, 2021, 1:51:16 PMApr 5
to Jack Royal-Gordon
You can check by using `STDOUT.puts` if you're debugging.
I personally prefer sticking `binding.pry` here and there from `pry-byebug` gem
> --
> You received this message because you are subscribed to the Google Groups "rspec" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to rspec+un...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/rspec/8004A377-5FB4-4F70-A740-C2F70E8F09B2%40pobox.com.

Jack Royal-Gordon

Apr 6, 2021, 2:15:01 PMApr 6
to rs...@googlegroups.com
Thanks, Phil. I’m going to have to spend some time groking pry so I can add it to my box of tools.

The underlying issue turned out to be a timing problem that was easily solved by adding “wait_for_ajax” after the #drag_to call.
> To view this discussion on the web visit https://groups.google.com/d/msgid/rspec/CAAk5Ok_K4taBvMDAN4%2BrLPQJxy57AFo6VPmvc6yzgNmbw%2BQVBQ%40mail.gmail.com.

Reply all
Reply to author
0 new messages