Logging is a way to store information about your script and track events that occur. When writing any complex script in Python, logging is essential for debugging software as you develop it. Without logging, finding the source of a problem in your code may be extremely time consuming.<\/p>\n
After completing this tutorial, you will know:<\/p>\n
- \n
- Why we would like to use the logging module<\/li>\n
- How to use the logging module<\/li>\n
- How to customize the logging mechanism<\/li>\n<\/ul>\n
Let\u2019s get started.<\/p>\n
\n![\"\"](\"https:\/\/machinelearningmastery.com\/wp-content\/uploads\/2022\/03\/pexels-ilaria-122588-scaled.jpg\")
<\/p>\nLogging in Python
Photo by ilaria88<\/a>. Some rights reserved.<\/p>\n<\/div>\nTutorial Overview<\/strong><\/h2>\n
This tutorial is divided into four parts; they are:<\/p>\n
- \n
- The benefits of logging<\/li>\n
- Basic logging<\/li>\n
- Advanced configuration to logging<\/li>\n
- An example of the use of logging<\/li>\n<\/ul>\n
Benefits of Logging<\/strong><\/h2>\n
You may ask: \u201cWhy not just use printing?\u201d<\/p>\n
When you run an algorithm and want to confirm it is doing what you expected, it is natural to add some
print()<\/code> statements at strategic locations to show the program\u2019s state. Printing can help debug simpler scripts, but as your code gets more and more complex, printing lacks the flexibility and robustness that logging has.<\/p>\nWith logging, you can pinpoint where a logging call came from, differentiate severity between messages, and write information to a file, which printing cannot do. For example, we can turn on and off the message from a particular module of a larger program. We can also increase or decrease the verbosity of the logging messages without changing a lot of code.<\/p>\n
Basic Logging<\/strong><\/h2>\n
Python has a built-in library,
logging,<\/code> for this purpose. It is simple to create a \u201clogger\u201d to log messages or information that you would like to see.<\/p>\nThe logging system in Python operates under a hierarchical namespace and different levels of severity. The Python script can create a logger under a namespace, and every time a message is logged, the script must specify its severity. The logged message can go to different places depending on the handler we set up for the namespace. The most common handler is to simply print on the screen, like the ubiquitous
print()<\/code> function. When we start the program, we may register a new handler and set up the level of severity to which the handler will react.<\/p>\nThere are 5 different logging levels that indicate the severity of the logs, shown in increasing severity:<\/p>\n
- \n
- DEBUG<\/li>\n
- INFO<\/li>\n
- WARNING<\/li>\n
- ERROR<\/li>\n
- CRITICAL<\/li>\n<\/ol>\n
A very simple example of logging is shown below, using the default logger or the root logger:<\/p>\n
import logging\r\n\r\nlogging.debug('Debug message')\r\nlogging.info('Info message')\r\nlogging.warning('Warning message')\r\nlogging.error('Error message')\r\nlogging.critical('Critical message')<\/pre>\nThese will emit log messages of different severity. While there are five lines of logging, you may see only three lines of output if you run this script, as follows:<\/p>\n
WARNING:root:This is a warning message\r\nERROR:root:This is an error message\r\nCRITICAL:root:This is a critical message<\/pre>\n
This is because the root logger, by default, only prints the log messages of a severity level of WARNING or above. However, using the root logger this way is not much different from using the print() function.<\/p>\n
The settings for the root logger are not set in stone. We can configure the root logger to output to a particular file, change its default severity level, and format the output.\u00a0Here\u2019s an example:<\/p>\n
import logging\r\n\r\nlogging.basicConfig(filename = 'file.log',\r\n level = logging.DEBUG,\r\n format = '%(asctime)s:%(levelname)s:%(name)s:%(message)s')\r\n\r\nlogging.debug('Debug message')\r\nlogging.info('Info message')\r\nlogging.warning('Warning message')\r\nlogging.error('Error message')\r\nlogging.critical('Critical message')<\/pre>\nRunning this script will produce no output to the screen but will have the following in the newly created file
file.log<\/code>:<\/p>\n2022-03-22 20:41:08,151:DEBUG:root:Debug message\r\n2022-03-22 20:41:08,152:INFO:root:Info message\r\n2022-03-22 20:41:08,152:WARNING:root:Warning message\r\n2022-03-22 20:41:08,152:ERROR:root:Error message\r\n2022-03-22 20:41:08,152:CRITICAL:root:Critical message<\/pre>\n
The call to
logging.basicConfig()<\/code> is to alter the root logger. In our example, we set the handler to output to a file instead of the screen, adjust the logging level such that all log messages of level DEBUG or above are handled, and also change the format of the log message output to include the time.<\/p>\nNote that now all five messages were output, so the default level that the root logger logs is now \u201cDEBUG.\u201d The log record attributes (such as
%(asctime)s<\/code>) that can be used to format the output can be found in the logging documentation<\/a>.<\/p>\nAlthough there is a default logger, we usually want to make and use other loggers that can be configured separately. This is because we may want a different severity level or format for different loggers. A new logger can be created with:<\/p>\n
logger = logging.getLogger(\"logger_name\")<\/pre>\n
Internally, the loggers are organized in a hierarchy. A logger created with:<\/p>\n
logger = logging.getLogger(\"parent.child\")<\/pre>\n
will be a child logger created under the logger with the name \u201c
parent<\/code>,\u201d which, in turn, is under the root logger. Using a dot in the string signifies that the child logger is a child of the parent logger. In the above case, a logger with the name \u201cparent.child<\/code>\u201d is created as well as one with the name\"parent\"<\/code> implicitly.<\/p>\nUpon creation, a child logger has all the properties of its parent logger until reconfigured. We can demonstrate this with the following example:<\/p>\n
import logging\r\n\r\n# Create `parent.child` logger\r\nlogger = logging.getLogger(\"parent.child\")\r\n\r\n# Emit a log message of level INFO, by default this is not print to the screen\r\nlogger.info(\"this is info level\")\r\n\r\n# Create `parent` logger\r\nparentlogger = logging.getLogger(\"parent\")\r\n\r\n# Set parent's level to INFO and assign a new handler\r\nhandler = logging.StreamHandler()\r\nhandler.setFormatter(logging.Formatter(\"%(asctime)s:%(name)s:%(levelname)s:%(message)s\"))\r\nparentlogger.setLevel(logging.INFO)\r\nparentlogger.addHandler(handler)\r\n\r\n# Let child logger emit a log message again\r\nlogger.info(\"this is info level again\")<\/pre>\n
This code snippet will output only one line:<\/p>\n
2022-03-28 19:23:29,315:parent.child:INFO:this is info level again<\/pre>\n
which is created by the StreamHandler object with the customized format string. It happens only after we reconfigured the logger for
parent<\/code> because otherwise, the root logger\u2019s configuration prevails, and no messages at level INFO will be printed.<\/p>\nAdvanced Configuration to Logging<\/strong><\/h2>\n
As we saw in the last example, we can configure the loggers we made.<\/p>\n
Threshold of Level<\/h3>\n
Like the basic configuration of the root logger, we can also configure the output destination, severity level, and formatting of a logger. The following is how we can set the threshold<\/strong> of the level of a logger to INFO:<\/p>\n
parent_logger = logging.getLogger(\"parent\")\r\nparent_logger.setLevel(logging.INFO)<\/pre>\n
Now commands with severity level INFO and higher will be logged by the parent_logger. But if this is all you did, you will not see anything from
parent_logger.info(\"messages\")<\/code> because there are no handlers<\/strong> assigned for this logger. In fact, there are no handlers for root logger as well unless you set up one withlogging.basicConfig()<\/code>.<\/p>\nLog Handlers<\/h3>\n
We can configure the output destination of our logger with handlers. Handlers are responsible for sending the log messages to the correct destination. There are several types of handlers; the most common ones are
StreamHandler<\/code> andFileHandler<\/code>. WithStreamHandler<\/code>, the logger will output to the terminal, while withFileHandler<\/code>, the logger will output to a particular file.<\/p>\nHere\u2019s an example of using
StreamHandler<\/code> to output logs to the terminal:<\/p>\nimport logging\r\n\r\n# Set up root logger, and add a file handler to root logger\r\nlogging.basicConfig(filename = 'file.log',\r\n level = logging.WARNING,\r\n format = '%(asctime)s:%(levelname)s:%(name)s:%(message)s')\r\n\r\n# Create logger, set level, and add stream handler\r\nparent_logger = logging.getLogger(\"parent\")\r\nparent_logger.setLevel(logging.INFO)\r\nparent_shandler = logging.StreamHandler()\r\nparent_logger.addHandler(parent_shandler)\r\n\r\n# Log message of severity INFO or above will be handled\r\nparent_logger.debug('Debug message')\r\nparent_logger.info('Info message')\r\nparent_logger.warning('Warning message')\r\nparent_logger.error('Error message')\r\nparent_logger.critical('Critical message')<\/pre>\nIn the code above, there are two handlers created: A
FileHandler<\/code> created bylogging.basicConfig()<\/code> for the root logger and aStreamHandler<\/code> created for theparent<\/code> logger.<\/p>\nNote that even though there is a
StreamHandler<\/code> that sends the logs to the terminal, logs from theparent<\/code> logger are still being sent tofile.log<\/code> since it is a child of the root logger, and the root logger\u2019s handler is also active for the child\u2019s log messages. We can see that the logs to the terminal include INFO level messages and above:<\/p>\nInfo message\r\nWarning message\r\nError message\r\nCritical message<\/pre>\n
But the output to the terminal is not formatted, as we have not used a
Formatter<\/code> yet. The log tofile.log<\/code>, however, has aFormatter<\/code> set up, and it will be like the following:<\/p>\n2022-03-22 23:07:12,533:INFO:parent:Info message\r\n2022-03-22 23:07:12,533:WARNING:parent:Warning message\r\n2022-03-22 23:07:12,533:ERROR:parent:Error message\r\n2022-03-22 23:07:12,533:CRITICAL:parent:Critical message<\/pre>\n
Alternatively, we can use
FileHandler<\/code> in the above example ofparent_logger<\/code>:<\/p>\nimport logging\r\n\r\n# Set up root logger, and add a file handler to root logger\r\nlogging.basicConfig(filename = 'file.log',\r\n level = logging.WARNING,\r\n format = '%(asctime)s:%(levelname)s:%(name)s:%(message)s')\r\n\r\n# Create logger, set level, and add stream handler\r\nparent_logger = logging.getLogger(\"parent\")\r\nparent_logger.setLevel(logging.INFO)\r\nparent_fhandler = logging.FileHandler('parent.log')\r\nparent_fhandler.setLevel(logging.WARNING)\r\nparent_logger.addHandler(parent_fhandler)\r\n\r\n# Log message of severity INFO or above will be handled\r\nparent_logger.debug('Debug message')\r\nparent_logger.info('Info message')\r\nparent_logger.warning('Warning message')\r\nparent_logger.error('Error message')\r\nparent_logger.critical('Critical message')<\/pre>\nThe example above demonstrated that you can also set the level of a handler. The level of
parent_fhandler<\/code> filters out logs that are not WARNING level or higher. However, if you set the handler\u2019s level to DEBUG, that would be the same as not setting the level because DEBUG logs would already be filtered out by the logger\u2019s level, which is INFO.<\/p>\nIn this case, the output to
parent.log<\/code>\u00a0is:<\/p>\nWarning message\r\nError message\r\nCritical message<\/pre>\n
while that of
file.log<\/code> is the same as before. In summary, when a log message is recorded by a logger,<\/p>\n- \n
- The logger\u2019s level will determine if the message is severe enough to be handled. If the logger\u2019s level is not set, the level of its parent (and ultimately the root logger) will be used for this consideration.<\/li>\n
- If the log message will be handled, all<\/strong> handlers ever added along the logger hierarchy up to the root logger will receive a copy of the message. Each handler\u2019s level will determine if this particular handler should honor this message.<\/li>\n<\/ol>\n
Formatters <\/strong><\/h3>\n
To configure the format of the logger, we use a
Formatter<\/code>. It allows us to set the format of the log, similarly to how we did so in the root logger\u2019sbasicConfig()<\/code>. This is how we can add a formatter to our handler:<\/p>\nimport logging\r\n\r\n# Set up root logger, and add a file handler to root logger\r\nlogging.basicConfig(filename = 'file.log',\r\n level = logging.WARNING,\r\n format = '%(asctime)s:%(levelname)s:%(name)s:%(message)s')\r\n\r\n# Create logger, set level, and add stream handler\r\nparent_logger = logging.getLogger(\"parent\")\r\nparent_logger.setLevel(logging.INFO)\r\nparent_fhandler = logging.FileHandler('parent.log')\r\nparent_fhandler.setLevel(logging.WARNING)\r\nparent_formatter = logging.Formatter('%(asctime)s:%(levelname)s:%(message)s')\r\nparent_fhandler.setFormatter(parent_formatter)\r\nparent_logger.addHandler(parent_fhandler)\r\n\r\n# Log message of severity INFO or above will be handled\r\nparent_logger.debug('Debug message')\r\nparent_logger.info('Info message')\r\nparent_logger.warning('Warning message')\r\nparent_logger.error('Error message')\r\nparent_logger.critical('Critical message')<\/pre>\nFirst, we create a formatter, then set our handler to use that formatter. If we wanted to, we could make several different loggers, handlers, and formatters so that we could mix and match based on our preferences.<\/p>\n
In this example, the
parent.log<\/code> will have:<\/p>\n2022-03-23 13:28:31,302:WARNING:Warning message\r\n2022-03-23 13:28:31,302:ERROR:Error message\r\n2022-03-23 13:28:31,303:CRITICAL:Critical message<\/pre>\n
and the
file.log<\/code> associated with the handler at root logger will have:<\/p>\n2022-03-23 13:28:31,302:INFO:parent:Info message\r\n2022-03-23 13:28:31,302:WARNING:parent:Warning message\r\n2022-03-23 13:28:31,302:ERROR:parent:Error message\r\n2022-03-23 13:28:31,303:CRITICAL:parent:Critical message<\/pre>\n
Below is the visualization of the flow of loggers, handlers, and formatters from the documentation of the logging module:<\/a><\/p>\n
\n![\"\"](\"https:\/\/machinelearningmastery.com\/wp-content\/uploads\/2022\/03\/logging_flow.png\")
<\/p>\nFlow chart of loggers and handlers in the logging module<\/p>\n<\/div>\n
An Example of the Use of Logging<\/h2>\n
Let\u2019s consider the Nadam algorithm<\/a> as an example:<\/p>\n
# gradient descent optimization with nadam for a two-dimensional test function\r\nfrom math import sqrt\r\nfrom numpy import asarray\r\nfrom numpy.random import rand\r\nfrom numpy.random import seed\r\n\r\n# objective function\r\ndef objective(x, y):\r\n\treturn x**2.0 + y**2.0\r\n\r\n# derivative of objective function\r\ndef derivative(x, y):\r\n\treturn asarray([x * 2.0, y * 2.0])\r\n\r\n# gradient descent algorithm with nadam\r\ndef nadam(objective, derivative, bounds, n_iter, alpha, mu, nu, eps=1e-8):\r\n\t# generate an initial point\r\n\tx = bounds[:, 0] + rand(len(bounds)) * (bounds[:, 1] - bounds[:, 0])\r\n\tscore = objective(x[0], x[1])\r\n\t# initialize decaying moving averages\r\n\tm = [0.0 for _ in range(bounds.shape[0])]\r\n\tn = [0.0 for _ in range(bounds.shape[0])]\r\n\t# run the gradient descent\r\n\tfor t in range(n_iter):\r\n\t\t# calculate gradient g(t)\r\n\t\tg = derivative(x[0], x[1])\r\n\t\t# build a solution one variable at a time\r\n\t\tfor i in range(bounds.shape[0]):\r\n\t\t\t# m(t) = mu * m(t-1) + (1 - mu) * g(t)\r\n\t\t\tm[i] = mu * m[i] + (1.0 - mu) * g[i]\r\n\t\t\t# n(t) = nu * n(t-1) + (1 - nu) * g(t)^2\r\n\t\t\tn[i] = nu * n[i] + (1.0 - nu) * g[i]**2\r\n\t\t\t# mhat = (mu * m(t) \/ (1 - mu)) + ((1 - mu) * g(t) \/ (1 - mu))\r\n\t\t\tmhat = (mu * m[i] \/ (1.0 - mu)) + ((1 - mu) * g[i] \/ (1.0 - mu))\r\n\t\t\t# nhat = nu * n(t) \/ (1 - nu)\r\n\t\t\tnhat = nu * n[i] \/ (1.0 - nu)\r\n\t\t\t# x(t) = x(t-1) - alpha \/ (sqrt(nhat) + eps) * mhat\r\n\t\t\tx[i] = x[i] - alpha \/ (sqrt(nhat) + eps) * mhat\r\n\t\t# evaluate candidate point\r\n\t\tscore = objective(x[0], x[1])\r\n\t\t# report progress\r\n\t\tprint('>%d f(%s) = %.5f' % (t, x, score))\r\n\treturn [x, score]\r\n\r\n# seed the pseudo random number generator\r\nseed(1)\r\n# define range for input\r\nbounds = asarray([[-1.0, 1.0], [-1.0, 1.0]])\r\n# define the total iterations\r\nn_iter = 50\r\n# steps size\r\nalpha = 0.02\r\n# factor for average gradient\r\nmu = 0.8\r\n# factor for average squared gradient\r\nnu = 0.999\r\n# perform the gradient descent search with nadam\r\nbest, score = nadam(objective, derivative, bounds, n_iter, alpha, mu, nu)\r\nprint('Done!')\r\nprint('f(%s) = %f' % (best, score))<\/pre>\nThe simplest use case is to use logging to replace the
print()<\/code> function. We can make the following change: First, create a logger with the namenadam<\/code> before we run any code and assign aStreamHandler<\/code>:<\/p>\n...\r\n\r\nimport logging\r\n\r\n...\r\n\r\n# Added: Create logger and assign handler\r\nlogger = logging.getLogger(\"nadam\")\r\nhandler = logging.StreamHandler()\r\nhandler.setFormatter(logging.Formatter(\"%(asctime)s|%(levelname)s|%(name)s|%(message)s\"))\r\nlogger.addHandler(handler)\r\nlogger.setLevel(logging.DEBUG)\r\n# seed the pseudo random number generator\r\nseed(1)\r\n... # rest of the code<\/pre>\n
We must assign a handler because we never configured the root logger, and this would be the only handler ever created. Then, in the function
nadam()<\/code>, we re-create a loggernadam,<\/code> but since it has already been set up, the level and handlers persisted. At the end of each outer for-loop innadam()<\/code>, we replaced theprint()<\/code> function withlogger.info()<\/code> so the message will be handled by the logging system:<\/p>\n...\r\n\r\n# gradient descent algorithm with nadam\r\ndef nadam(objective, derivative, bounds, n_iter, alpha, mu, nu, eps=1e-8):\r\n # Create a logger\r\n logger = logging.getLogger(\"nadam\")\r\n # generate an initial point\r\n x = bounds[:, 0] + rand(len(bounds)) * (bounds[:, 1] - bounds[:, 0])\r\n score = objective(x[0], x[1])\r\n # initialize decaying moving averages\r\n m = [0.0 for _ in range(bounds.shape[0])]\r\n n = [0.0 for _ in range(bounds.shape[0])]\r\n # run the gradient descent\r\n for t in range(n_iter):\r\n # calculate gradient g(t)\r\n g = derivative(x[0], x[1])\r\n # build a solution one variable at a time\r\n for i in range(bounds.shape[0]):\r\n # m(t) = mu * m(t-1) + (1 - mu) * g(t)\r\n m[i] = mu * m[i] + (1.0 - mu) * g[i]\r\n # n(t) = nu * n(t-1) + (1 - nu) * g(t)^2\r\n n[i] = nu * n[i] + (1.0 - nu) * g[i]**2\r\n # mhat = (mu * m(t) \/ (1 - mu)) + ((1 - mu) * g(t) \/ (1 - mu))\r\n mhat = (mu * m[i] \/ (1.0 - mu)) + ((1 - mu) * g[i] \/ (1.0 - mu))\r\n # nhat = nu * n(t) \/ (1 - nu)\r\n nhat = nu * n[i] \/ (1.0 - nu)\r\n # x(t) = x(t-1) - alpha \/ (sqrt(nhat) + eps) * mhat\r\n x[i] = x[i] - alpha \/ (sqrt(nhat) + eps) * mhat\r\n # evaluate candidate point\r\n score = objective(x[0], x[1])\r\n # report progress using logger\r\n logger.info('>%d f(%s) = %.5f' % (t, x, score))\r\n return [x, score]\r\n\r\n...<\/pre>\nIf we are interested in the deeper mechanics of the Nadam algorithm, we may add more logs. The following is the complete code:<\/p>\n
# gradient descent optimization with nadam for a two-dimensional test function\r\nimport logging\r\nfrom math import sqrt\r\nfrom numpy import asarray\r\nfrom numpy.random import rand\r\nfrom numpy.random import seed\r\n\r\n# objective function\r\ndef objective(x, y):\r\n return x**2.0 + y**2.0\r\n\r\n# derivative of objective function\r\ndef derivative(x, y):\r\n return asarray([x * 2.0, y * 2.0])\r\n\r\n# gradient descent algorithm with nadam\r\ndef nadam(objective, derivative, bounds, n_iter, alpha, mu, nu, eps=1e-8):\r\n logger = logging.getLogger(\"nadam\")\r\n # generate an initial point\r\n x = bounds[:, 0] + rand(len(bounds)) * (bounds[:, 1] - bounds[:, 0])\r\n score = objective(x[0], x[1])\r\n # initialize decaying moving averages\r\n m = [0.0 for _ in range(bounds.shape[0])]\r\n n = [0.0 for _ in range(bounds.shape[0])]\r\n # run the gradient descent\r\n for t in range(n_iter):\r\n iterlogger = logging.getLogger(\"nadam.iter\")\r\n # calculate gradient g(t)\r\n g = derivative(x[0], x[1])\r\n # build a solution one variable at a time\r\n for i in range(bounds.shape[0]):\r\n # m(t) = mu * m(t-1) + (1 - mu) * g(t)\r\n m[i] = mu * m[i] + (1.0 - mu) * g[i]\r\n # n(t) = nu * n(t-1) + (1 - nu) * g(t)^2\r\n n[i] = nu * n[i] + (1.0 - nu) * g[i]**2\r\n # mhat = (mu * m(t) \/ (1 - mu)) + ((1 - mu) * g(t) \/ (1 - mu))\r\n mhat = (mu * m[i] \/ (1.0 - mu)) + ((1 - mu) * g[i] \/ (1.0 - mu))\r\n # nhat = nu * n(t) \/ (1 - nu)\r\n nhat = nu * n[i] \/ (1.0 - nu)\r\n # x(t) = x(t-1) - alpha \/ (sqrt(nhat) + eps) * mhat\r\n x[i] = x[i] - alpha \/ (sqrt(nhat) + eps) * mhat\r\n iterlogger.info(\"Iteration %d variable %d: mhat=%f nhat=%f\", t, i, mhat, nhat)\r\n # evaluate candidate point\r\n score = objective(x[0], x[1])\r\n # report progress\r\n logger.info('>%d f(%s) = %.5f' % (t, x, score))\r\n return [x, score]\r\n\r\n# Create logger and assign handler\r\nlogger = logging.getLogger(\"nadam\")\r\nhandler = logging.StreamHandler()\r\nhandler.setFormatter(logging.Formatter(\"%(asctime)s|%(levelname)s|%(name)s|%(message)s\"))\r\nlogger.addHandler(handler)\r\nlogger.setLevel(logging.DEBUG)\r\nlogger = logging.getLogger(\"nadam.iter\")\r\nlogger.setLevel(logging.INFO)\r\n# seed the pseudo random number generator\r\nseed(1)\r\n# define range for input\r\nbounds = asarray([[-1.0, 1.0], [-1.0, 1.0]])\r\n# define the total iterations\r\nn_iter = 50\r\n# steps size\r\nalpha = 0.02\r\n# factor for average gradient\r\nmu = 0.8\r\n# factor for average squared gradient\r\nnu = 0.999\r\n# perform the gradient descent search with nadam\r\nbest, score = nadam(objective, derivative, bounds, n_iter, alpha, mu, nu)\r\nprint('Done!')\r\nprint('f(%s) = %f' % (best, score))<\/pre>\nWe prepared two level of loggers,
nadam<\/code> andnadam.iter<\/code>, and set them in different levels. In the inner loop ofnadam()<\/code>, we use the child logger to print some internal variables. When you run this script, it will print the following:<\/p>\n2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 0 variable 0: mhat=-0.597442 nhat=0.110055\r\n2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 0 variable 1: mhat=1.586336 nhat=0.775909\r\n2022-03-29 12:24:59,421|INFO|nadam|>0 f([-0.12993798 0.40463097]) = 0.18061\r\n2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 1 variable 0: mhat=-0.680200 nhat=0.177413\r\n2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 1 variable 1: mhat=2.020702 nhat=1.429384\r\n2022-03-29 12:24:59,421|INFO|nadam|>1 f([-0.09764012 0.37082777]) = 0.14705\r\n2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 2 variable 0: mhat=-0.687764 nhat=0.215332\r\n2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 2 variable 1: mhat=2.304132 nhat=1.977457\r\n2022-03-29 12:24:59,421|INFO|nadam|>2 f([-0.06799761 0.33805721]) = 0.11891\r\n...\r\n2022-03-29 12:24:59,449|INFO|nadam.iter|Iteration 49 variable 0: mhat=-0.000482 nhat=0.246709\r\n2022-03-29 12:24:59,449|INFO|nadam.iter|Iteration 49 variable 1: mhat=-0.018244 nhat=3.966938\r\n2022-03-29 12:24:59,449|INFO|nadam|>49 f([-5.54299505e-05 -1.00116899e-03]) = 0.00000\r\nDone!\r\nf([-5.54299505e-05 -1.00116899e-03]) = 0.000001<\/pre>\n
Setting different loggers not only allows us to set a different level or handlers, but it also lets us differentiate where the log message comes from by looking at the logger\u2019s name from the message printed.<\/p>\n
In fact, one handy trick is to create a logging decorator and apply the decorator to some functions. We can keep track of every time that function is called. For example, we created a decorator below and applied it to the functions
objective()<\/code> andderivative()<\/code>:<\/p>\n...\r\n\r\n# A Python decorator to log the function call and return value\r\ndef loggingdecorator(name):\r\n logger = logging.getLogger(name)\r\n def _decor(fn):\r\n function_name = fn.__name__\r\n def _fn(*args, **kwargs):\r\n ret = fn(*args, **kwargs)\r\n argstr = [str(x) for x in args]\r\n argstr += [key+\"=\"+str(val) for key,val in kwargs.items()]\r\n logger.debug(\"%s(%s) -> %s\", function_name, \", \".join(argstr), ret)\r\n return ret\r\n return _fn\r\n return _decor\r\n\r\n# objective function\r\n@loggingdecorator(\"nadam.function\")\r\ndef objective(x, y):\r\n return x**2.0 + y**2.0\r\n\r\n# derivative of objective function\r\n@loggingdecorator(\"nadam.function\")\r\ndef derivative(x, y):\r\n return asarray([x * 2.0, y * 2.0])<\/pre>\n
Then we will see the following in the log:<\/p>\n
2022-03-29 13:14:07,542|DEBUG|nadam.function|objective(-0.165955990594852, 0.4406489868843162) -> 0.22171292045649288\r\n2022-03-29 13:14:07,542|DEBUG|nadam.function|derivative(-0.165955990594852, 0.4406489868843162) -> [-0.33191198 0.88129797]\r\n2022-03-29 13:14:07,542|INFO|nadam.iter|Iteration 0 variable 0: mhat=-0.597442 nhat=0.110055\r\n2022-03-29 13:14:07,542|INFO|nadam.iter|Iteration 0 variable 1: mhat=1.586336 nhat=0.775909\r\n2022-03-29 13:14:07,542|DEBUG|nadam.function|objective(-0.12993797816930272, 0.4046309737819536) -> 0.18061010311445824\r\n2022-03-29 13:14:07,543|INFO|nadam|>0 f([-0.12993798 0.40463097]) = 0.18061\r\n2022-03-29 13:14:07,543|DEBUG|nadam.function|derivative(-0.12993797816930272, 0.4046309737819536) -> [-0.25987596 0.80926195]\r\n2022-03-29 13:14:07,543|INFO|nadam.iter|Iteration 1 variable 0: mhat=-0.680200 nhat=0.177413\r\n2022-03-29 13:14:07,543|INFO|nadam.iter|Iteration 1 variable 1: mhat=2.020702 nhat=1.429384\r\n2022-03-29 13:14:07,543|DEBUG|nadam.function|objective(-0.09764011794760165, 0.3708277653552375) -> 0.14704682419118062\r\n2022-03-29 13:14:07,543|INFO|nadam|>1 f([-0.09764012 0.37082777]) = 0.14705\r\n2022-03-29 13:14:07,543|DEBUG|nadam.function|derivative(-0.09764011794760165, 0.3708277653552375) -> [-0.19528024 0.74165553]\r\n2022-03-29 13:14:07,543|INFO|nadam.iter|Iteration 2 variable 0: mhat=-0.687764 nhat=0.215332\r\n...<\/pre>\n
where we can see the parameters and return values of each call to those two functions in the message logged by the
nadam.function<\/code> logger.<\/p>\nAs we get more and more log messages, the terminal screen will become very busy. One way to make it easier to watch for issues is to highlight the logs in color with the
colorama<\/code> module. You need to have the module installed first:<\/p>\npip install colorama<\/pre>\n
Here\u2019s an example of how you can use the
colorama<\/code> module with thelogging<\/code> module to change your log colors and text brightness:<\/p>\nimport logging\r\nimport colorama\r\nfrom colorama import Fore, Back, Style\r\n\r\n# Initialize the terminal for color\r\ncolorama.init(autoreset = True)\r\n\r\n# Set up logger as usual\r\nlogger = logging.getLogger(\"color\")\r\nlogger.setLevel(logging.DEBUG)\r\nshandler = logging.StreamHandler()\r\nformatter = logging.Formatter('%(asctime)s:%(levelname)s:%(name)s:%(message)s')\r\nshandler.setFormatter(formatter)\r\nlogger.addHandler(shandler)\r\n\r\n# Emit log message with color\r\nlogger.debug('Debug message')\r\nlogger.info(Fore.GREEN + 'Info message')\r\nlogger.warning(Fore.BLUE + 'Warning message')\r\nlogger.error(Fore.YELLOW + Style.BRIGHT + 'Error message')\r\nlogger.critical(Fore.RED + Back.YELLOW + Style.BRIGHT + 'Critical message')<\/pre>\nFrom the terminal, you would see the following:
![\"\"](\"https:\/\/machinelearningmastery.com\/wp-content\/uploads\/2022\/03\/logs1.png\")
<\/p>\nwhere the
Fore<\/code>,Back<\/code>, andStyle<\/code> from thecolorama<\/code> module control the foreground, background, and brightness style of the text printed. This is leveraging the ANSI escape characters and works only on ANSI-supported terminals. Hence this is not suitable for logging to a text file.<\/p>\nIn fact, we may derive the
Formatter<\/code> class with:<\/p>\n...\r\ncolors = {\"DEBUG\":Fore.BLUE, \"INFO\":Fore.CYAN,\r\n \"WARNING\":Fore.YELLOW, \"ERROR\":Fore.RED, \"CRITICAL\":Fore.MAGENTA}\r\nclass ColoredFormatter(logging.Formatter):\r\n def format(self, record):\r\n msg = logging.Formatter.format(self, record)\r\n if record.levelname in colors:\r\n msg = colors[record.levelname] + msg + Fore.RESET\r\n return msg<\/pre>\nand use this instead of
logging.Formatter<\/code>. The following is how we can further modify the Nadam example to add color:<\/p>\n# gradient descent optimization with nadam for a two-dimensional test function\r\nimport logging\r\nimport colorama\r\nfrom colorama import Fore\r\n\r\nfrom math import sqrt\r\nfrom numpy import asarray\r\nfrom numpy.random import rand\r\nfrom numpy.random import seed\r\n\r\ndef loggingdecorator(name):\r\n logger = logging.getLogger(name)\r\n def _decor(fn):\r\n function_name = fn.__name__\r\n def _fn(*args, **kwargs):\r\n ret = fn(*args, **kwargs)\r\n argstr = [str(x) for x in args]\r\n argstr += [key+\"=\"+str(val) for key,val in kwargs.items()]\r\n logger.debug(\"%s(%s) -> %s\", function_name, \", \".join(argstr), ret)\r\n return ret\r\n return _fn\r\n return _decor\r\n\r\n# objective function\r\n@loggingdecorator(\"nadam.function\")\r\ndef objective(x, y):\r\n return x**2.0 + y**2.0\r\n\r\n# derivative of objective function\r\n@loggingdecorator(\"nadam.function\")\r\ndef derivative(x, y):\r\n return asarray([x * 2.0, y * 2.0])\r\n\r\n# gradient descent algorithm with nadam\r\ndef nadam(objective, derivative, bounds, n_iter, alpha, mu, nu, eps=1e-8):\r\n logger = logging.getLogger(\"nadam\")\r\n # generate an initial point\r\n x = bounds[:, 0] + rand(len(bounds)) * (bounds[:, 1] - bounds[:, 0])\r\n score = objective(x[0], x[1])\r\n # initialize decaying moving averages\r\n m = [0.0 for _ in range(bounds.shape[0])]\r\n n = [0.0 for _ in range(bounds.shape[0])]\r\n # run the gradient descent\r\n for t in range(n_iter):\r\n iterlogger = logging.getLogger(\"nadam.iter\")\r\n # calculate gradient g(t)\r\n g = derivative(x[0], x[1])\r\n # build a solution one variable at a time\r\n for i in range(bounds.shape[0]):\r\n # m(t) = mu * m(t-1) + (1 - mu) * g(t)\r\n m[i] = mu * m[i] + (1.0 - mu) * g[i]\r\n # n(t) = nu * n(t-1) + (1 - nu) * g(t)^2\r\n n[i] = nu * n[i] + (1.0 - nu) * g[i]**2\r\n # mhat = (mu * m(t) \/ (1 - mu)) + ((1 - mu) * g(t) \/ (1 - mu))\r\n mhat = (mu * m[i] \/ (1.0 - mu)) + ((1 - mu) * g[i] \/ (1.0 - mu))\r\n # nhat = nu * n(t) \/ (1 - nu)\r\n nhat = nu * n[i] \/ (1.0 - nu)\r\n # x(t) = x(t-1) - alpha \/ (sqrt(nhat) + eps) * mhat\r\n x[i] = x[i] - alpha \/ (sqrt(nhat) + eps) * mhat\r\n iterlogger.info(\"Iteration %d variable %d: mhat=%f nhat=%f\", t, i, mhat, nhat)\r\n # evaluate candidate point\r\n score = objective(x[0], x[1])\r\n # report progress\r\n logger.warning('>%d f(%s) = %.5f' % (t, x, score))\r\n return [x, score]\r\n\r\n# Prepare the colored formatter\r\ncolorama.init(autoreset = True)\r\ncolors = {\"DEBUG\":Fore.BLUE, \"INFO\":Fore.CYAN,\r\n \"WARNING\":Fore.YELLOW, \"ERROR\":Fore.RED, \"CRITICAL\":Fore.MAGENTA}\r\nclass ColoredFormatter(logging.Formatter):\r\n def format(self, record):\r\n msg = logging.Formatter.format(self, record)\r\n if record.levelname in colors:\r\n msg = colors[record.levelname] + msg + Fore.RESET\r\n return msg\r\n\r\n# Create logger and assign handler\r\nlogger = logging.getLogger(\"nadam\")\r\nhandler = logging.StreamHandler()\r\nhandler.setFormatter(ColoredFormatter(\"%(asctime)s|%(levelname)s|%(name)s|%(message)s\"))\r\nlogger.addHandler(handler)\r\nlogger.setLevel(logging.DEBUG)\r\nlogger = logging.getLogger(\"nadam.iter\")\r\nlogger.setLevel(logging.DEBUG)\r\n# seed the pseudo random number generator\r\nseed(1)\r\n# define range for input\r\nbounds = asarray([[-1.0, 1.0], [-1.0, 1.0]])\r\n# define the total iterations\r\nn_iter = 50\r\n# steps size\r\nalpha = 0.02\r\n# factor for average gradient\r\nmu = 0.8\r\n# factor for average squared gradient\r\nnu = 0.999\r\n# perform the gradient descent search with nadam\r\nbest, score = nadam(objective, derivative, bounds, n_iter, alpha, mu, nu)\r\nprint('Done!')\r\nprint('f(%s) = %f' % (best, score))<\/pre>\nIf we run it on a supporting terminal, we will see the following output:<\/p>\n
![\"\"](\"https:\/\/machinelearningmastery.com\/wp-content\/uploads\/2022\/03\/logs2.png\")
<\/p>\nNote that the colorful output can help us spot any abnormal behavior easier. Logging helps with debugging and also allows us to easily control how much detail we want to see by changing only a few lines of code.<\/p>\n
Further Reading<\/h2>\n
This section provides more resources on the topic if you are looking to go deeper.<\/p>\n
APIs<\/h3>\n
- \n
- \nlogging module<\/a> from Python standard library<\/li>\n
- Colorama<\/a><\/li>\n<\/ul>\n
Articles<\/h3>\n
- \n
- Python logging HOWTO<\/a><\/li>\n<\/ul>\n
Summary<\/strong><\/h2>\n
In this tutorial, you learned how to implement logging techniques in your scripts.<\/p>\n
Specifically, you learned:<\/p>\n
- \n
- Basic and advanced logging techniques<\/li>\n
- How to apply logging to a script and the benefits of doing so<\/li>\n<\/ul>\n
The post Logging in Python<\/a> appeared first on Machine Learning Mastery<\/a>.<\/p>\n<\/div>\n
Go to Source<\/a><\/p>\n","protected":false},"excerpt":{"rendered":"
- Colorama<\/a><\/li>\n<\/ul>\n
- \nlogging module<\/a> from Python standard library<\/li>\n