How to debug the predict function in tests

Unfortunately, you cannot configure a debugger when you run tests during a build. After all, the build runs on a secure environment inside the Qwak Platform.

However, we can log the variables inside the predict function (and tests) to figure out what happens.

Let's assume we have the following predict function:

@qwak.api()
def predict(self, df: pd.DataFrame) -> pd.DataFrame:
	print(f'!!!! Predicting... {df}')
	if "exception" in df.columns:
		raise ValueError("This is a test exception")
return df

It's not a useful ML prediction, but it's good enough for our example. It logs the input and returns it unchanged. If the input contains an "exception" column, it throws a ValueError.

To demonstrate all possible test outcomes, we will create three test cases: a successful prediction with the returned value equal to the expected value, a successful prediction with a different expected value, and a failure inside the predict function. Note that, in this case, we run the tests as an integration test:

from qwak_mock import real_time_client


def test_whatever(real_time_client):
    feature_vector = [
	{
		"passing_test" : 1,
	}]

    real_time_client.predict(feature_vector)


def test_fails(real_time_client):
    feature_vector = [
	{
		"failing_test" : 0,
	}]

    real_time_client.predict(feature_vector)
    assert False

def test_failure_inside_predict(real_time_client):
    feature_vector = [
    {
        "exception" : 2,
    }]

    real_time_client.predict(feature_vector)
    assert False

In the test log, we will see the following result:

Executing model tests
Running tests
>>> ============================= test session starts ==============================
>>> platform linux -- Python 3.8.15, pytest-7.2.0, pluggy-1.0.0
>>> rootdir: /qwak/model_dir/tests
>>> plugins: typeguard-2.13.3
>>> collected 3 items
>>> tests/it/test_log.py .FF [100%]
>>> =================================== FAILURES ===================================

We see that two of the tests failed. That's what we expect in this example. Let's take a look at the failure details.

>>> =================================== FAILURES ===================================
>>> __________________________________ test_fails __________________________________
>>> /qwak/model_dir/tests/it/test_log.py:20: in test_fails
>>> assert False
>>> E assert False
>>> _________________________ test_failure_inside_predict __________________________
>>> /opt/conda/lib/python3.8/site-packages/requests/models.py:971: in json
... long, long stack trace
>>> raise RuntimeError(f"Failed to make a prediction request. Error is: {e}")
>>> E RuntimeError: Failed to make a prediction request. Error is: Expecting value: line 1 column 1 (char 0)

An assertion error causes the first failure. We see the expected error message logged by pytest.

What about the second error? The error message won't help us debug the problem. That's because the error cannot be parsed as a Pandas DataFrame.

To figure out what happened, we have to look at the test container logs below the pytest logs. The container logs look like this:

>>> ---------------------------- Captured log teardown -----------------------------
>>> INFO qwak_mock.fixture:fixture.py:82 [2023-01-04 12:16:36,372] INFO - Starting BentoML API server in production mode..
>>> [2023-01-04 12:16:36,372] INFO - Running micro batch service on :5000

In those logs, we will see the messages logged inside the predict function and a summary of the request/response logged by the underlying web framework. In the case of passing tests, we will see this:

🚧

Logs before the summary!

Note that the logged messages are listed before the request summary. If you look for a particular request, scroll up after finding it.

>>> !!!! Predicting... passing_test
>>> 0 1
>>> [2023-01-04 12:16:45,777] INFO - {'service_name': 'QwakBentoml', 'service_version': '20230104121621_1E32F9', 'api': 'predict', 'task': {'data': '{"columns":["passing_test"],"index":[0],"data":[[1]]}', 'task_id': 'f149c4cb-7964-42cb-a1c5-28bdc49a7312', 'batch': 1, 'http_headers': (('Host', '127.0.0.1:46313'), ('User-Agent', 'python-requests/2.28.1'), ('Accept-Encoding', 'gzip, deflate, br'), ('Accept', '*/*'), ('Connection', 'keep-alive'), ('Content-Type', 'application/json'), ('Authorization', 'Bearer HERE_IS_THE_TOKEN'), ('x-realtime-route-mode', 'true'), ('Content-Length', '53'))}, 'result': {'data': '[{"passing_test":1}]', 'http_status': 200}, 'request_id': 'f149c4cb-7964-42cb-a1c5-28bdc49a7312'}

We will see a similar log if the test fails because of an assertion error. After all, the failure happened outside of the container with the model.

However, if the predict function raises an error, we will see the logged messages and the entire stack trace in the container logs:

>>> !!!! Predicting... exception
>>> 0 2
>>> [2023-01-04 12:16:45,951] ERROR - Error caught in API function:
>>> Traceback (most recent call last):
>>> File "/opt/conda/lib/python3.8/site-packages/bentoml/service/inference_api.py", line 226, in wrapped_func
>>> return self._user_func(*args, **kwargs)
>>> File "./QwakBentoml/build_model.py", line 39, in predict
>>> File "/opt/conda/lib/python3.8/site-packages/qwak/model/decorators/api.py", line 169, in wrapper_func
>>> raise e
>>> File "/opt/conda/lib/python3.8/site-packages/qwak/model/decorators/api.py", line 112, in wrapper_func
>>> output = func(*args, **kwargs)
>>> File "/qwak/model_dir/main/model.py", line 15, in predict
>>> raise ValueError("This is a test exception")
>>> ValueError: This is a test exception
>>> [2023-01-04 12:16:45,952] ERROR - {'service_name': 'QwakBentoml', 'service_version': '20230104121621_1E32F9', 'api': 'predict', 'task': {'data': '{"columns":["exception"],"index":[0],"data":[[2]]}', 'error': {'err_msg': 'Exception happened in API function: This is a test exception', 'http_headers': (('X-Exception-Class', 'ValueError'),)}, 'task_id': '590d9272-83ca-4320-a215-2c9df0113aa0', 'is_discarded': True, 'batch': 1, 'http_headers': (('Host', '127.0.0.1:46313'), ('User-Agent', 'python-requests/2.28.1'), ('Accept-Encoding', 'gzip, deflate, br'), ('Accept', '*/*'), ('Connection', 'keep-alive'), ('Content-Type', 'application/json'), ('Authorization', 'Bearer TOKEN'), ('x-realtime-route-mode', 'true'), ('Content-Length', '50'))}, 'error_response': {'status_code': 500, 'error_message': 'Exception happened in API function: This is a test exception', 'exception_class': 'ValueError'}, 'request_id': '590d9272-83ca-4320-a215-2c9df0113aa0'}

Here, we get all the information required to debug the failing code.

How to make it easier to find relevant logs

Looking for the relevant logs may be tedious when you have many tests. Because of that, you can use the metadata argument of the predict function to pass additional information. The Qwak platform will pass them as HTTP headers and log them in the container logs.

📘

Passing metadata work in production too!

In my test code, I can write the tests like this:

def test_failure_inside_predict(real_time_client):
    feature_vector = [
    {
        "exception" : 2,
    }]

    real_time_client.predict(feature_vector, metadata={"X-Test-Case": "test_failure_inside_predict"})
    assert False

Now, in the request/response summary, I will see the X-Test-Case header: ('X-Test-Case', 'test_failure_inside_predict')

>>> [2023-01-04 12:16:45,952] ERROR - {'service_name': 'QwakBentoml', 'service_version': '20230104121621_1E32F9', 'api': 'predict', 'task': {'data': '{"columns":["exception"],"index":[0],"data":[[2]]}', 'error': {'err_msg': 'Exception happened in API function: This is a test exception', 'http_headers': (('X-Exception-Class', 'ValueError'),)}, 'task_id': '590d9272-83ca-4320-a215-2c9df0113aa0', 'is_discarded': True, 'batch': 1, 'http_headers': (('Host', '127.0.0.1:46313'), ('User-Agent', 'python-requests/2.28.1'), ('Accept-Encoding', 'gzip, deflate, br'), ('Accept', '*/*'), ('Connection', 'keep-alive'), ('Content-Type', 'application/json'), ('Authorization', 'Bearer TOKEN'), ('X-Test-Case', 'test_failure_inside_predict'), ('x-realtime-route-mode', 'true'), ('Content-Length', '50'))}, 'error_response': {'status_code': 500, 'error_message': 'Exception happened in API function: This is a test exception', 'exception_class': 'ValueError'}, 'request_id': '590d9272-83ca-4320-a215-2c9df0113aa0'}

To find the relevant logs, use the text search feature of your web browser, find the request/response summary and scroll up to see the values logged in the predict function.