Skip to content

Latest commit

 

History

History
245 lines (176 loc) · 12.4 KB

Debug-backend-tests.md

File metadata and controls

245 lines (176 loc) · 12.4 KB
Raw

Table of contents

Introduction

When your backend tests fail, the strategies below can help you figure out how to fix them. We recommend the following workflow:

  1. Look at the log output to understand what it means.
  2. Find the test that failed and examine its code.
  3. Run the failing test in isolation so that you can iterate more quickly.
  4. Use print statements and/or the Python debugger to investigate further.

Interpret log output

When your backend tests fail, look near the end of the log for output that looks like this:

======================================================================
FAIL: test_failed_api_call_logs_the_exception (jobs.jobs_manager_test.RefreshStateOfBeamJobRunModelTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/runner/work/oppia/oppia/jobs/jobs_manager_test.py", line 158, in test_failed_api_call_logs_the_exception
    lambda: jobs_manager.refresh_state_of_beam_job_run_model(
  File "/home/runner/work/oppia/oppia/core/tests/test_utils.py", line 1306, in assertRaisesRegexp
    expected_exception, expected_regex, *args, **kwargs)
AssertionError: Exception not raised by <lambda>

---------------------------------------------------------------------

This is the part of the log that you should pay attention to. It tells you which test failed and why the failure occurred. Here's how to read it:

  • At the top, the line beginning with FAIL tells you which test failed. In this case, it's the test_failed_api_call_logs_the_exception test in the jobs.jobs_manager_test.RefreshStateOfBeamJobRunModelTests class. Note that this line can also start with ERROR. FAIL indicates that an assertion failed, while ERROR indicates that an exception (other than AssertionError) was raised unexpectedly.

  • Next is the traceback. This shows you the state of the stack when the error was raised. In this example:

    • The AssertionError was raised by line 1306 of test_utils.py in the assertRaisesRegexp() function.
    • That assertRaisesRegexp() function was called on line 158 of jobs_manager_test.py in the test_failed_api_call_logs_the_exception() function. Since this is the function defining our test, it's the end of the trace.

  • Lastly, the line starting with AssertionError describes what caused the test to fail. In this case, it's because we expected an exception to be raised, but that didn't happen.

Find tests

You usually want to look at the full code of the failing test to better understand what could have gone wrong. Unittest, the Python testing framework we use, makes this really easy: the description of which test failed also tells us exactly where to find it. In the example above, we saw this line:

FAIL: test_failed_api_call_logs_the_exception (jobs.jobs_manager_test.RefreshStateOfBeamJobRunModelTests)

This means that the full dotted name of the failing test function is:

jobs.jobs_manager_test.RefreshStateOfBeamJobRunModelTests.test_failed_api_call_logs_the_exception

In Python, the first part of a dotted name describes a file path. In this case, the jobs at the start of the name refers to the jobs/ folder at the root of the repository. Inside that folder is jobs_manager_test.py, which matches the jobs_manager_test part of the dotted name. (Notice that the .py extension of the file name disappeared.)

Now that we've reached a file, the rest of the dotted name refers to Python attributes. The jobs_manager_test.py file defines the RefreshStateOfBeamJobRunModelTests class, which has a test_failed_api_call_logs_the_exception method. This is the method that defines our test!

Run tests in isolation

When you know which test is causing you problems, running it in isolation can help you debug. For one thing, the tests will run much faster if you only run a few in isolation. Further, the console output from the test run will be much easier to understand.

To run a test in isolation, you can use the --test_target option:

python -m scripts.run_backend_tests --test_target jobs.jobs_manager_test.RefreshStateOfBeamJobRunModelTests.test_failed_api_call_logs_the_exception

If you wanted to run all the tests defined by the RefreshStateOfBeamJobRunModelTests, you could do that too. Just shorten the dotted name to end at the class:

python -m scripts.run_backend_tests --test_target jobs.jobs_manager_test.RefreshStateOfBeamJobRunModelTests

Note that if you want to run all the tests in a directory, you need to use --test_path instead like this:

python -m scripts.run_backend_tests --test_path jobs

Make sure that you can reproduce the problem you are trying to debug when you run the test in isolation! While rare, it is possible for a test failure to have been caused by previous tests. In these cases, you may not be able to reproduce the problem when you only run the test that initially failed.

Increase verbosity

Normally, we suppress any console output from passing tests, so even if you add print statements for debugging, you'll only see a success message:

[datastore] Sep 19, 2021 3:30:21 PM io.gapi.emulators.grpc.GrpcServer$3 operationComplete
[datastore] INFO: Adding handler(s) to newly registered Channel.
[datastore] Sep 19, 2021 3:30:21 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
[datastore] INFO: Detected HTTP/2 connection.
19:30:23 FINISHED scripts.run_e2e_tests_test.RunE2ETestsTests.test_is_oppia_server_already_running_when_ports_closed: 22.1 secs
Stopping Redis Server(name="redis-server", pid=37086)...
Stopping Cloud Datastore Emulator(name="python2.7", pid=37069)...

+------------------+
| SUMMARY OF TESTS |
+------------------+

SUCCESS   scripts.run_e2e_tests_test.RunE2ETestsTests.test_is_oppia_server_already_running_when_ports_closed: 1 tests (1.2 secs)

Ran 1 test in 1 test class.
All tests passed.

However if you pass the --verbose flag when running the backend tests, you'll see console output. For example, here we added a print('HELLO THERE') statement to the test:

[datastore] Sep 19, 2021 3:32:28 PM io.gapi.emulators.grpc.GrpcServer$3 operationComplete
[datastore] INFO: Adding handler(s) to newly registered Channel.
[datastore] Sep 19, 2021 3:32:28 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
[datastore] INFO: Detected HTTP/2 connection.
19:32:30 LOG scripts.run_e2e_tests_test.RunE2ETestsTests.test_is_oppia_server_already_running_when_ports_closed:
HELLO THERE
test_is_oppia_server_already_running_when_ports_closed (scripts.run_e2e_tests_test.RunE2ETestsTests) ... ok

----------------------------------------------------------------------
Ran 1 test in 1.455s

OK
----------------------------------------
19:32:30 FINISHED scripts.run_e2e_tests_test.RunE2ETestsTests.test_is_oppia_server_already_running_when_ports_closed: 26.3 secs
Stopping Redis Server(name="redis-server", pid=37294)...
Stopping Cloud Datastore Emulator(name="python2.7", pid=37277)...

+------------------+
| SUMMARY OF TESTS |
+------------------+

SUCCESS   scripts.run_e2e_tests_test.RunE2ETestsTests.test_is_oppia_server_already_running_when_ports_closed: 1 tests (1.5 secs)

Ran 1 test in 1 test class.
All tests passed.

If a test fails, you'll always see its console output:

[datastore] Sep 19, 2021 3:34:41 PM io.gapi.emulators.grpc.GrpcServer$3 operationComplete
[datastore] INFO: Adding handler(s) to newly registered Channel.
[datastore] Sep 19, 2021 3:34:41 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
[datastore] INFO: Detected HTTP/2 connection.
19:34:42 ERROR scripts.run_e2e_tests_test.RunE2ETestsTests.test_is_oppia_server_already_running_when_ports_closed: 21.1 secs
Error 1
HELLO THERE
test_is_oppia_server_already_running_when_ports_closed (scripts.run_e2e_tests_test.RunE2ETestsTests) ... FAIL

======================================================================
FAIL: test_is_oppia_server_already_running_when_ports_closed (scripts.run_e2e_tests_test.RunE2ETestsTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/oppia/scripts/run_e2e_tests_test.py", line 70, in test_is_oppia_server_already_running_when_ports_closed
    raise AssertionError('hi')
AssertionError: hi

----------------------------------------------------------------------
Ran 1 test in 1.078s

FAILED (failures=1)
Traceback (most recent call last):
  File "/oppia/core/tests/gae_suite.py", line 126, in <module>
    main()
  File "/oppia/core/tests/gae_suite.py", line 122, in main
    result.testsRun, len(result.errors), len(result.failures)))
Exception: Test suite failed: 1 tests run, 0 errors, 1 failures.

Stopping Redis Server(name="redis-server", pid=38032)...
Stopping Cloud Datastore Emulator(name="python2.7", pid=38015)...

+------------------+
| SUMMARY OF TESTS |
+------------------+
...

Notice that the HELLO THERE output appears above the summary of tests.

Use the Python debugger

The Python debugger, or pdb, is very helpful for debugging tests. It is very similar to GDB, the GNU Debugger, in case you are familiar with GDB already.

With pdb, you set break points to tell the debugger where to pause when executing your code. When the debugger pauses, you are dropped into a debugging shell where you can execute normal Python statements or pdb commands. The shell reflects the state of your program at the break point, so you can print out variable values, call functions, and even change variables in your program.

Step 1: Insert break points

To begin, insert a break point in your code like this:

import pdb; pdb.set_trace()

When your test executes, the debugger will pause every time it executes this line.

Step 2: Run test with unittest

To use pdb, you cannot use the run_backend_tests.py script. Instead, you need to run the test you want to debug using Python's native unittest command:

python -m unittest [full dotted name to test function]

Step 3: PDB commands

Once you are in a debugging shell, you can also use any of the following pdb commands:

  • w(here): Print a stack trace based on your current location in the program.
  • d(own): Move down one frame in the stack (to a newer frame).
  • u(p): Move up one frame in the stack (to an older frame).
  • s(tep): Execute the current line and stop at the next line of code, even if that next line is inside the function called on the current line. You can think of this as stepping into the function call on the current line.
  • n(ext): Execute the current line and stop at the next line in the current function. If a function is called on the current line, the debugger will not stop inside that function.
  • c(ontinue): Continue executing the program until the next break point.
  • l(ist): List the source code around your current line, or continue your previous listing if you've already called list on the current line.
  • p [expression]: Evaluate [expression] and print it.
  • pp [expression]: Evaluate [expression] and pretty-print it.
  • q(uit): Abort the program and quit the debugger.

The parentheses indicate optional parts of the commands. For example, you can use the where command either by typing w or by typing where. These are just a few of the most useful commands. See the pdb documentation for more information.

Be careful when executing Python code directly in the debugging shell. If your commands look like a PDB command, the PDB command may be executed instead.

For example, this works just as you'd expect:

(Pdb) z = 1
(Pdb) z
1

However, this fails:

(Pdb) p = 1
*** SyntaxError: invalid syntax

This second case fails because p looks to PDB like the print command, not a variable.