as shown in the following example.<\/span><\/p>\n# logging_test1.py\r\n\r\nimport logging\r\n\r\nlogging.basicConfig(level=logging.DEBUG,\r\n filename='basic_config_test1.log',\r\n format='%(asctime)s %(name)s %(levelname)s:%(message)s')\r\n\r\nlogger = logging.getLogger(__name__)\r\n\r\n\r\ndef basic_config_test1():\r\n logger.debug(\"debug log test 1\")\r\n logger.error(\"error log test 1\")\r\n\r\n\r\n# logging_test2.py\r\n\r\nimport logging\r\nimport logging_test1\r\n\r\nlogger = logging.getLogger(__name__)\r\n\r\n\r\n\r\ndef basic_config_test2():\r\n logger.debug(\"debug log test 2\")\r\n logger.error(\"error log test 2\")\r\n<\/pre>\nWe have a better configuration<\/strong> now, each module is describing itself inside the log stream and everything is more clear, but nonetheless, the logger instantiated in the <\/span>logging_test2<\/span> module will use the same configuration as the logger instantiated in the <\/span>logging_test1<\/span> module, i.e. the root logger\u2019s configuration. As stated before, the second invocation of <\/span>basicConfig()<\/span> method will have no effect. Therefore, executing both <\/span>basic_config_test1()<\/span> and <\/span>basic_config_test2()<\/span>methods will result in the creation of a single <\/span>basic_config_test1.log<\/span> file with the following content.<\/span><\/p>\n2020-05-09 19:37:59,607 logging_test1 DEBUG:debug log test 1<\/span>\r\n\r\n2020-05-09 19:37:59,607 logging_test1 ERROR:error log test 1<\/span>\r\n\r\n2020-05-09 19:38:05,183 logging_test2 DEBUG:debug log test 2<\/span>\r\n\r\n2020-05-09 19:38:05,183 logging_test2 ERROR:error log test 2<\/span><\/pre>\nDepending on the context of your application, using a single configuration for loggers instantiated in different modules can be not enough.<\/p>\n
In the next section, we will see how to provide logging configuration across multiple loggers through either fileConfig() or dictConfig().<\/p>\n
Using fileConfig() and dictConfig()<\/h2>\n Even if basicConfig() is a quick way to start organizing your logging, file, or dictionary-based configurations offer more options to fine-tune your needs, allow for more than one logger in your application and can send your log to different destinations based on specific factors.<\/p>\n
This is also the preferred way frameworks like Django and Flask use for setting up logging in your projects. In the next sections, we\u2019ll take a closer look at how to set up a proper file or dictionary-based configuration.<\/strong><\/p>\nfileConfig()<\/h2>\n Configuration files must adhere to this structure, containing some key elements.<\/strong><\/p>\n[loggers]: the names of the loggers we need to configure. \n[handlers]: the handlers we want to use for specific loggers (e.g. consoleHandler, fileHandler). \n[formatters]: the formats you want to apply to each logger.<\/p>\n
Each section of the file (named in plural) should include a comma-separated list of one or more keys to link the actual configuration:<\/p>\n
[loggers]<\/span>\r\n\r\nkeys=root,secondary<\/span>\u00a0<\/span><\/pre>\nThe keys are used to traverse the file and read appropriate configurations for each section. The keys are defined as [_], where the section name is logger, handler, or formatter which are predefined as said before.<\/p>\n
A sample logging configuration file (logging.ini) is shown below.<\/p>\n
[loggers]<\/span>\r\nkeys=root,custom<\/span>\r\n\r\n[handlers]<\/span>\r\nkeys=fileHandler,streamHandler<\/span>\r\n\r\n[formatters]<\/span>\r\nkeys=formatter<\/span>\r\n\u00a0\r\n[logger_root]<\/span>\r\nlevel=DEBUG<\/span>\r\nhandlers=fileHandler<\/span>\r\n\r\n[logger_custom]<\/span>\r\nlevel=ERROR<\/span>\r\nhandlers=streamHandler<\/span>\r\n\u00a0\r\n[handler_fileHandler]<\/span>\r\nclass=FileHandler<\/span>\r\nlevel=DEBUG<\/span>\r\nformatter=formatter<\/span>\r\nargs=(\"\/path\/to\/log\/test.log\",)<\/span>\r\n\r\n[handler_streamHandler]<\/span>\r\nclass=StreamHandler<\/span>\r\nlevel=ERROR<\/span>\r\nformatter=formatter<\/span>\r\n\r\n[formatter_formatter]<\/span>\r\nformat=%(asctime)s %(name)s - %(levelname)s:%(message)s<\/span><\/pre>\nPython\u2019s best practices recommend to only maintain one handler per logger<\/strong> relying on the inheritance of child logger for properties propagation. This basically means that you just have to attach a specific configuration to a parent logger, to have it inherited by all the child loggers without having to set it up for every single one of them. A good example of this is a smart use of the root logger as the parent.<\/span><\/p>\nBack on track, once you have prepared a configuration file, you can attach it to a logger with these simple lines of code:<\/span><\/p>\nimport logging.config\r\n\r\nlogging.config.fileConfig('\/path\/to\/logging.ini',\r\n disable_existing_loggers=False)\r\nlogger = logging.getLogger(__name__)\r\n<\/pre>\nIn this example, we also included disable_existing_loggers set to False, which ensure that pre-existing loggers are not removed when this snippet is executed; this is usually a good tip, as many modules declare a global logger that will be instantiated before fileConfig() is called.<\/p>\n
dictConfig()<\/h2>\n The logging configuration with all the properties we have described can be also defined as a standard dictionary object. This dictionary should follow the structure presented for the fileConfig() with sections covering loggers, handlers, and formatters with some global parameters. \nHere\u2019s an example:<\/p>\n
import logging.config\r\n\r\n\r\nconfig = {\r\n \"version\": 1,\r\n \"disable_existing_loggers\": False,\r\n \"formatters\": {\r\n \"standard\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n }\r\n },\r\n \"handlers\": {\r\n \"standard\": {\r\n \"class\": \"logging.StreamHandler\",\r\n \"formatter\": \"standard\"\r\n }\r\n },\r\n \"loggers\": {\r\n \"\": {\r\n \"handlers\": [\"standard\"],\r\n \"level\": logging.INFO\r\n }\r\n }\r\n}\r\n<\/pre>\nTo apply this configuration simply pass it as the parameter for the dict config:<\/span><\/p>\nlogging.config.dictConfig(config)<\/pre>\ndictConfig() will also disable all existing loggers unless disable_existing_loggers is set to False like we did in the fileConfig() example before.<\/p>\n
This configuration can be also stored in a YAML file and configured from there. Many developers often prefer using dictConfig() over fileConfig(), as it offers more ways to customize parameters and is more readable and maintainable.<\/p>\n
Formatting logs the JSON way<\/h2>\n Thanks to the way it is designed, it is easy to extend the logging module. Because our goal is to automate logging and integrate it with Kibana we want a format more suitable for adding custom properties and more compatible with custom workloads. So we want to configure a JSON formatter.<\/strong><\/p>\nIf we want, we can log JSON by creating a custom formatter that transforms the log records into a JSON-encoded string:<\/p>\n
import logging\r\nimport json\r\n\r\n\r\nclass JsonFormatter:\r\n def format(self, record):\r\n formatted_record = dict()\r\n\r\n for key in ['created', 'levelname', 'pathname', 'msg']:\r\n formatted_record[key] = getattr(record, key)\r\n\r\n return json.dumps(formatted_record, indent=4)\r\n\r\n\r\nhandler = logging.StreamHandler()\r\nhandler.formatter = JsonFormatter()\r\n\r\nlogger = logging.getLogger(__name__)\r\nlogger.addHandler(handler)\r\n\r\nlogger.error(\"Test\")\r\n<\/pre>\nIf you don\u2019t want to create your own custom formatter, you can rely on various libraries, developed by the Python Community, that can help you convert your logs into JSON format. \nOne of them is python-json-logger to convert log records into JSON. \nFirst, install it in your environment:<\/p>\n
pip install python-json-logger<\/pre>\nNow update the logging configuration dictionary to customize an existing formatter or create a new formatter that will format logs in JSON like in the example below. To use the JSON formatter add pythonjsonlogger.jsonlogger.JsonFormatter as the reference for “class” property. In the formatter\u2019s “format” property, you can define the attributes you\u2019d like to have in the log\u2019s JSON record:<\/p>\n
import logging.config \r\n\r\n\r\nconfig = {\r\n \"version\": 1,\r\n \"disable_existing_loggers\": False,\r\n \"formatters\": {\r\n \"standard\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n },\r\n \"json\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n \"class\": \"pythonjsonlogger.jsonlogger.JsonFormatter\"\r\n }\r\n },\r\n \"handlers\": {\r\n \"standard\": {\r\n \"class\": \"logging.StreamHandler\",\r\n \"formatter\": \"json\"\r\n }\r\n },\r\n \"loggers\": {\r\n \"\": {\r\n \"handlers\": [\"standard\"],\r\n \"level\": LogLevel.INFO.value\r\n }\r\n }\r\n}\r\n\r\nlogging.config.dictConfig(config)\r\nlogger = logging.getLogger(__name__)\r\n<\/pre>\nLogs that get sent to the console, through the standard handler, will get written in JSON format.<\/p>\n
Once you\u2019ve included the pythonjsonlogger.jsonlogger.JsonFormatter class in your logging configuration file, the dictConfig() function should be able to create an instance of it as long as you run the code from an environment where it can import python-json-logger module.<\/p>\n
Add contextual information to your logs<\/h2>\n If you need to add some context to your logs, Python\u2019s logging module gives you the possibility to inject custom attributes<\/strong> to them. An elegant way to enrich your logs involves the use of the LoggerAdapter class.<\/p>\nlogger = logging.LoggerAdapter(logger, {\"custom_key1\": \"custom_value1\", \"custom_key2\": \"custom_value2\"})<\/pre>\nThis effectively adds custom attributes to all the records that go through that logger. \nNote that this impacts all log records in your application, including libraries or other frameworks that you might be using and for which you are emitting logs. It can be used to log things like a unique request ID on all log lines to track requests or to add extra contextual information.<\/p>\n
Python exception handling and tracebacks<\/h2>\n By default<\/strong>, errors don\u2019t include any traceback information. The log will simply show the exception as an error, without any other information. To make sure that logging.error() prints the entire traceback, add the exc_info property with True value. To show the difference, let\u2019s try logging an exception with and without exc_info.<\/p>\nimport logging.config\r\n\r\n\r\nconfig = {\r\n \"version\": 1,\r\n \"disable_existing_loggers\": False,\r\n \"formatters\": {\r\n \"standard\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n },\r\n \"json\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n \"class\": \"pythonjsonlogger.jsonlogger.JsonFormatter\"\r\n }\r\n },\r\n \"handlers\": {\r\n \"standard\": {\r\n \"class\": \"logging.StreamHandler\",\r\n \"formatter\": \"json\"\r\n }\r\n },\r\n \"loggers\": {\r\n \"\": {\r\n \"handlers\": [\"standard\"],\r\n \"level\": logging.INFO\r\n }\r\n }\r\n}\r\n\r\nlogging.config.dictConfig(config)\r\nlogger = logging.getLogger(__name__)\r\n\r\n\r\ndef test():\r\n try:\r\n raise NameError(\"fake NameError\")\r\n except NameError as e:\r\n logger.error(e)\r\n logger.error(e, exc_info=True)\r\n<\/pre>\nIf you run test() method, it will generate the following output:<\/p>\n
{\"asctime\": \"2020-05-10T16:43:12+0200\", \"name\": \"logging_test\", \"levelname\": \"ERROR\", \"message\": \"fake NameError\"}\r\n \r\n{\"asctime\": \"2020-05-10T16:43:12+0200\", \"name\": \"logging_test\", \"levelname\": \"ERROR\", \"message\": \"fake NameError\", \"exc_info\": \"Traceback (most recent call last):\\n File \\\"\/Users\/aleric\/Projects\/logging-test\/src\/logging_test.py\\\", line 39, in test\\n raise NameError(\\\"fake NameError\\\")\\nNameError: fake NameError\"}\r\n<\/pre>\nAs we can see the first line doesn\u2019t provide much information about the error apart from a generic message fake NameError; instead the second line, by adding the property exc_info=True, shows the full traceback, which includes information about methods involved and line numbers to follow back and see where the exception was raised.<\/p>\n
As an alternative you can achieve the same result by using logger.exception() from an exception handler like in the example below:<\/p>\n
def test():\r\n try:\r\n raise NameError(\"fake NameError\")\r\n except NameError as e:\r\n logger.error(e)\r\n logger.exception(e)\r\n<\/pre>\nThis can retrieve the same traceback information by using exc_info=True. This has also the benefit of setting the priority level of the log to logging.ERROR.<\/p>\n
Regardless of which method you use to capture the traceback, having the full exception information available in your logs is critical for monitoring and troubleshooting the performance of your applications.<\/p>\n
Capturing unhandled exceptions<\/h2>\n Even by thinking about every possible scenario, it’s guaranteed that you can never catch every exception in your application nor is it a recommended behavior but still you can log uncaught exceptions so you can investigate them later on.<\/p>\n
An unhandled exception can be outside of a try\/except block, or when you don\u2019t include the correct type in your except block.<\/p>\n
If an exception is not handled in the method it occurs it starts bubbling up until it reaches a fitting except block or until it reaches the main block.<\/p>\n
If it is not catched it becomes an unhandled exception and the interpreter will invoke sys.excepthook(). The information given by the method usually appears in sys.stderr but the traceback information won\u2019t get logged there if you haven\u2019t explicitly set the traceback to be shown in a non default handler (e.g. a fileHandler).<\/p>\n
You can use Python\u2019s standard traceback library to format the traceback<\/strong> and include it in the log message.<\/p>\nLet\u2019s revise our example function to raise an exception not managed by our try except block to see the behavior we\u2019ve described above:<\/p>\n
import logging.config\r\nimport traceback\r\n\r\nconfig = {\r\n \"version\": 1,\r\n \"disable_existing_loggers\": False,\r\n \"formatters\": {\r\n \"standard\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n },\r\n \"json\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n \"class\": \"pythonjsonlogger.jsonlogger.JsonFormatter\"\r\n }\r\n },\r\n \"handlers\": {\r\n \"standard\": {\r\n \"class\": \"logging.StreamHandler\",\r\n \"formatter\": \"json\"\r\n }\r\n },\r\n \"loggers\": {\r\n \"\": {\r\n \"handlers\": [\"standard\"],\r\n \"level\": logging.INFO\r\n }\r\n }\r\n}\r\n\r\nlogging.config.dictConfig(config)\r\nlogger = logging.getLogger(__name__)\r\n\r\n\r\ndef test():\r\n try:\r\n raise OSError(\"fake OSError\")\r\n except NameError as e:\r\n logger.error(e, exc_info=True)\r\n except:\r\n logger.error(\"Uncaught exception: %s\", traceback.format_exc())\r\n<\/pre>\nRunning this code will throw a OSError exception that doesn\u2019t get handled in the try-except logic, but thanks to having the traceback code, it will get logged, as we can see in the second except clause:<\/p>\n
{\"asctime\": \"2020-05-10T17:04:05+0200\", \"name\": \"logging_test\", \"levelname\": \"ERROR\", \"message\": \"Uncaught exception: Traceback (most recent call last):\\n File \\\"\/Users\/aleric\/Projects\/logging-test\/src\/logging_test4.py\\\", line 38, in test\\n raise OSError(\\\"fake OSError\\\")\\nOSError: fake OSError\\n\"}<\/pre>\nLogging the full traceback within each handled and unhandled exception provides critical visibility<\/strong> into errors as they occur in real time, so that you can investigate when and why they occurred.<\/p>\nThis is the end for part one of this two-part article, in the next one, we\u2019ll cover how to aggregate logs using Kinesis Stream and ElasticSearch<\/strong> and putting all together in a highly customizable Kibana Dashboard.<\/strong><\/p>\nStay tuned \ud83d\ude42<\/p>\n
\nGo to part II<\/a><\/p>\n","protected":false},"excerpt":{"rendered":"Applications running in production lose their ability to tell us directly what is going on under the hood, they become […]<\/p>\n","protected":false},"author":6,"featured_media":1448,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[478],"tags":[270,262,266,274],"class_list":["post-1384","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-cloud-native-development-en","tag-amazon-elasticsearch-service-en","tag-amazon-kinesis-data-firehose-en","tag-kibana-en","tag-python-en"],"yoast_head":"\n
Part I: Python logging best practices and how to integrate with Kibana Dashboard through AWS Kinesis Data Firehose and Amazon Elasticsearch Service - Proud2beCloud Blog<\/title>\n \n \n \n \n \n \n \n \n \n \n \n \n\t \n\t \n\t \n \n \n \n \n \n \n\t \n\t \n\t \n