Back
Chapters

Debugging test failures

Search icon
Search Book
⌘K

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.