Asynchronous Server/Client with Python [0x02]: Logging

In part 0x02 of this series, we’re going to add a logging system to our server!  As I mentioned in the last post, this server is going to have quite a lot of moving parts;  it’s going to be useful to have a way to monitor what it’s doing.  If we ever end up in a situation where our code crashes or misbehaves for some unknown reason, our logs should at least give us enough information to form some educated guesses about where the problem is coming from. In addition, logs can also provide a history of our chat room if you want one.

Link to Part 0x03 Client Data & Server Broadcast

Links to the code on Github and useful documentation/references can be found below under the heading  “Sauce, References, & Documentation”.

Logging Basics

Before we jump right into the actual coding, we need to decide a few things about what we want from our logging system. 

The first thing to consider is what you will need messages for, as well as how urgent messages for some things should be compared to others.   In Python logging, there are a few different levels of logging that we can use… (https://docs.python.org/3/library/logging.html#logging-levels):

• Critical – Something REALLY bad happened
• Error – Something bad happened
• Warning – Something unexpected happened, but is probably not going to break our code
• Info – Useful information (Server start/stop, client connect/disconnect, user messages, etc)
• Debug – Information that might be helpful to us, the developer, when troubleshooting problems

In this project, it is up to you to determine exactly how you need to use these throughout the code. The levels above are listed in descending order of importance, and the names themselves should give some idea as to what kinds of events might be appropriate for each label.

Next, we should consider how we’re going to format our logs. Luckily, there are some built-in formatters we can use to help us out here… (https://docs.python.org/3/library/logging.html#formatter-objects).

For the sake of simplicity, in this example we will be using the following format:

[Datetime] – [Logging Level] – Message

Finally, we should have some idea of where we’re going to store our logs. For this project, let’s just create a “logs” folder in our current directory and store each new log there. We can use basic python file IO to make this happen; I’ll go further into detail about that later.  For now, we’re set to move ahead!

Getting Started

For part 0x02, we are going to modify our Server.py file that we wrote in part one of this series. To get started, let’s go ahead and add our new imports to the top of our file (logging and datetime):

import asyncio
import sys
import logging
import os
import pathlib
from datetime

Setting Up Our Logging System

In our Server.py, we’ll want to monitor all of our Server’s activities. To begin, let’s modify our server’s constructor to include the logger we plan on using:

class Server:
    def __init__(self, ip: str, port: int, loop: asyncio.AbstractEventLoop):
        '''
        Parameters
        ----------
        ip : str
            IP that the server will be using
        port : int
            Port that the server will be using
        ----------
        '''
        self.__ip: str = ip
        self.__port: int = port
        self.__loop: asyncio.AbstractEventLoop = loop
        self.__logger: logging.Logger = self.initialize_logger().  # <--- New line

        print(f"Server Initialized with {self.ip}:{self.port}")

    # New server property
    @property
    def logger(self):
        return self.__logger

Now we’ll need to create our initialize_logger() function within our class so that we can setup the logger. Our self.initialize_logger() function will be responsible for setting up our log file, log format, and for returning a logger object accessible in self.logger.  We’ll need to use that logger object to write logs into a file. 

Let’s implement that function right below the new logger property that we just defined…

    def initialize_logger(self):
        '''
        Initializes a logger and generates a log file in ./logs.
        Returns
        -------
        logging.Logger
            Used for writing logs of varying levels to the console and log file.
        -------
        '''
        path = pathlib.Path(os.path.join(os.getcwd(), "logs"))
        path.mkdir(parents=True, exist_ok=True)

        logger = logging.getLogger('Server')
        logger.setLevel(logging.DEBUG)

        ch = logging.StreamHandler()
        fh = logging.FileHandler(
            filename=f'logs/{datetime.now().strftime("%Y-%m-%d-%H-%M-%S")}_server.log'
        )
        ch.setLevel(logging.INFO)
        fh.setLevel(logging.DEBUG)

        formatter = logging.Formatter(
            '[%(asctime)s] - %(levelname)s - %(message)s'
        )

        ch.setFormatter(formatter)
        fh.setFormatter(formatter)
        logger.addHandler(ch)
        logger.addHandler(fh)

        return logger

This function might look like a lot, but it’s not actually that complicated. Let’s break down what’s happening line by line…

• Lines 10-11: We are using os and pathlib to check if our logs folder exists within our current working directory. If this folder does not exist, we will create it. If the logs folder already exists, then it will proceed without raising any errors, as indicated by us setting the “exists_ok” flag to “true” in line 11.
• Line 13: In python’s Logging library, we are able to work with more than one logging object at a time. This might be useful in larger applications with many distinct moving parts executing under the same program. In our case, we are only dealing with the server so we can just reference our “server” logging object.
• Line 14: Setting the logging level here determines the lowest priority of logs that our logging object will concern itself with.  In our case, we care about ALL logs, so we will set our level to the lowest: debug. This ensures that our logs contain anything and everything that we might send it. If we were to set our logging level to something higher, then our logging object will ignore any attempts to log messages of a lower priority level.
• Lines 16-21: Here, we are setting up our stream and file handling so that we are able to save and track our logs. We’re also setting up our file, which will be named after the current datetime.
• Lines 23-25: This establishes the format of our entries.
• Lines 27-30 This applies our settings to our logging object.

At this point, the hard part of logging is now behind us. All we have to do now is start using our logger! To keep things simple, I will paste the entirety of our Server.py so far below. Note that I have replaced all of our print statements with the logger:

import asyncio
import sys
import logging
import pathlib
import os
from datetime


class Server:
    def __init__(self, ip: str, port: int, loop: asyncio.AbstractEventLoop):
        '''
        Parameters
        ----------
        ip : str
            IP that the server will be using
        port : int
            Port that the server will be using
        ----------
        '''
        self.__ip: str = ip
        self.__port: int = port
        self.__loop: asyncio.AbstractEventLoop = loop
        self.__logger: logging.Logger = self.initialize_logger()

        self.logger.info(f"Server Initialized with {self.ip}:{self.port}")

    @property
    def ip(self):
        return self.__ip

    @property
    def port(self):
        return self.__port

    @property
    def loop(self):
        return self.__loop

    @property
    def logger(self):
        return self.__logger

    def initialize_logger(self):
        '''
        Initializes a logger and generates a log file in ./logs.
        Returns
        -------
        logging.Logger
            Used for writing logs of varying levels to the console and log file.
        -------
        '''
        path = pathlib.Path(os.path.join(os.getcwd(), "logs"))
        path.mkdir(parents=True, exist_ok=True)

        logger = logging.getLogger('Server')
        logger.setLevel(logging.DEBUG)

        ch = logging.StreamHandler()
        fh = logging.FileHandler(
            filename=f'logs/{datetime.now().strftime("%Y-%m-%d-%H-%M-%S")}_server.log'
        )
        ch.setLevel(logging.INFO)
        fh.setLevel(logging.DEBUG)

        formatter = logging.Formatter(
            '[%(asctime)s] - %(levelname)s - %(message)s'
        )

        ch.setFormatter(formatter)
        fh.setFormatter(formatter)
        logger.addHandler(ch)
        logger.addHandler(fh)

        return logger

    def start_server(self):
        '''
        Starts the server on IP and PORT.
        '''
        try:
            self.server = asyncio.start_server(
                self.accept_client, self.ip, self.port
            )
            self.loop.run_until_complete(self.server)
            self.loop.run_forever()
        except Exception as e:
            self.logger.error(e)
        except KeyboardInterrupt:
            self.logger.warning("Keyboard Interrupt Detected. Shutting down!")

    def accept_client(self, client_reader: asyncio.StreamReader, client_writer: asyncio.StreamWriter):
        '''
        Callback that is used when server accepts clients

        Parameters
        ----------
        client_reader : asyncio.StreamReader
            StreamReader generated by asyncio.start_server.
        client_writer : asyncio.StreamWriter
            StreamWriter generated by asyncio.start_server.
        ----------
        '''
        task = asyncio.Task(self.handle_client(client_reader, client_writer))
        client_ip = client_writer.get_extra_info('peername')[0]
        client_port = client_writer.get_extra_info('peername')[1]
        self.logger.info(f"New Connection: {client_ip}:{client_port}")

    async def handle_client(self, client_reader: asyncio.StreamReader, client_writer: asyncio.StreamWriter):
        '''
        Handles incoming messages from client

        Parameters
        ----------
        client_reader : asyncio.StreamReader
            StreamReader generated by asyncio.start_server.
        client_writer : asyncio.StreamWriter
            StreamWriter generated by asyncio.start_server.
        ----------
        '''
        while True:
            client_message = str((await client_reader.read(255)).decode('utf8'))

            if client_message.startswith("quit"):
                break

            self.logger.info(f"{client_message}")

            await client_writer.drain()

        self.logger.info("Client Disconnected!")


if __name__ == '__main__':
    if len(sys.argv) < 3:
        sys.exit(f"Usage: {sys.argv[0]} HOST_IP PORT")

    loop = asyncio.get_event_loop()
    server = Server(sys.argv[1], sys.argv[2], loop)
    server.start_server()

Now if we want to see our logger in action, all we have to do is run our server! Nothing has really changed in terms of functionality from our code in the previous blog post, so testing this code should be exactly the same!

Conclusion

The point of this installment was to add a more robust logging system to our code that’s capable of persisting in a file after our program exits for future reference. This can be useful in a number of different cases, such as reviewing server logs for a chat history or for checking the logs while troubleshooting or improving the server. This feature will seriously come in handy as our server code increases in size and complexity.

In the next part of this project series, we will continue adding features to our server that will enable it to better track and manage its connections. We’ll also modify the server so that it can broadcast messages to all clients! This means one client will be able to see messages from all of the other clients; basically, we’ll be able to do group chats instead of just having a bunch of direct messages. 

I hope you are happy with how your progress here is coming along! 

Link to Part 0x03 Client Data & Server Broadcast

As always, if you liked what you read and you’d like to support me, please consider buying me some coffee! Every cup of coffee sent my way helps me stay awake after my full-time job so that I can produce more high quality blog posts! Any and all support would be greatly appreciated!

Sauce, References, & Documentation

Github: https://github.com/D3ISM3/Python-Asynchronous-Server-Client
Python Logging Documentation: https://docs.python.org/3/library/logging.html