Search
⌘K
    to navigateEnterto select Escto close

    Debugging test failures

    While running all the test cases there are chances some might fail. In this chapter we take a look at the tools that we can use to debug our code to figure out why the failure occurred and to fix it.

    Let's run a test file which has been taken from the "granite" application, but has been modified to make sure some test cases will fail for debugging purposes.

    The following are the different failures that we may encounter:

    1$ bundler exec rails test test/models/task_test.rb
    2Running via Spring preloader in process 85217
    3Run options: --seed 40122
    4
    5# Running:
    6
    7A task was created with the following title: Et laboriosam aliquam vero.
    8A task was created with the following title: test task
    9A task was created with the following title: test task
    10F
    11
    12Failure:
    13TaskTest#test_incremental_slug_generation_for_tasks_with_duplicate_two_worded_titles [/Users/mre/bb/granite/test/models/task_test.rb:51]:
    14Expected: "test-task-22"
    15  Actual: "test-task-2"
    16
    17
    18rails test test/models/task_test.rb:47
    19
    20A task was created with the following title: Voluptatem molestiae enim sed.
    21F
    22
    23Failure:
    24TaskTest#test_task_slug_is_parameterized_title [/Users/mre/bb/granite/test/models/task_test.rb:44]:
    25--- expected
    26+++ actual
    27@@ -1 +1 @@
    28-"voluptatem-molestiae-enim-sed "
    29+"voluptatem-molestiae-enim-sed"
    30
    31
    32
    33rails test test/models/task_test.rb:41
    34
    35A task was created with the following title: Ut qui sed minima.
    36.A task was created with the following title: Minus enim et perferendis.
    37A task was created with the following title: buy 2 apples
    38A task was created with the following title: buy
    39.A task was created with the following title: Cum aut eos porro.
    40A task was created with the following title: Fugiat explicabo consequuntur qui.
    41.A task was created with the following title: Fugit commodi nihil asperiores.
    42A task was created with the following title: test-task
    43A task was created with the following title: test-task
    44A task was created with the following title: test-task
    45A task was created with the following title: test-task
    46A task was created with the following title: test-task
    47.A task was created with the following title: Aut ut atque in.
    48A task was created with the following title: another test task
    49.A task was created with the following title: Excepturi omnis laborum molestiae.
    50A task was created with the following title: buy milk and apple
    51A task was created with the following title: buy milk
    52.A task was created with the following title: Reiciendis consequatur recusandae qui.
    53A task was created with the following title: test-task
    54A task was created with the following title: test-task
    55F
    56
    57Failure:
    58TaskTest#test_incremental_slug_generation_for_tasks_with_duplicate_hyphenated_titles [/Users/mre/bb/granite/test/models/task_test.rb:59]:
    59Expected: "test-task-23"
    60  Actual: "test-task-2"
    61
    62
    63rails test test/models/task_test.rb:54
    64
    65A task was created with the following title: Aut iste molestias veniam.
    66.A task was created with the following title: Aut at omnis dolores.
    67A task was created with the following title: This is a test task
    68.A task was created with the following title: Ab quia rerum est.
    69.A task was created with the following title: Debitis error tempora magnam.
    70A task was created with the following title: fishing
    71A task was created with the following title: fish
    72F
    73
    74Failure:
    75TaskTest#test_slug_generation_for_tasks_having_titles_one_being_prefix_of_the_other [/Users/mre/bb/granite/test/models/task_test.rb:67]:
    76Expected: "fishh"
    77  Actual: "fish"
    78
    79
    80rails test test/models/task_test.rb:62
    81
    82
    83
    84Finished in 0.590504s, 22.0151 runs/s, 47.4171 assertions/s.
    8513 runs, 28 assertions, 4 failures, 0 errors, 0 skips

    Here on the final line of the output we get an summary of the test we ran, we can see 28 assertions where made in 13 runs (which means 13 functions were executed) and in which 4 assertions failed.

    It's easier to fix the failures when we can take a look at it one by one. Rails provides us an easy a way to do this. Lets look at the output we got from running the test again.

    1# previous test case outputs
    2...
    3Failure:
    4TaskTest#test_slug_generation_for_tasks_having_titles_one_being_prefix_of_the_other [/Users/mre/bb/granite/test/models/task_test.rb:67]:
    5Expected: "fishh"
    6  Actual: "fish"
    7
    8
    9rails test test/models/task_test.rb:62
    10
    11
    12
    13Finished in 0.590504s, 22.0151 runs/s, 47.4171 assertions/s.
    1413 runs, 28 assertions, 4 failures, 0 errors, 0 skips

    Running an single test

    In the above code snippet shown in last section, the highlighted line shows a line number after the file name. If we take a look at task_test.rb we can see that line 62 is the start of the test function which failed:

    Test Function

    By running rails test test/models/task_test.rb:62 we can see that rails runs only the method corresponding to the line number mentioned:

    1$ bundler exec rails test test/models/task_test.rb:62
    2Running via Spring preloader in process 93088
    3Run options: --seed 7633
    4
    5# Running:
    6
    7A task was created with the following title: Reiciendis molestias nulla commodi.
    8A task was created with the following title: fishing
    9A task was created with the following title: fish
    10F
    11
    12Failure:
    13TaskTest#test_slug_generation_for_tasks_having_titles_one_being_prefix_of_the_other [/Users/mre/bb/granite/test/models/task_test.rb:67]:
    14Expected: "fishh"
    15  Actual: "fish"
    16
    17rails test test/models/task_test.rb:62
    18
    19Finished in 0.234019s, 4.2732 runs/s, 8.5463 assertions/s.
    201 runs, 2 assertions, 1 failures, 0 errors, 0 skips

    Here from the final line of the output we understand that only "1" test ran which had "2" assertions and "1" failed. If we take a look at the function definition we can see the second assertion failed here.

    Now we know where exactly the issue is and what the expected and actual values are. Sometimes it might not be obvious from the failure details and we might need to do a deeper analysis.

    Debugging using puts

    From the test we know that we are calling Task.create!. Lets navigate to where the actual method is written. There we can add puts statements to figure out what might have gone wrong. This is more or less a hacky way of getting the job done.

    Here we need to add puts statements to test/models/task_test.rb:

    1  before_create :set_slug
    2
    3  private
    4
    5    def set_slug
    6      title_slug = title.parameterize
    7      regex_pattern = "slug #{Constants::DB_REGEX_OPERATOR} ?"
    8      latest_task_slug = Task.where(
    9        regex_pattern,
    10        "#{title_slug}$|#{title_slug}-[0-9]+$").order(slug: :desc).first&.slug
    11      slug_count = 0
    12      if latest_task_slug.present?
    13        slug_count = latest_task_slug.split("-").last.to_i
    14        only_one_slug_exists = slug_count == 0
    15        slug_count = 1 if only_one_slug_exists
    16      end
    17      slug_candidate = slug_count.positive? ? "#{title_slug}-#{slug_count + 1}" : title_slug
    18      puts "DEBUGGING:" + slug_candidate
    19      self.slug = slug_candidate
    20    end

    By adding the above statement, the value of the puts statement is now printed when we run the test again:

    1
    2$ bundler exec rails test test/models/task_test.rb:62
    3Running via Spring preloader in process 96740
    4Run options: --seed 34992
    5
    6# Running:
    7
    8DEBUGGING:cupiditate-rerum-suscipit-voluptatem
    9A task was created with the following title: Cupiditate rerum suscipit voluptatem.
    10DEBUGGING:fishing
    11A task was created with the following title: fishing
    12DEBUGGING:fish
    13A task was created with the following title: fish
    14F
    15
    16Failure:
    17TaskTest#test_slug_generation_for_tasks_having_titles_one_being_prefix_of_the_other [/Users/mre/bb/granite/test/models/task_test.rb:67]:
    18Expected: "fishh"
    19  Actual: "fish"
    20
    21
    22rails test test/models/task_test.rb:62
    23
    24
    25
    26Finished in 0.248429s, 4.0253 runs/s, 8.0506 assertions/s.
    271 runs, 2 assertions, 1 failures, 0 errors, 0 skips

    From the logs it is evident that it is a spelling mistake that caused the test suite to fail. But this puts method becomes a hassle if we want to try change or view multiple variable values. And more importantly we should never commit code which has puts statements.

    Debugging using byebug

    To achieve the same result as the above method we can also use the byebug gem to get a more powerful and interactive way to debug.

    Example:

    1    def set_slug
    2      title_slug = title.parameterize
    3      regex_pattern = "slug #{Constants::DB_REGEX_OPERATOR} ?"
    4      latest_task_slug = Task.where(
    5        regex_pattern,
    6        "#{title_slug}$|#{title_slug}-[0-9]+$").order(slug: :desc).first&.slug
    7      slug_count = 0
    8      if latest_task_slug.present?
    9        slug_count = latest_task_slug.split("-").last.to_i
    10        only_one_slug_exists = slug_count == 0
    11        slug_count = 1 if only_one_slug_exists
    12      end
    13      slug_candidate = slug_count.positive? ? "#{title_slug}-#{slug_count + 1}" : title_slug
    14      byebug
    15      self.slug = slug_candidate
    16    end
    17
    

    The debugger will run byebug which is a gem which has been already installed. This gem requires no additional configuration. Now when we run the test:

    1$ bundler exec rails test test/models/task_test.rb:62
    2Running via Spring preloader in process 2977
    3Run options: --seed 32115
    4
    5# Running:
    6
    7[31, 40] in /Users/mre/bb/granite/app/models/task.rb
    8   31:         only_one_slug_exists = slug_count == 0
    9   32:         slug_count = 1 if only_one_slug_exists
    10   33:       end
    11   34:       slug_candidate = slug_count.positive? ? "#{title_slug}-#{slug_count + 1}" : title_slug
    12   35:       byebug
    13=> 36:       self.slug = slug_candidate
    14   37:     end
    15   38:
    16   39:     def slug_not_changed
    17   40:       if slug_changed? && self.persisted?
    18(byebug)

    We can see that byebug has set a breakpoint right after the line where we specified byebug.

    Let's say we want to print the current value of the variable slug_candidate. For such cases we can just enter it to the terminal and we will get the output in the current scope's context:

    1(byebug) slug_candidate
    2"fish"
    3(byebug)

    We can also change the value of variables by:

    1(byebug) slug_candidate= "fishh"
    2"fishh"
    3(byebug)

    byebug gem has a lot of options which we can see by using the help command. Some useful ones to know are:

    1. continue - it runs until the next breakpoint is reached or the program is terminated.
    2. var local - it shows all the local variable in current scope.
    3. break LINE_NO - it sets additional breakpoint in LINE_NO.
    Previous
    Next