Step 6: Add Logging

When you first start programming in any language, you’re often taught to print() to the console in order to see the values of variables or just to help you debug.

As a beginner, this is an acceptable technique. As you advance in your programming career, you find out sooner or later, that print()-ing to the console to debug is easy, but comes with a lot of drawbacks. But what else should you do?

Use the debugger and use the Logging module instead.

Python created “PEP-282 — A Logging System” back in February 2002! https://www.python.org/dev/peps/pep-0282/

It was inspired by other logging packages of other languages. Logging is a little bit more complex than print(), but it is much better suited to debugging your program than print().

Let’s enhance our REST adapter with Logging!

import requests
import requests.packages
from json import JSONDecodeError
from typing import List, Dict
from .exceptions import TheCatApiException
from .models import Result

class RestAdapter:
    def __init__(self, hostname: str, api_key: str = '', ver: str = 'v1', ssl_verify: bool = True):
        self.url = "https://{}/{}".format(hostname, ver)
        self._api_key = api_key
        self._ssl_verify = ssl_verify
        if not ssl_verify:
            # noinspection PyUnresolvedReferences
            requests.packages.urllib3.disable_warnings()

Let’s start by importing logging into our project.

import logging

That was easy. How do we add it to our REST adapter? Tack on parameter to our __init__ constructor called logger and hint that it is of type logging.Logger and set it to the default value of None:

class RestAdapter:
    def __init__(self, hostname: str, api_key: str = '', ver: str = 'v1', ssl_verify: bool = True, logger: logging.Logger = None):

Then in the constructor, add the following line:

self._logger = logger or logging.getLogger(__name__)

This takes either a logger that the consumer of this REST adapter supplied. Or, if none is provided, it auto-generates one for you based on the class name.

Ok, we have a logger now, but what do we do with it? How do we even use it?

Things you should know about loggers

1. Logger output can be sent to many different locations: the screen, log files, network locations, or even other programs.
2. Logger output should be optimized for machine readability, but it also should be readable by humans.
   Why is this? For the most part, you want your logs parse-able by other code for analysis. But you still want to be able to read the logs yourself.
3. The Logger has many different “log levels”. Python has 6 levels built into the logger. The default levels are:

CRITICAL 50
ERROR 40
WARNING 30
INFO 20
DEBUG 10
NOTSET 0

If you wish, you can create additional levels between the existing levels. As an example, you could create your own custom logger that has 2 additional levels. One called MESG 25 and another LOWDEBUG 7.

What are these “levels” exactly? Well, when you send a message to the logger, you often want to specify how important this info is. Perhaps, you’re only interested in Warnings and Errors, so you set your log level to 30. Maybe you want to see all the piddly little details, so you set your log level to 0. Maybe you only want to log critical errors to the screen, warnings/errors/critical to the local log file, and send all info to a log collector program.

How to use the logger in your code

self._logger.info("Something happened")

This will send the message “Something happened” to the logger at the INFO (20) level. This is a silly thing to send to the logger because it doesn’t tell anyone anything.

It does point out a good practice with logging:

1. Log the state just before something important is going to happen.
2. Log the result just after something important happened (especially if the something that happened was “bad”)

Let’s look at our code again:

class RestAdapter:
    def __init__(self, hostname: str, api_key: str = '', ver: str = 'v1', ssl_verify: bool = True, logger: logging.Logger = None):
        self._logger = logger or logging.getLogger(__name__)
        self.url = f"https://{hostname}/{ver}"
        self._api_key = api_key
        self._ssl_verify = ssl_verify
        if not ssl_verify:
            # noinspection PyUnresolvedReferences
            requests.packages.urllib3.disable_warnings()

    def _do(self, http_method: str, endpoint: str, def _do(self, http_method: str, endpoint: str, ep_params: Dict = None, data: Dict = None):
        full_url = self.url + endpoint
        headers = {'x-api-key': self._api_key}
        try:
            response = requests.request(method=http_method, url=full_url, verify=self._ssl_verify,
                                        headers=headers, params=ep_params, json=data)
        except requests.exceptions.RequestException as e:
            raise TheCatApiException("Request failed") from e
        try:
            data_out = response.json()
        except (ValueError, JSONDecodeError) as e:
            raise TheCatApiException("Bad JSON in response") from e
        if 299 >= response.status_code >= 200:     # 200 to 299 is OK
            return Result(response.status_code, message=response.reason, data=data_out)
        raise TheCatApiException(f"{response.status_code}: {response.reason}")

    def get(self, endpoint: str, ep_params: Dict = None) -> Result:
        return self._do(http_method='GET', endpoint=endpoint, ep_params=ep_params)

    def post(self, endpoint: str, ep_params: Dict = None, data: Dict = None) -> Result:
        return self._do(http_method='POST', endpoint=endpoint, ep_params=ep_params, data=data)

    def delete(self, endpoint: str, ep_params: Dict = None, data: Dict = None) -> Result:
        return self._do(http_method='DELETE', endpoint=endpoint, ep_params=ep_params, data=data)

If we look over our code, we might be tempted to put log lines in the __init__ constructor of our RestAdapter class, but not much is actually happening there.

Let’s add a couple logger lines before the first try-except block because some action is happening there:

        log_line_pre = f"method={http_method}, url={full_url}, params={ep_params}"
        log_line_post = ', '.join((log_line_pre, "success={}, status_code={}, message={}"))
        try:
            self._logger.debug(msg=log_line_pre)
            response = requests.request(method=http_method, url=full_url, verify=self._ssl_verify,
                                        headers=headers, params=ep_params, json=data)
        except requests.exceptions.RequestException as e:
            self._logger.error(msg=(str(e)))
            raise TheCatApiException("Request failed") from e

First, we’ve created two formatted-string using pairs of variables and variable values in the form of variable_name=variable_value separated by commas (,)

Then we pass this log_line_pre to the logger and set it at the debug level. This is to log that the code is about to do something significant. In this case, it is about to call requests.request

We also put an error logging msg in the except block to log when anything goes wrong.

The reason we use key-value pairs in the comma-delimited equals format is because many logging collector programs (like the enterprise logging service, Splunk) readily use this format. It’s also easy for you to write your own parsing program.

---

Let’s continue to add more log lines in our REST adapter:

        try:
            data_out = response.json()
        except (ValueError, JSONDecodeError) as e:
            self._logger.error(msg=log_line_post.format(False, None, e))
            raise TheCatApiException("Bad JSON in response") from e
        is_success = 299 >= response.status_code >= 200     # 200 to 299 is OK
        log_line = log_line_post.format(is_success, response.status_code, response.reason)
        if is_success:
            self._logger.debug(msg=log_line)
            return Result(response.status_code, message=response.reason, data=data_out)
        self._logger.error(msg=log_line)
        raise TheCatApiException(f"{response.status_code}: {response.reason}")

Note here that we don’t log the response.json() deserialization. This is a common occurrence and doesn’t need to be logged, except for when there is an error (as shown above).

We refactor our code slightly to convert the 200-299 status code test into a boolean (is_success).

If it IS a success, we log the response as a debug level info. Generally, we’re not interested in this info, unless we’re debugging. Thus debug level.

If NOT a success, then we log as an error and raise the exception.

And that’s it for logging! The get(), post(), and delete() methods don’t require logging because they all leverage the same _do() method which already has logging added.

Step 7: Time to comment our code!

---

Source code: https://github.com/PretzelLogix/py-cat-api/tree/06_add_logging