diff --git a/sa/README.md b/sa/README.md index 0f8b271..be2dc85 100644 --- a/sa/README.md +++ b/sa/README.md @@ -3,3 +3,4 @@ Current content: - [Git tips](git_tips) +- [Logging tips](logging_tips) \ No newline at end of file diff --git a/sa/logging_tips/README.md b/sa/logging_tips/README.md new file mode 100644 index 0000000..72fc702 --- /dev/null +++ b/sa/logging_tips/README.md @@ -0,0 +1,7 @@ +# Logging in Python 👌 + +During coding, making sure that you have a logging system in place is very important. It will allow you to debug errors more easily and will enable you to better analyse the performance 🕵️‍♀️ of your application. + +--- + +In the notebook included in this folder you will not only find general information about the logging module, but also multiple tips and tricks that will level up your logging game! Make sure to run every codeblock only once, as reruns might break some things with the logging components. diff --git a/sa/logging_tips/img/logging_components.png b/sa/logging_tips/img/logging_components.png new file mode 100644 index 0000000..362112b Binary files /dev/null and b/sa/logging_tips/img/logging_components.png differ diff --git a/sa/logging_tips/logging.conf b/sa/logging_tips/logging.conf new file mode 100644 index 0000000..38c0c4d --- /dev/null +++ b/sa/logging_tips/logging.conf @@ -0,0 +1,28 @@ +[loggers] +keys=root,simpleExample + +[handlers] +keys=consoleHandler + +[formatters] +keys=simpleFormatter + +[logger_root] +level=DEBUG +handlers=consoleHandler + +[logger_simpleExample] +level=DEBUG +handlers=consoleHandler +qualname=simpleExample +propagate=0 + +[handler_consoleHandler] +class=StreamHandler +level=DEBUG +formatter=simpleFormatter +args=(sys.stdout,) + +[formatter_simpleFormatter] +format=%(asctime)s - %(name)s - %(levelname)s - %(message)s +datefmt= \ No newline at end of file diff --git a/sa/logging_tips/logging_template/helpers/__init__.py b/sa/logging_tips/logging_template/helpers/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/sa/logging_tips/logging_template/helpers/logger.py b/sa/logging_tips/logging_template/helpers/logger.py new file mode 100644 index 0000000..30241d7 --- /dev/null +++ b/sa/logging_tips/logging_template/helpers/logger.py @@ -0,0 +1,33 @@ +""" +This file contains the logging setup. +""" + +import logging +import sys + +APP_LOGGER_NAME = 'MyLoggerApp' + +def setup_applevel_logger(logger_name=APP_LOGGER_NAME, file_name=None): + """...""" + logger = logging.getLogger(logger_name) + syslog = logging.StreamHandler() + + format = '%(name)s - %(levelname)s - %(message)s' + formatter = logging.Formatter(format) + syslog.setFormatter(formatter) + + logger.setLevel(logging.DEBUG) + logger.handlers.clear() + logger.addHandler(sh) + + if file_name: + fh = logging.FileHandler(file_name) + fh.setFormatter(formatter) + logger.addHandler(fh) + + return logger + + +def get_logger(module_name): + """...""" + return logging.getLogger(APP_LOGGER_NAME).getChild(module_name) diff --git a/sa/logging_tips/logging_template/helpers/module.py b/sa/logging_tips/logging_template/helpers/module.py new file mode 100644 index 0000000..4ba4e50 --- /dev/null +++ b/sa/logging_tips/logging_template/helpers/module.py @@ -0,0 +1,13 @@ +""" +Custom module +""" + +import logger + +log = logger.get_logger(__name__) + + +def multiply(num1, num2): # multiply two numbers + """...""" + log.debug('Executing multiply.') + return num1 * num2 diff --git a/sa/logging_tips/logging_template/main.py b/sa/logging_tips/logging_template/main.py new file mode 100644 index 0000000..cd9fa94 --- /dev/null +++ b/sa/logging_tips/logging_template/main.py @@ -0,0 +1,19 @@ +""" +File containing the entrypoint of the script. +""" + +from helpers import logger +log = logger.setup_applevel_logger(file_name = 'app_debug.log') + +from helpers import module + + +def run(): + """...""" + log.debug('Calling module function.') + module.multiply(5, 2) + log.info('Finished.') + + +if __name__ == '__main__': + run() diff --git a/sa/logging_tips/logging_tips.ipynb b/sa/logging_tips/logging_tips.ipynb new file mode 100644 index 0000000..b3405a7 --- /dev/null +++ b/sa/logging_tips/logging_tips.ipynb @@ -0,0 +1,557 @@ +{ + "cells": [ + { + "cell_type": "markdown", + "source": [ + "# Logging in Python\n", + "\n", + "Hi there!\n", + "\n", + "In this notebook we will take a closer look @ Python logging. Logging is very important to get right! With it, you will not only be able to debug errors more easily. You will also be able to better analyse the performance of an application which is very valuable in production environments.\n", + "\n", + "Below you will find multiple tips and tricks to level up your logging game!" + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "## The logging module\n", + "\n", + "Python has a neat, built in module that provides a flexible framework for logging messages." + ], + "metadata": { + "tags": [] + } + }, + { + "cell_type": "code", + "execution_count": 1, + "source": [ + "import logging" + ], + "outputs": [], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "### Logging classes\n", + "\n", + "The package offers four components that are used during logging. Log events are passed between these components until they reach the final output.\n", + "\n", + "* Loggers expose the interface that application code uses (creates the log records).\n", + "* Filters provide a fine grained system to control which log records to output.\n", + "* Handlers send the log records to the correct destination.\n", + "* Formatters specify the layout of log records.\n", + "\n", + "The basic flow of log records between the components can be found in the image below.\n", + "\n", + "![Log records flow](./img/logging_components.png \"logging components\")" + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "### Loggers\n", + "\n", + "When importing the `logging` package, a logger called `ROOT` exists by default. To create a new logger, use the following code. A nice rule to use when naming loggers is to use module-level loggers. This will make sure the logger tracks the hierarchy of the package, which make it very easy to know where event were logged, by the loggers name." + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 2, + "source": [ + "custom_logger = logging.getLogger('custom_logger')\n", + "module_level_logger = logging.getLogger(__name__)" + ], + "outputs": [], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "If a logger has a parent logger (which is in most cases the `ROOT` logger), it will propagate the logged record to all parent loggers and when this happens, a single log record might be logged multiple times. To make sure this doesn't happen we can set the `propagate` flag to False." + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 3, + "source": [ + "custom_logger.propagate = False" + ], + "outputs": [], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "#### The levels of logging\n", + "\n", + "By default, the `logging` package offers five levels of logging. These levels indicate the severity of the logged events. The five levels, in order of increasing severity are:\n", + "\n", + "* DEBUG (10): Problem diagnosing\n", + "* INFO (20): Confirmation messages of successful execution\n", + "* WARNING (30): Warn about unexpected situations\n", + "* ERROR (40): More serious syntax and logic problems\n", + "* CRITICAL (50): Report problems that result in crashes\n", + "\n", + "To define the level of a certain log message, you can call the following corresponding methods on the logger you want to create the log records with:" + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 4, + "source": [ + "custom_logger.debug('Debug message')\n", + "logging.info('Info message')\n", + "module_level_logger.warning('Warning message')\n", + "custom_logger.error('Error message')\n", + "logging.critical('Critical message')" + ], + "outputs": [ + { + "output_type": "stream", + "name": "stderr", + "text": [ + "WARNING:__main__:Warning message\n", + "Error message\n", + "CRITICAL:root:Critical message\n" + ] + } + ], + "metadata": { + "tags": [] + } + }, + { + "cell_type": "markdown", + "source": [ + "In the log records we can notice multiple things. For one, we can clearly see which logger was used to log a certain event. We can also notice that the debug and info log records were not printed. The reason for this is that, by default, logging message with severity levels lower than `warning` or `30` will not be created. To lower and highten the severity level of records we want to see, use the following code." + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 5, + "source": [ + "custom_logger.setLevel('DEBUG')\n", + "module_level_logger.setLevel('ERROR')\n", + "\n", + "custom_logger.debug('Debug message')\n", + "logging.info('Info message')\n", + "module_level_logger.warning('Warning message')\n", + "custom_logger.error('Error message')\n", + "logging.critical('Critical message')\n" + ], + "outputs": [ + { + "output_type": "stream", + "name": "stderr", + "text": [ + "Error message\n", + "CRITICAL:root:Critical message\n" + ] + } + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "By setting the level from our custom_logger to `DEBUG` and the level from our module_level_logger to `ERROR` we now get to see completely different log records. The custom logger can now output our debug event, and thus it shows up in the results. Our module-level logger however is logging a warning record but has it's output level set on `ERROR`. Thus, it will not create the record and we are not able to find it in our output." + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "#### Logging exceptions\n", + "\n", + "One specific use case for logging is that we want to log certain errors in our code. If a certain exception occures, we want to know about it and be able to see it pop up in our logs. And we are in luck! The `logging` package provides a neat function for this (`logger.exception()`)." + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 6, + "source": [ + "custom_logger.info('Started code.')\n", + "try:\n", + " numbers = [5, 8, 9, 1, 'four']\n", + " acc = sum(numbers)\n", + "except TypeError:\n", + " custom_logger.exception('Calculating sum failed..')\n", + "custom_logger.info('Shut down code.')" + ], + "outputs": [ + { + "output_type": "stream", + "name": "stderr", + "text": [ + "Calculating sum failed..\n", + "Traceback (most recent call last):\n", + " File \"/tmp/ipykernel_5217/4156510778.py\", line 4, in \n", + " acc = sum(numbers)\n", + "TypeError: unsupported operand type(s) for +: 'int' and 'str'\n" + ] + } + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "The function `.exception()` will automatically include the stack trace of the raised exception. It will create the log message with the `ERROR` severity level. You can only use this specific function from an exception handler!" + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "### Filters\n", + "\n", + "Filters can be used by both loggers and handlers for *next level* filtering, which is not provided by severity levels. To create a filter use the following code. From version 3.2 on, it is no longer necessary to subclass the `logging.Filter` class. You can now just create a function that will act as a filter." + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 7, + "source": [ + "class CustomFilter(logging.Filter):\n", + " def filter(self, record):\n", + " \"\"\"To allow a certain record to be logged, return True.\n", + " Return False to block a record from being logged.\n", + " One can also modify the record in-place in this class method.\n", + " \"\"\"\n", + " if record.name == 'custom_logger':\n", + " return True\n", + " return False\n", + "\n", + "# After logging version 3.2\n", + "def custom_filter(record):\n", + " \"\"\"To allow a certain record to be logged, return True.\n", + " Return False to block a record from being logged.\n", + " One can also modify the record in-place in this class method.\n", + " \"\"\"\n", + " if record.name == 'custom_logger':\n", + " return True\n", + " return False" + ], + "outputs": [], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "In the custom filters created above, we check which logger created the log record. If it was the customer logger, we allow it to be logged. Otherwise we block the log record by returning `False`." + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 8, + "source": [ + "custom_logger.addFilter(custom_filter)\n", + "module_level_logger.addFilter(custom_filter)\n", + "\n", + "custom_logger.critical('This record should get logged.')\n", + "module_level_logger.critical('This record should not get logged.')\n", + "\n", + "custom_logger.removeFilter(custom_filter)\n", + "module_level_logger.removeFilter(custom_filter)" + ], + "outputs": [ + { + "output_type": "stream", + "name": "stderr", + "text": [ + "This record should get logged.\n" + ] + } + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "### Handlers\n", + "\n", + "Handlers will dispatch log records to the handlers specified location. Both severity level and filters can be set on handlers (eg. only records are dispatched above severity level `INFO`). Loggers can have zero or multiple handlers. Handlers make it easy to send all log records to a log file, all log records with severity level `ERROR` or higher to stdout and all critical log records to an email address.\n", + "\n", + "The `logging` library contains a few handler types that can be used. The ones to note are:\n", + "\n", + "* StreamHandler - Sends log records to streams (file-like objects).\n", + "* FileHandler - Sends log records to disk files.\n", + "* QueueHandler - Sends log records to a queue, like those implemented in the queue or multiprocessing modules.\n", + "* SMTPHandler - Sends log records to a specified email address." + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 9, + "source": [ + "syslog = logging.StreamHandler()\n", + "syslog.setLevel('INFO')\n", + "\n", + "filelog = logging.FileHandler('./logs/log_test.log', mode='a')\n", + "filelog.setLevel('ERROR')\n", + "\n", + "if syslog not in custom_logger.handlers:\n", + " custom_logger.addHandler(syslog)\n", + " custom_logger.addHandler(filelog)\n", + "\n", + "custom_logger.info('Started code.')\n", + "try:\n", + " numbers = [5, 8, 9, 1, 'four']\n", + " acc = sum(numbers)\n", + "except TypeError:\n", + " custom_logger.exception('Calculating sum failed..')\n", + "custom_logger.info('Shut down code.')" + ], + "outputs": [ + { + "output_type": "stream", + "name": "stderr", + "text": [ + "Started code.\n", + "Calculating sum failed..\n", + "Traceback (most recent call last):\n", + " File \"/tmp/ipykernel_5217/4177430724.py\", line 14, in \n", + " acc = sum(numbers)\n", + "TypeError: unsupported operand type(s) for +: 'int' and 'str'\n", + "Shut down code.\n" + ] + } + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "### Formatters\n", + "\n", + "Formatters are used to configure the final order, structure and contents of a log record. One should pass a `fmt` or message format string to customize the format of the log records." + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 10, + "source": [ + "custom_logger.info('Log record without formatter.')\n", + "\n", + "format_string = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'\n", + "date_format_string = '%d-%m-%Y %H:%M:%S' # Defaults to %Y-%m-%d %H:%M:%S\n", + "custom_formatter = logging.Formatter(fmt=format_string, datefmt=date_format_string)\n", + "syslog.setFormatter(custom_formatter) # A Format is linked to a handler!\n", + "\n", + "custom_logger.info('Log record with formatter.')" + ], + "outputs": [ + { + "output_type": "stream", + "name": "stderr", + "text": [ + "Log record without formatter.\n", + "02-08-2021 13:48:15 - custom_logger - INFO - Log record with formatter.\n" + ] + } + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "You can also set the style the message format string is using. By default it uses the '%' style. However there are other styles, such as '{' or '$' that can be used. More information about this can be found [here](https://docs.python.org/3/howto/logging-cookbook.html#use-of-alternative-formatting-styles)." + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "#### Adding contextual information\n", + "\n", + "Sometimes, you will want to add custom contextual information into your log records. However one can not just add the variable to the format string of the Formatter, as this object will not recognize the variable. Luckily there are two seperate ways we can still accomplish this task. We could either use a Filter (as mentioned above, Filters can also be used to modify log records in-place.), or a LogAdapter.\n", + "\n", + "A LogAdapter might not always work for your use case, so if it doesn't work with a LogAdapter, try to use a Filter." + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 11, + "source": [ + "extra = {'app_name':'Logging App'}\n", + "\n", + "logger = logging.getLogger('Contextual-info-app-name-adapter')\n", + "logger.propagate = False\n", + "syslog = logging.StreamHandler()\n", + "\n", + "format = '%(app_name)s: %(message)s'\n", + "formatter = logging.Formatter(format)\n", + "syslog.setFormatter(formatter)\n", + "\n", + "logger.setLevel(logging.INFO)\n", + "logger.addHandler(syslog)\n", + "custom_adapter = logging.LoggerAdapter(logger, extra)\n", + "custom_adapter.info('Include contextual info')" + ], + "outputs": [ + { + "output_type": "stream", + "name": "stderr", + "text": [ + "Logging App: Include contextual info\n" + ] + } + ], + "metadata": {} + }, + { + "cell_type": "code", + "execution_count": 12, + "source": [ + "def custom_filter(record):\n", + " \"\"\"To allow a certain record to be logged, return True.\n", + " Return False to block a record from being logged.\n", + " One can also modify the record in-place in this class method.\n", + " \"\"\"\n", + " record.app_name = 'Logging App'\n", + " return True\n", + "\n", + "logger = logging.getLogger('Contextual-info-app-name-filter')\n", + "logger.propagate = False\n", + "logger.addFilter(custom_filter)\n", + "syslog = logging.StreamHandler()\n", + "\n", + "format = '%(app_name)s: %(message)s'\n", + "formatter = logging.Formatter(format)\n", + "syslog.setFormatter(formatter)\n", + "\n", + "logger.setLevel(logging.INFO)\n", + "logger.addHandler(syslog)\n", + "logger.info('Include contextual info')" + ], + "outputs": [ + { + "output_type": "stream", + "name": "stderr", + "text": [ + "Logging App: Include contextual info\n" + ] + } + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "### Set up logging with config\n", + "\n", + "The `logging` package also provides easy ways to quickly set up a full logging system with all the logger, handlers, etc.. that are required. To do this you can use the `logging.config` module. It contains multiple functions that let you load in a predefined config in different formats to set up everything automatically.\n", + "\n", + "* fileConfig - A logging config file. See `logging.conf` for an example.\n", + "* dictConfig - A dictionary of configuration information\n", + " \n", + "To read and load in configurations, use the following code. Make sure to only import third party libraries after you have loaded in the logging config to avoid getting their logs!" + ], + "metadata": { + "tags": [] + } + }, + { + "cell_type": "code", + "execution_count": 19, + "source": [ + "import logging.config\n", + "\n", + "logging.config.fileConfig('logging.conf')\n", + "\n", + "# OR\n", + "\n", + "LOGGING_CONFIG = {\n", + " 'version': 1,\n", + " 'disable_existing_loggers': True,\n", + " 'formatters': {\n", + " 'standard': {'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'},\n", + " },\n", + " 'handlers': {'default': {\n", + " 'level': 'INFO',\n", + " 'formatter': 'standard',\n", + " 'class': 'logging.StreamHandler',\n", + " 'stream': 'ext://sys.stdout', # Default is stderr\n", + " }, \n", + " },\n", + " 'loggers': { '': { # root logger\n", + " 'handlers': ['default'],\n", + " 'level': 'WARNING',\n", + " 'propagate': False\n", + " }, 'helpers.module': {\n", + " 'handlers': ['default'],\n", + " 'level': 'INFO',\n", + " 'propagate': False\n", + " }, '__main__': { # if __name__ == '__main__'\n", + " 'handlers': ['default'],\n", + " 'level': 'DEBUG',\n", + " 'propagate': False\n", + " },\n", + " }\n", + "}\n", + "logging.config.dictConfig(LOGGING_CONFIG)" + ], + "outputs": [], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "### Logging template\n", + "\n", + "To set up a logging system quickly on a new project, use the logging template included in this repo in the `logging_template` folder!" + ], + "metadata": {} + }, + { + "cell_type": "markdown", + "source": [ + "## Resources to consult\n", + "\n", + "* [Python Logging Cookbook](https://docs.python.org/3/howto/logging.html)\n", + "* [Medium blogposts](https://medium.com/search?q=python%20logging)" + ], + "metadata": { + "tags": [] + } + } + ], + "metadata": { + "interpreter": { + "hash": "348f8adaa9da0d6201cb8b21aecd4d4e467ee1cdb958d4ec9e1e284ab379cbdc" + }, + "kernelspec": { + "name": "python3", + "display_name": "Python 3.8.10 64-bit (conda)" + }, + "language_info": { + "codemirror_mode": { + "name": "ipython", + "version": 3 + }, + "file_extension": ".py", + "mimetype": "text/x-python", + "name": "python", + "nbconvert_exporter": "python", + "pygments_lexer": "ipython3", + "version": "3.8.10" + } + }, + "nbformat": 4, + "nbformat_minor": 4 +} \ No newline at end of file