Timing of test failure output

[Jack Royal-Gordon]

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
F

Failures:

  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

            source_control.drag_to(target_control)

          end

        end

      

        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"

          end

        end

      

        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"

        end

      end

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

[Phil Pirozhkov]

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]

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.