{
"cells": [
{
"cell_type": "markdown",
"metadata": {},
"source": [
"# Basic usage of python logging module\n",
"**Paola Petrelli, CLEX CMS**"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Most people use *print* statements to debug their code, uncommenting them when they need them and commenting them again when they have finished. \n",
"Python has some proper debugging modules like *pdb* or you might be using an IDE with debug functionality like *pycharm* . \n",
"Look here for a list: https://wiki.python.org/moin/PythonDebuggingTools ). \n",
"While these tools are certainly good, in this blog I will show you how to use the **logging** module. This module, used in a basic mode, is as easy as printing statements but will give you a lot more control on your code and the ability to eventually add more advanced features. \n",
"As well as demostrating some simple usage of **logging**, I will touch on other simple but useful debugging tools: the functions **type()** and **dir()** and the **try/except** control flow.
\n",
"**logging** is part of the python distribution so you do not need to install or load anything else, simply import the module.
\n",
"**NB** I am using python3.5 there might be difference if you are using a different version. \n",
"Also jupyter can send your logging output to the terminal rather then the cell and generally interacts with logging in its own way. While you might be able to fix this after reading the blog, using python would make reproducing this easier."
]
},
{
"cell_type": "code",
"execution_count": 1,
"metadata": {
"collapsed": true,
"jupyter": {
"outputs_hidden": true
}
},
"outputs": [],
"source": [
"import logging"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Now we are ready to start! "
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"**Printing out messages and logging levels**\n",
"--"
]
},
{
"cell_type": "code",
"execution_count": 2,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [],
"source": [
"logging.warning('This is a warning message this should be printed on your console')\n",
"logging.info('This is an info message the code will not print this unless you change its operating level')"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"All we have to do is to call one of the logging printing method, we used *warning* and *info*. \n",
"Let's have a look at the message we printed. \n",
"The first part indicates the logging level, in this case *WARNING*. \n",
"The second part *root* is telling us that we are using the *root logger* i.e. the default logger, in fact we haven't set up anything up to now, but just started using logging. \n",
"Finally there is the message. \n",
"The **logging.info** command didn't produce any output. Logging has 5 different levels. From the lowest: \n",
" * DEBUG\n",
" * INFO\n",
" * WARNING\n",
" * ERROR\n",
" * CRITICAL \n",
" \n",
"Logging will only show the messages which are of level >= of the set level, the default level is *warning* so our *info* message is not getting printed. \n",
"Let's change the level."
]
},
{
"cell_type": "code",
"execution_count": 3,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [],
"source": [
"logging.basicConfig(level=logging.INFO) # Note the logging levels are defined in the logging attributes, not by a string!\n",
"logging.warning('This is a warning message this should be printed on your console, its level is above the set level')\n",
"logging.info('This is an info message it should be printed now!')\n",
"logging.debug('This is a debug message which will not be shown, its level is below the set level')"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Oops nothing happened, the level is still set to *warning*. Let's pretend we researched this, there could various situations when this happens. In my brief experience, it is usually because: *This function does nothing if the root logger has already handlers configured*.
\n",
"The root logger is set up so you can get logging to work straight on as we did. *Loggers* are the logging objects we are dealing with. Like all other python variables, they have some attributes and some methods. So when we use **logging.info()** for example we are calling the method **info()** of our root logger. A logging **handler** takes a log message and send it to an output, this could the console (default) or a file, an e-mail or more complex outputs.
\n",
"This might seems complicated but now that we know there is already a logger defined, we know we need to disable it somehow.
\n",
"We can use two approaches:\n",
"* disable the root logger handlers and start afresh\n",
"* setup our own logger object pointing at the root logger
\n",
"\n",
"Let's start with disabling the root logger handlers first and then we'll see how to set our own logger."
]
},
{
"cell_type": "code",
"execution_count": 4,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"WARNING:root:This is a warning message this should be printed on your console, its level is above the set level\n",
"INFO:root:This is an info message it should be printed now!\n"
]
}
],
"source": [
"# Remove all handlers associated with the root logger object.\n",
"for handler in logging.root.handlers[:]:\n",
" logging.root.removeHandler(handler)\n",
"logging.basicConfig(level=logging.INFO) \n",
"logging.warning('This is a warning message this should be printed on your console, its level is above the set level')\n",
"logging.info('This is an info message it should be printed now!')\n",
"logging.debug('This is a debug message which will not be shown, its level is below the set level')"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"**Setting up a logger**\n",
"--"
]
},
{
"cell_type": "code",
"execution_count": 5,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"WARNING:mylogger:This is a warning message this should be printed on your console, its level is above the set level\n",
"INFO:mylogger:This is an info message it should be printed now!\n"
]
}
],
"source": [
"# Note: this works because we configured the root logger before.\n",
"# if you are starting from scratch uncomment the lines below\n",
"#import logging\n",
"#for handler in logging.root.handlers[:]:\n",
"# logging.root.removeHandler(handler)\n",
"#logging.basicConfig(level=logging.INFO)\n",
"\n",
"mylog = logging.getLogger('mylogger')\n",
"mylog.setLevel(logging.INFO)\n",
"mylog.warning('This is a warning message this should be printed on your console, its level is above the set level')\n",
"mylog.info('This is an info message it should be printed now!')\n",
"mylog.debug('This is a debug message which will not be shown, its level is below the set level')"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"We created a new logger and save it to a variable using **getLogger()**. \n",
"Then we use **setLevel()** to change the level to INFO and the messages are showing as expected. \n",
"If we want to run the code in debug mode we can now change only the logging level instead of commenting/uncommenting print statements."
]
},
{
"cell_type": "code",
"execution_count": 6,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"WARNING:mylogger:I now have two loggers working!\n",
"WARNING:root:I can still use the root logger\n",
"WARNING:root:This is still the root logger, I have just saved it to a different variable\n"
]
}
],
"source": [
"mylog.warning('I now have two loggers working!')\n",
"logging.warning('I can still use the root logger')\n",
"root_logger = logging.getLogger()\n",
"root_logger.warning('This is still the root logger, I have just saved it to a different variable')"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"The root logger it's still working, we can use one of the other.
\n",
"We can also saved the root logger to a variable by using the **get_logger()** function without any arguments.
\n",
"This is a good start but let's see how we can actually print out something a bit more useful. \n",
"Personally when I'm trying to debug something there are 3 things which I usually print: the variable value, its type and the methods and attributes. Remember, in python any variable is an object and can have more or less complex methods (functions) and attributes. "
]
},
{
"cell_type": "code",
"execution_count": 7,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"WARNING:mylogger:This script is totally useless\n",
"INFO:mylogger:Starting complex calculation\n",
"INFO:mylogger:Calculation completed, result is 1\n"
]
}
],
"source": [
"mylog.warning('This script is totally useless')\n",
"var1 = 1\n",
"var2 = 0\n",
"mylog.debug('Input values are %d %d', var1, var2)\n",
"mylog.info('Starting complex calculation')\n",
"result = var1 + var2\n",
"mylog.info('Calculation completed, result is %d', result)"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"This looks more like a script, first of all we are starting using the levels as appropriate. \n",
"INFO is used to define the steps our script is going through and show us the result of our calculation. \n",
"WARNING is telling the user something which is potentially an issue but not an error. \n",
"DEBUG is ready to show us the values of the variables we used, should something go wrong. \n",
"Please note that I am using *%d* as a number placeholder. \n",
"Let's now generate an error.\n"
]
},
{
"cell_type": "code",
"execution_count": 8,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"WARNING:mylogger:This script is totally useless\n",
"INFO:mylogger:Starting complex calculation\n"
]
},
{
"ename": "TypeError",
"evalue": "unsupported operand type(s) for +: 'int' and 'str'",
"output_type": "error",
"traceback": [
"\u001b[0;31m---------------------------------------------------------------------------\u001b[0m",
"\u001b[0;31mTypeError\u001b[0m Traceback (most recent call last)",
"\u001b[0;32m\u001b[0m in \u001b[0;36m\u001b[0;34m()\u001b[0m\n\u001b[1;32m 4\u001b[0m \u001b[0mmylog\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0mdebug\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0;34m'Input values are %d %d'\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mvar1\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mvar2\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m 5\u001b[0m \u001b[0mmylog\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0minfo\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0;34m'Starting complex calculation'\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0;32m----> 6\u001b[0;31m \u001b[0mresult\u001b[0m \u001b[0;34m=\u001b[0m \u001b[0mvar1\u001b[0m \u001b[0;34m+\u001b[0m \u001b[0mvar2\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0m\u001b[1;32m 7\u001b[0m \u001b[0mmylog\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0minfo\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0;34m'Calculation completed, result is %d'\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mresult\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n",
"\u001b[0;31mTypeError\u001b[0m: unsupported operand type(s) for +: 'int' and 'str'"
]
}
],
"source": [
"mylog.warning('This script is totally useless')\n",
"var1 = 1\n",
"var2 = '0'\n",
"mylog.debug('Input values are %d %d', var1, var2)\n",
"mylog.info('Starting complex calculation')\n",
"result = var1 + var2\n",
"mylog.info('Calculation completed, result is %d', result)"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Instead of 0 we passed the equivalent string so we get an error. Let's switch to *debug* level.\n",
"\n"
]
},
{
"cell_type": "code",
"execution_count": 9,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"WARNING:mylogger:This script is totally useless\n",
"--- Logging error ---\n",
"Traceback (most recent call last):\n",
" File \"/Users/paolap/anaconda/lib/python3.5/logging/__init__.py\", line 980, in emit\n",
" msg = self.format(record)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/logging/__init__.py\", line 830, in format\n",
" return fmt.format(record)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/logging/__init__.py\", line 567, in format\n",
" record.message = record.getMessage()\n",
" File \"/Users/paolap/anaconda/lib/python3.5/logging/__init__.py\", line 330, in getMessage\n",
" msg = msg % self.args\n",
"TypeError: %d format: a number is required, not str\n",
"Call stack:\n",
" File \"/Users/paolap/anaconda/lib/python3.5/runpy.py\", line 184, in _run_module_as_main\n",
" \"__main__\", mod_spec)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/runpy.py\", line 85, in _run_code\n",
" exec(code, run_globals)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/__main__.py\", line 3, in \n",
" app.launch_new_instance()\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/traitlets/config/application.py\", line 596, in launch_instance\n",
" app.start()\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/kernelapp.py\", line 442, in start\n",
" ioloop.IOLoop.instance().start()\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/zmq/eventloop/ioloop.py\", line 162, in start\n",
" super(ZMQIOLoop, self).start()\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/tornado/ioloop.py\", line 883, in start\n",
" handler_func(fd_obj, events)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/tornado/stack_context.py\", line 275, in null_wrapper\n",
" return fn(*args, **kwargs)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/zmq/eventloop/zmqstream.py\", line 440, in _handle_events\n",
" self._handle_recv()\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/zmq/eventloop/zmqstream.py\", line 472, in _handle_recv\n",
" self._run_callback(callback, msg)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/zmq/eventloop/zmqstream.py\", line 414, in _run_callback\n",
" callback(*args, **kwargs)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/tornado/stack_context.py\", line 275, in null_wrapper\n",
" return fn(*args, **kwargs)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/kernelbase.py\", line 276, in dispatcher\n",
" return self.dispatch_shell(stream, msg)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/kernelbase.py\", line 228, in dispatch_shell\n",
" handler(stream, idents, msg)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/kernelbase.py\", line 391, in execute_request\n",
" user_expressions, allow_stdin)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/ipkernel.py\", line 199, in do_execute\n",
" shell.run_cell(code, store_history=store_history, silent=silent)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/IPython/core/interactiveshell.py\", line 2723, in run_cell\n",
" interactivity=interactivity, compiler=compiler, result=result)\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/IPython/core/interactiveshell.py\", line 2825, in run_ast_nodes\n",
" if self.run_code(code, result):\n",
" File \"/Users/paolap/anaconda/lib/python3.5/site-packages/IPython/core/interactiveshell.py\", line 2885, in run_code\n",
" exec(code_obj, self.user_global_ns, self.user_ns)\n",
" File \"\", line 5, in \n",
" mylog.debug('Input values are %d %d', var1, var2)\n",
"Message: 'Input values are %d %d'\n",
"Arguments: (1, '0')\n",
"INFO:mylogger:Starting complex calculation\n"
]
},
{
"ename": "TypeError",
"evalue": "unsupported operand type(s) for +: 'int' and 'str'",
"output_type": "error",
"traceback": [
"\u001b[0;31m---------------------------------------------------------------------------\u001b[0m",
"\u001b[0;31mTypeError\u001b[0m Traceback (most recent call last)",
"\u001b[0;32m\u001b[0m in \u001b[0;36m\u001b[0;34m()\u001b[0m\n\u001b[1;32m 5\u001b[0m \u001b[0mmylog\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0mdebug\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0;34m'Input values are %d %d'\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mvar1\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mvar2\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m 6\u001b[0m \u001b[0mmylog\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0minfo\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0;34m'Starting complex calculation'\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0;32m----> 7\u001b[0;31m \u001b[0mresult\u001b[0m \u001b[0;34m=\u001b[0m \u001b[0mvar1\u001b[0m \u001b[0;34m+\u001b[0m \u001b[0mvar2\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0m\u001b[1;32m 8\u001b[0m \u001b[0mmylog\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0minfo\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0;34m'Calculation completed, result is %d'\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mresult\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n",
"\u001b[0;31mTypeError\u001b[0m: unsupported operand type(s) for +: 'int' and 'str'"
]
}
],
"source": [
"mylog.setLevel(logging.DEBUG)\n",
"mylog.warning('This script is totally useless')\n",
"var1 = 1\n",
"var2 = '0'\n",
"mylog.debug('Input values are %d %d', var1, var2)\n",
"mylog.info('Starting complex calculation')\n",
"result = var1 + var2\n",
"mylog.info('Calculation completed, result is %d', result)"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Funnily enough, now we have two separate error messages: \n",
"* The debug statement uses %d as place holder which fails when passed a string, we can use %s instead which is a string place holder and works with basically everything. You will notice that this error didn't stop the code from going on. This is a useful feature!\n",
"* The second error message tells us we have a type error, we can improve our debug message to catch this better.\n",
"\n"
]
},
{
"cell_type": "code",
"execution_count": 10,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"WARNING:mylogger:This script is totally useless\n",
"DEBUG:mylogger:Input values are 1 0, their respective types are and \n",
"INFO:mylogger:Starting complex calculation\n"
]
},
{
"ename": "TypeError",
"evalue": "unsupported operand type(s) for +: 'int' and 'str'",
"output_type": "error",
"traceback": [
"\u001b[0;31m---------------------------------------------------------------------------\u001b[0m",
"\u001b[0;31mTypeError\u001b[0m Traceback (most recent call last)",
"\u001b[0;32m\u001b[0m in \u001b[0;36m\u001b[0;34m()\u001b[0m\n\u001b[1;32m 4\u001b[0m \u001b[0mmylog\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0mdebug\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0;34m'Input values are %s %s, their respective types are %s and %s'\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mvar1\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mvar2\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mtype\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0mvar1\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mtype\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0mvar2\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m 5\u001b[0m \u001b[0mmylog\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0minfo\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0;34m'Starting complex calculation'\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0;32m----> 6\u001b[0;31m \u001b[0mresult\u001b[0m \u001b[0;34m=\u001b[0m \u001b[0mvar1\u001b[0m \u001b[0;34m+\u001b[0m \u001b[0mvar2\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0m\u001b[1;32m 7\u001b[0m \u001b[0mmylog\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0minfo\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0;34m'Calculation completed, result is %s'\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mresult\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n",
"\u001b[0;31mTypeError\u001b[0m: unsupported operand type(s) for +: 'int' and 'str'"
]
}
],
"source": [
"mylog.warning('This script is totally useless')\n",
"var1 = 1\n",
"var2 = '0'\n",
"mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))\n",
"mylog.info('Starting complex calculation')\n",
"result = var1 + var2\n",
"mylog.info('Calculation completed, result is %s', result)"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"This is better except in good programming, the programmer is expected to handle errors rather than letting the code to crash. An easy way to do this is the the **try: except:** statements. \n",
"\n",
"Let's also see what the *ERROR* level does. We can safely ignore CRITICAL that's reserved for an error which can have catastrophic consequences and it's probably not useful to us. \n",
"\n",
"Let's get back to a lower level of logging and run the script again.\n"
]
},
{
"cell_type": "code",
"execution_count": 11,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"WARNING:mylogger:This script is totally useless\n",
"INFO:mylogger:Starting complex calculation\n",
"ERROR:mylogger:There is an issue adding 1 and 0\n",
"WARNING:mylogger:I am still going on!\n",
"INFO:mylogger:Calculation completed, result is 1\n"
]
}
],
"source": [
"mylog.setLevel(logging.INFO)\n",
"mylog.warning('This script is totally useless')\n",
"var1 = 1\n",
"var2 = '0'\n",
"mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))\n",
"mylog.info('Starting complex calculation')\n",
"try:\n",
" result = var1 + var2\n",
"except: \n",
" mylog.error('There is an issue adding %s and %s', var1, var2)\n",
"mylog.warning('I am still going on!')\n",
"# Last statement still print fine because we haven't deleted result\n",
"mylog.info('Calculation completed, result is %s', result)"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"We tried to do 1 + '0' which failed so the code moved on executing the **except** statement rather then stopping and throwing out an error. \n",
"While often we want our code to stop when failing, there are situations where we can remedy the error. **try/except** help us handling those cases. For example if you want to open a file and you are not sure if exists already you could **try** to open the file, if that fails you can use **except** to create first and then open the file. \n",
"The other common case is to simply use **try/except** as we did to choose an error message to print out and then exit the code by adding **sys.exit()** at the end or going on depending on how critical the error is. \n",
"Note that because we are using **try/except** we cannot see the standard error message anymore, since this could be useful let's see how we can get both. "
]
},
{
"cell_type": "code",
"execution_count": 12,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"WARNING:mylogger:This script is totally useless\n",
"INFO:mylogger:Starting complex calculation\n",
"ERROR:mylogger:There some issue with adding 1 and 0\n",
"Traceback (most recent call last):\n",
" File \"\", line 7, in \n",
" result = var1 + var2\n",
"TypeError: unsupported operand type(s) for +: 'int' and 'str'\n",
"ERROR:mylogger:There is some issue adding 1 and 0\n",
"Traceback (most recent call last):\n",
" File \"\", line 7, in \n",
" result = var1 + var2\n",
"TypeError: unsupported operand type(s) for +: 'int' and 'str'\n",
"WARNING:mylogger:I am still going on!\n",
"INFO:mylogger:Calculation completed, result is 1\n"
]
}
],
"source": [
"mylog.warning('This script is totally useless')\n",
"var1 = 1\n",
"var2 = '0'\n",
"mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))\n",
"mylog.info('Starting complex calculation')\n",
"try:\n",
" result = var1 + var2\n",
"except: \n",
" mylog.error('There some issue with adding %s and %s', var1, var2, exc_info=True)\n",
" mylog.exception('There is some issue adding %s and %s', var1, var2)\n",
"mylog.warning('I am still going on!')\n",
"mylog.info('Calculation completed, result is %d', result)"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"By adding *exc_info=True* to the **logger.error()** we can get also the traceback error again. Please note that you can achieve exactly the same using **logger.exception()**. \n",
"\n",
"This is a fairly straightforward error, sometimes when you have variables going from one function to another and using modules you are not familiar with, you might end up with mysterious objects that don't work as you expect. Or simply, you might want to understand better the objects' properties. This is where the function **dir()** comes handy. \n",
"Let's look at a simple example."
]
},
{
"cell_type": "code",
"execution_count": 13,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"['copy', 'fromkeys', 'get', 'items', 'keys']\n",
"pop is %s \n",
"keys is %s \n"
]
}
],
"source": [
"a = {'key1': 1, 'key2': 2}\n",
"print( dir(a)[-10:-5])\n",
"print('pop is %s', type(a.pop))\n",
"print('keys is %s', type(a.keys)) \n",
"# There's a new way to print formatted string introduced in python3.6, which accept any expression in {} embedded in the string\n",
"# then evaluates the expression before printing.\n",
"# It doesn't work yet in notebooks, but it will if you run directly with python.\n",
"# print(f\"pop is {type(a.pop)}\")\n",
"# print(f\"the sum of {var1} and {var2} is {var1 + var2}\")"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"We defined a dictionary and used **dir()** to list all its properties, some are attributes and some are methods. **type()** will tell us that. Please note **dir()** returns a list and we printed only a subset to avoid a long listing. \n",
"In fact lots of the debugging information might be better off sent to a file, this will allow us to keep a record we can check later and to separate it from the usual print statements, or better, INFO and WARNING level statements. We'll have a look at how to do this in the second part.\n",
"\n"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"**Sending messages to different ouputs**\n",
"--"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Remember the handlers at the start of the blog? We will have a quick look at how to use them to send different levels of messages to different output channels.
\n",
"\n",
"To make testing easier we will write the logger setup as a function that takes the logger level as input."
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"We defined the file_handler simply by giving it a filename, there are other options we could set at the same time, but that's the only one we need.
\n",
"We set the file_handler level to DEBUG and add a *formatter* to add before the message:
\n",
" time | logger_name | log level
\n",
"NB I added a *'w'* to the file handler definition so it will create a new file each time.
\n",
"Finally we add it to the logger and add a debug message to test it.
\n",
"Let's call the function using INFO as input level. Remember this is setting the level for the logger not the file_handler.
\n",
"**IMPORTANT**
Because we are disabling all the existing handlers after importing the module we need to set up a level for the root logger!
\n",
"You can use the basicConfig command only once in a session, if you try to run it twice it won't do anything."
]
},
{
"cell_type": "code",
"execution_count": 14,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"INFO:clever_logger:This function is a logging demo\n",
"INFO:clever_logger:Code ends here!\n"
]
}
],
"source": [
"%%script python3\n",
"# I am using this to run this as a separate script so we start with a clean enviroment!\n",
"import logging\n",
"# remember to uncomment these lines if you have want to set your own root logger\n",
"#for handler in logging.root.handlers[:]:\n",
"# logging.root.removeHandler(handler)\n",
"# We disabled the existing handlers after import logging so we can configure the root logger as we want\n",
"# We set the level to root logger level to WARNING\n",
"logging.basicConfig(level=logging.WARNING)\n",
"\n",
"def log_setup(name, level, fname):\n",
" '''This function will setup a logger with the name and level you pass as input'''\n",
" # start a logger\n",
" logger = logging.getLogger(name)\n",
" # set a formatter to manage the output format of our handler\n",
" formatter = logging.Formatter('%(asctime)s | %(name)s | %(levelname)s: %(message)s')\n",
" # set the level passed as input, has to be logging.LEVEL not a string\n",
" # until we do so mylog doesn't have a level and inherits the root logger level:WARNING\n",
" logger.setLevel(level)\n",
"\n",
" # add a handler to send INFO level messages to console\n",
"\n",
" # add a handler to send DEBUG level messages to file\n",
" # all you need is a file name I added the 'w' so each time a new file will be created\n",
" # without it the messagges will be appended to the same file\n",
" file_handler = logging.FileHandler(fname,'w')\n",
" file_handler.setLevel(logging.DEBUG)\n",
" file_handler.setFormatter(formatter)\n",
" logger.addHandler(file_handler)\n",
"\n",
" # return the logger object\n",
" return logger\n",
"\n",
"# call function to setup the logger to the lowest level (DEBUG) so we can see all the messages!\n",
"mylog = log_setup('clever_logger', logging.INFO, 'mycode_debug.log')\n",
"# add some debug messages\n",
"mylog.info('This function is a logging demo')\n",
"var1 = 1\n",
"var2 = '0'\n",
"mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))\n",
"mylog.info('Code ends here!')"
]
},
{
"cell_type": "code",
"execution_count": 15,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"2018-10-05 12:16:29,093 | clever_logger | INFO: This function is a logging demo\n",
"2018-10-05 12:16:29,093 | clever_logger | INFO: Code ends here!\n"
]
}
],
"source": [
"!cat mycode_debug.log"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"The output shows that the INFO message was printed out both in the file and on the console. There's no trace of the debug message in the file even if the file_handler level was set to DEBUG!! \n",
"Let's try to run it again but passing DEBUG as level.
\n",
"I'm running the same script directly from the command line."
]
},
{
"cell_type": "code",
"execution_count": 16,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"INFO:clever_logger:This function is a logging demo\n",
"DEBUG:clever_logger:Input values are 1 0, their respective types are and \n",
"INFO:clever_logger:Code ends here!\n"
]
}
],
"source": [
"# the console output\n",
"!python demo_log.py > out.txt\n",
"!cat out.txt"
]
},
{
"cell_type": "code",
"execution_count": 17,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"2018-10-05 12:16:37,998 | clever_logger | INFO: This function is a logging demo\n",
"2018-10-05 12:16:37,998 | clever_logger | DEBUG: Input values are 1 0, their respective types are and \n",
"2018-10-05 12:16:37,998 | clever_logger | INFO: Code ends here!\n"
]
}
],
"source": [
"# the file output\n",
"!cat mycode_debug.log"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Ok now we can see the debug message!
\n",
"We couldn't before because the logger level was setting the lowest possible level to INFO so even if we set the file level to DEBUG this was bumped up to INFO.
\n",
"Luckily this can be easily fixed by setting the logger level to DEBUG, so now our file handler works as expected! The problem is that the debug messages are also showing on the console, if we want to set different levels we need to define **stream handler**."
]
},
{
"cell_type": "code",
"execution_count": 18,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"This function is a logging demo\n",
"Code ends here!\n"
]
}
],
"source": [
"%%script python3\n",
"# I am using this to run this as a separate script so we start with a clean enviroment!\n",
"\n",
"import logging\n",
"#for handler in logging.root.handlers[:]:\n",
"# logging.root.removeHandler(handler)\n",
"# We disabled the existing handlers after import logging so we can configure the root logger as we want\n",
"# We set the level to root logger level to WARNING\n",
"#logging.basicConfig(level=logging.WARNING)\n",
"\n",
"\n",
"def log_setup(name, level):\n",
" '''This function will setup a logger with the name and level you pass as input'''\n",
" # start a logger\n",
" logger = logging.getLogger(name)\n",
" # set a formatter to manage the output format of our handler\n",
" formatter = logging.Formatter('%(asctime)s | %(name)s | %(levelname)s: %(message)s')\n",
" # set the level passed as input, has to be logging.LEVEL not a string\n",
" # until we do so mylog doesn't have a level and inherits the root logger level:WARNING\n",
" logger.setLevel(level)\n",
" \n",
" # add a handler to send INFO level messages to console\n",
" console_handler = logging.StreamHandler()\n",
" console_handler.setLevel(logging.INFO)\n",
" logger.addHandler(console_handler) \n",
" \n",
" # add a handler to send DEBUG level messages to file \n",
" # all you need is a file name I added the 'w' so each time a new file will be created\n",
" # without it the messagges will be appended to the same file\n",
" file_handler = logging.FileHandler('mycode_debug.log','w') \n",
" file_handler.setLevel(logging.DEBUG)\n",
" file_handler.setFormatter(formatter)\n",
" logger.addHandler(file_handler)\n",
" \n",
" # return the logger object\n",
" return logger\n",
"\n",
"# call function to setup the logger to the lowest level (DEBUG) so we can see all the messages!\n",
"mylog = log_setup('clever_logger', logging.DEBUG)\n",
"# add some debug messages\n",
"mylog.info('This function is a logging demo')\n",
"var1 = 1\n",
"var2 = '0'\n",
"mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))\n",
"mylog.info('Code ends here!')"
]
},
{
"cell_type": "code",
"execution_count": 19,
"metadata": {
"jupyter": {
"outputs_hidden": false
}
},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"2018-10-05 12:16:48,654 | clever_logger | INFO: This function is a logging demo\n",
"2018-10-05 12:16:48,654 | clever_logger | DEBUG: Input values are 1 0, their respective types are and \n",
"2018-10-05 12:16:48,654 | clever_logger | INFO: Code ends here!\n"
]
}
],
"source": [
"!cat mycode_debug.log"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Now we are going to get all the message at level INFO or above printed on the console and the same plus the DEBUG messages saved on the file!
\n",
"NB Because now we set up a stream handler I'm ignoring completely the root logger and I commented the basicConfig command.
\n",
"If you try the same in the previous version you will, or better might since it depends on the starting logging config, find that nothing gets printed on the console. This is because our logger wouldn't have any stream handler to inherit from.\n",
"\n"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"I hope you'll find this helpful, once you understand the different loggers levels and how they interacts, this can be a very helpful module.
\n",
"While we started the demo using the root logger is probably a good practice to setup your own logger and use that in your code.
\n",
"You can use as a starting point the log_setup function we used in the last example.
\n",
"Keep also in mind that the root logger will be used by some of the modules you might be loading so changing its configuration level will affect them too. Once you are a bit more experienced you could use this if you want to get more information out of them or redirect their log output to a file.
"
]
}
],
"metadata": {
"kernelspec": {
"display_name": "Python 3 (ipykernel)",
"language": "python",
"name": "python3"
},
"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.10.5"
}
},
"nbformat": 4,
"nbformat_minor": 4
}