Tutorial on Python Logging

Logging is a method of storing information about your script and tracking events. Logging is essential for debugging software as you develop it when writing any complex script in Python. Finding the source of a problem in your code without logging can be extremely time-consuming.

After finishing this tutorial, you will understand:

1. Why do we want to use the logging module?
2. How to Make Use of the Logging Module
3. How to Tailor the Logging Mechanism

Let’s get started.

Tutorial Overview

This tutorial is divided into four sections, which are as follows:

1. The benefits of logging
2. Basic logging
3. Advanced configuration to logging
4. An example of the use of logging

Benefits of logging

“Why not just use printing?” you may wonder.

When running an algorithm and confirming that it is performing as expected, it is natural to include some print() statements at strategic locations to display the program’s state. Printing can aid in the debugging of simpler scripts, but as your code becomes more complex, printing lacks the flexibility and robustness that logging provides.

Logging allows you to pinpoint where a logging call originated, differentiate the severity of messages, and write information to a file, which printing cannot. For example, we can toggle the message from a specific module of a larger program on and off. We can also change the verbosity of the logging messages without changing much code.

Basic logging

For this purpose, Python has a built-in library called logging. It is simple to set up a “logger” to record messages or information that you want to see.

Python’s logging system uses a hierarchical namespace and different levels of severity. The Python script can create a logger in a namespace, and the script must specify the severity of each message logged. Depending on the handler we configure for the namespace, the logged message may be routed to different locations. The most common handler is to simply print on the screen, as the print() function does. When we start the program, we can register a new handler and specify the severity level to which the handler will respond.

There are five distinct logging levels that indicate the severity of the logs, as shown in descending order of severity:

1. DEBUG
2. INFO
3. WARNING
4. ERROR
5. CRITICAL

The following is a very simple example of logging using the default logger or the root logger:

import logging

logging.debug('Debug message')
logging.info('Info message')
logging.warning('Warning message')
logging.error('Error message')
logging.critical('Critical message')

These will generate log messages of varying severity. If you run this script, you may see only three lines of output, even though there are five lines of logging:

WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

This is because the root logger, by default, only prints log messages with a severity level of WARNING or higher. However, using the root logger in this manner is very similar to using the print() function.

The root logger’s settings are not set in stone. The root logger can be configured to output to a specific file, change its default severity level, and format the output. Here’s an illustration:

import logging

logging.basicConfig(filename = 'file.log',
level = logging.DEBUG,
format = '%(asctime)s:%(levelname)s:%(name)s:%(message)s')

logging.debug('Debug message')
logging.info('Info message')
logging.warning('Warning message')
logging.error('Error message')
logging.critical('Critical message')

Running this script will result in no output to the screen but the following in the newly created file file. log:

2022-03-22 20:41:08,151:DEBUG:root:Debug message
2022-03-22 20:41:08,152:INFO:root:Info message
2022-03-22 20:41:08,152:WARNING:root:Warning message
2022-03-22 20:41:08,152:ERROR:root:Error message
2022-03-22 20:41:08,152:CRITICAL:root:Critical message

The logging.basicConfig() method is used to change the root logger. In our example, we change the handler to output to a file rather than the screen, adjust the logging level so that all log messages with the level DEBUG or higher are handled, and change the format of the log message output to include the time.

Because all five messages were output, the root logger’s default level is now “DEBUG.” The logging documentation describes the log record attributes (such as % (asctime)s) that can be used to format the output.

Although there is a default logger, we usually want to create and use additional loggers that can be configured independently. This is because different loggers may require a different severity level or format. A new logger can be created by typing:

logger = logging.getLogger("logger_name")

Internally, the loggers are organized in a hierarchical structure. A logger made with:

logger = logging.getLogger("parent.child")

will be a child logger created under the logger with the name “parent,” which is in turn under the root logger. A dot in the string indicates that the child logger is a child of the parent logger. In the preceding example, a logger with the name “parent.child” is created, as is one with the name “parent” implicitly.

Upon creation, a child logger inherits all of the properties of its parent logger until reconfigured. As an example, consider the following:

import logging

# Create `parent.child` logger
logger = logging.getLogger("parent.child")

# Emit a log message of level INFO, by default this is not print to the screen
logger.info("this is info level")

# Create `parent` logger
parentlogger = logging.getLogger("parent")

# Set parent's level to INFO and assign a new handler
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(asctime)s:%(name)s:%(levelname)s:%(message)s"))
parentlogger.setLevel(logging.INFO)
parentlogger.addHandler(handler)

# Let child logger emit a log message again
logger.info("this is info level again")

This code snippet will only output one line:

2022-03-28 19:23:29,315:parent.child:INFO:this is info level again

which is created with the customized format string by the StreamHandler object It only happens after we reconfigure the logger for parent; otherwise, the root logger’s configuration takes precedence, and no messages at level INFO are printed.

Advanced configuration to logging

We can configure the loggers we created, as we saw in the previous example.

Threshold of Level

We can configure the output destination, severity level, and formatting of a logger in the same way that we can the root logger. The following is how we can set the logger’s level threshold to INFO:

parent_logger = logging.getLogger("parent")
parent_logger.setLevel(logging.INFO)

The parent_ logger will now log commands with severity levels INFO and higher. However, if this is all you did, you will not see anything from parent_ logger.info(“messages”) because this logger has no handlers assigned to it. Unless you use logging.basicConfig() there are no handlers for root logger.

Log Handlers

With handlers, we can configure our logger’s output destination. Handlers are in charge of routing log messages to their proper destinations. Handlers are classified into several types, the most common of which are StreamHandler and FileHandler. The logger will output to the terminal with StreamHandler, while the logger will output to a specific file with FileHandler.

Here’s an example of how to use StreamHandler to send logs to the terminal:

import logging

# Set up root logger, and add a file handler to root logger
logging.basicConfig(filename = 'file.log',
level = logging.WARNING,
format = '%(asctime)s:%(levelname)s:%(name)s:%(message)s')

# Create logger, set level, and add stream handler
parent_logger = logging.getLogger("parent")
parent_logger.setLevel(logging.INFO)
parent_shandler = logging.StreamHandler()
parent_logger.addHandler(parent_shandler)

# Log message of severity INFO or above will be handled
parent_logger.debug('Debug message')
parent_logger.info('Info message')
parent_logger.warning('Warning message')
parent_logger.error('Error message')
parent_logger.critical('Critical message')

There are two handlers created in the code above: a FileHandler created by logging. basicConfig() for the root logger and a StreamHandler for the parent logger.

It should be noted that, despite the presence of a StreamHandler that sends logs to the terminal, logs from the parent logger are still sent to the file. log because it is a child of the root logger, and the handler for the root logger’s log messages is also active for the child’s log messages. We can see that the terminal logs contain INFO level messages and higher:

Info message
Warning message
Error message
Critical message

However, because we have not yet used a Formatter, the output to the terminal is not formatted. The log to file.log, on the other hand, has a Formatter configured, and it will look like this:

2022-03-22 23:07:12,533:INFO:parent:Info message
2022-03-22 23:07:12,533:WARNING:parent:Warning message
2022-03-22 23:07:12,533:ERROR:parent:Error message
2022-03-22 23:07:12,533:CRITICAL:parent:Critical message

In the parent_ logger example above, we can also use FileHandler:

import logging

# Set up root logger, and add a file handler to root logger
logging.basicConfig(filename = 'file.log',
level = logging.WARNING,
format = '%(asctime)s:%(levelname)s:%(name)s:%(message)s')

# Create logger, set level, and add stream handler
parent_logger = logging.getLogger("parent")
parent_logger.setLevel(logging.INFO)
parent_fhandler = logging.FileHandler('parent.log')
parent_fhandler.setLevel(logging.WARNING)
parent_logger.addHandler(parent_fhandler)

# Log message of severity INFO or above will be handled
parent_logger.debug('Debug message')
parent_logger.info('Info message')
parent_logger.warning('Warning message')
parent_logger.error('Error message')
parent_logger.critical('Critical message')

The preceding example demonstrated that you can also set a handler’s level. The parent_ fhandler level filters out logs that are not WARNING or higher. However, setting the handler’s level to DEBUG is equivalent to not setting the level because DEBUG logs are already filtered out by the logger’s level, which is INFO.

In this case, the output to parent.log is as follows:

Warning message
Error message
Critical message

while that of file.log is the same as before. In summary, when a log message is recorded by a logger,

1. The severity of the message will be determined by the logger’s level. If the logger’s level is not specified, the level of its parent (and, eventually, the root logger) will be used for this purpose.
2. If the log message is handled, a copy of the message is sent to all handlers added along the logger hierarchy up to the root logger. The level of each handler will determine whether or not this message should be honored by this handler.

Formatters

A Formatter is used to configure the logger’s format. It allows us to configure the log format in the same way that we did in the root logger’s basicConfig (). Here’s how we can include a formatter in our handler:

import logging

# Set up root logger, and add a file handler to root logger
logging.basicConfig(filename = 'file.log',
level = logging.WARNING,
format = '%(asctime)s:%(levelname)s:%(name)s:%(message)s')

# Create logger, set level, and add stream handler
parent_logger = logging.getLogger("parent")
parent_logger.setLevel(logging.INFO)
parent_fhandler = logging.FileHandler('parent.log')
parent_fhandler.setLevel(logging.WARNING)
parent_formatter = logging.Formatter('%(asctime)s:%(levelname)s:%(message)s')
parent_fhandler.setFormatter(parent_formatter)
parent_logger.addHandler(parent_fhandler)

# Log message of severity INFO or above will be handled
parent_logger.debug('Debug message')
parent_logger.info('Info message')
parent_logger.warning('Warning message')
parent_logger.error('Error message')
parent_logger.critical('Critical message')

First, we create a formatter and then configure our handler to use it. We could create several different loggers, handlers, and formatters and mix and match them based on our preferences.

In this example, the parent.log will have:

2022-03-23 13:28:31,302:WARNING:Warning message
2022-03-23 13:28:31,302:ERROR:Error message
2022-03-23 13:28:31,303:CRITICAL:Critical message

and the file.log associated with the handler at the root logger will have:

2022-03-23 13:28:31,302:INFO:parent:Info message
2022-03-23 13:28:31,302:WARNING:parent:Warning message
2022-03-23 13:28:31,302:ERROR:parent:Error message
2022-03-23 13:28:31,303:CRITICAL:parent:Critical message

The diagram below depicts the flow of loggers, handlers, and formatters from the logging module’s documentation:

An Example of the Use of Logging

Let’s consider the Nadam algorithm as an example:

# gradient descent optimization with nadam for a two-dimensional test function
from math import sqrt
from numpy import asarray
from numpy.random import rand
from numpy.random import seed

# objective function
def objective(x, y):
return x**2.0 + y**2.0

# derivative of objective function
def derivative(x, y):
return asarray([x * 2.0, y * 2.0])

# gradient descent algorithm with nadam
def nadam(objective, derivative, bounds, n_iter, alpha, mu, nu, eps=1e-8):
# generate an initial point
x = bounds[:, 0] + rand(len(bounds)) * (bounds[:, 1] - bounds[:, 0])
score = objective(x[0], x[1])
# initialize decaying moving averages
m = [0.0 for _ in range(bounds.shape[0])]
n = [0.0 for _ in range(bounds.shape[0])]
# run the gradient descent
for t in range(n_iter):
# calculate gradient g(t)
g = derivative(x[0], x[1])
# build a solution one variable at a time
for i in range(bounds.shape[0]):
# m(t) = mu * m(t-1) + (1 - mu) * g(t)
m[i] = mu * m[i] + (1.0 - mu) * g[i]
# n(t) = nu * n(t-1) + (1 - nu) * g(t)^2
n[i] = nu * n[i] + (1.0 - nu) * g[i]**2
# mhat = (mu * m(t) / (1 - mu)) + ((1 - mu) * g(t) / (1 - mu))
mhat = (mu * m[i] / (1.0 - mu)) + ((1 - mu) * g[i] / (1.0 - mu))
# nhat = nu * n(t) / (1 - nu)
nhat = nu * n[i] / (1.0 - nu)
# x(t) = x(t-1) - alpha / (sqrt(nhat) + eps) * mhat
x[i] = x[i] - alpha / (sqrt(nhat) + eps) * mhat
# evaluate candidate point
score = objective(x[0], x[1])
# report progress
print('>%d f(%s) = %.5f' % (t, x, score))
return [x, score]

# seed the pseudo random number generator
seed(1)
# define range for input
bounds = asarray([[-1.0, 1.0], [-1.0, 1.0]])
# define the total iterations
n_iter = 50
# steps size
alpha = 0.02
# factor for average gradient
mu = 0.8
# factor for average squared gradient
nu = 0.999
# perform the gradient descent search with nadam
best, score = nadam(objective, derivative, bounds, n_iter, alpha, mu, nu)
print('Done!')
print('f(%s) = %f' % (best, score))

The most basic application is to use logging to replace the print() function. We can make the following modifications: Before we run any code, let’s first create a logger called nadam and assign it a StreamHandler:

...

import logging

...

# Added: Create logger and assign handler
logger = logging.getLogger("nadam")
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(asctime)s|%(levelname)s|%(name)s|%(message)s"))
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)
# seed the pseudo random number generator
seed(1)
... # rest of the code

Because we never configured the root logger, this will be the only handler ever created. Then, in the function nadam(), we recreate a logger nadam, but because it was already set up, the level and handlers are preserved. We replaced the print() function at the end of each outer for-loop in nadam() with logger.info() to ensure that the message is handled by the logging system:

...

# gradient descent algorithm with nadam
def nadam(objective, derivative, bounds, n_iter, alpha, mu, nu, eps=1e-8):
# Create a logger
logger = logging.getLogger("nadam")
# generate an initial point
x = bounds[:, 0] + rand(len(bounds)) * (bounds[:, 1] - bounds[:, 0])
score = objective(x[0], x[1])
# initialize decaying moving averages
m = [0.0 for _ in range(bounds.shape[0])]
n = [0.0 for _ in range(bounds.shape[0])]
# run the gradient descent
for t in range(n_iter):
# calculate gradient g(t)
g = derivative(x[0], x[1])
# build a solution one variable at a time
for i in range(bounds.shape[0]):
# m(t) = mu * m(t-1) + (1 - mu) * g(t)
m[i] = mu * m[i] + (1.0 - mu) * g[i]
# n(t) = nu * n(t-1) + (1 - nu) * g(t)^2
n[i] = nu * n[i] + (1.0 - nu) * g[i]**2
# mhat = (mu * m(t) / (1 - mu)) + ((1 - mu) * g(t) / (1 - mu))
mhat = (mu * m[i] / (1.0 - mu)) + ((1 - mu) * g[i] / (1.0 - mu))
# nhat = nu * n(t) / (1 - nu)
nhat = nu * n[i] / (1.0 - nu)
# x(t) = x(t-1) - alpha / (sqrt(nhat) + eps) * mhat
x[i] = x[i] - alpha / (sqrt(nhat) + eps) * mhat
# evaluate candidate point
score = objective(x[0], x[1])
# report progress using logger
logger.info('>%d f(%s) = %.5f' % (t, x, score))
return [x, score]

...

More logs may be added if we are interested in the deeper mechanics of the Nadam algorithm. The complete code is as follows:

# gradient descent optimization with nadam for a two-dimensional test function
import logging
from math import sqrt
from numpy import asarray
from numpy.random import rand
from numpy.random import seed

# objective function
def objective(x, y):
return x**2.0 + y**2.0

# derivative of objective function
def derivative(x, y):
return asarray([x * 2.0, y * 2.0])

# gradient descent algorithm with nadam
def nadam(objective, derivative, bounds, n_iter, alpha, mu, nu, eps=1e-8):
logger = logging.getLogger("nadam")
# generate an initial point
x = bounds[:, 0] + rand(len(bounds)) * (bounds[:, 1] - bounds[:, 0])
score = objective(x[0], x[1])
# initialize decaying moving averages
m = [0.0 for _ in range(bounds.shape[0])]
n = [0.0 for _ in range(bounds.shape[0])]
# run the gradient descent
for t in range(n_iter):
iterlogger = logging.getLogger("nadam.iter")
# calculate gradient g(t)
g = derivative(x[0], x[1])
# build a solution one variable at a time
for i in range(bounds.shape[0]):
# m(t) = mu * m(t-1) + (1 - mu) * g(t)
m[i] = mu * m[i] + (1.0 - mu) * g[i]
# n(t) = nu * n(t-1) + (1 - nu) * g(t)^2
n[i] = nu * n[i] + (1.0 - nu) * g[i]**2
# mhat = (mu * m(t) / (1 - mu)) + ((1 - mu) * g(t) / (1 - mu))
mhat = (mu * m[i] / (1.0 - mu)) + ((1 - mu) * g[i] / (1.0 - mu))
# nhat = nu * n(t) / (1 - nu)
nhat = nu * n[i] / (1.0 - nu)
# x(t) = x(t-1) - alpha / (sqrt(nhat) + eps) * mhat
x[i] = x[i] - alpha / (sqrt(nhat) + eps) * mhat
iterlogger.info("Iteration %d variable %d: mhat=%f nhat=%f", t, i, mhat, nhat)
# evaluate candidate point
score = objective(x[0], x[1])
# report progress
logger.info('>%d f(%s) = %.5f' % (t, x, score))
return [x, score]

# Create logger and assign handler
logger = logging.getLogger("nadam")
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(asctime)s|%(levelname)s|%(name)s|%(message)s"))
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)
logger = logging.getLogger("nadam.iter")
logger.setLevel(logging.INFO)
# seed the pseudo random number generator
seed(1)
# define range for input
bounds = asarray([[-1.0, 1.0], [-1.0, 1.0]])
# define the total iterations
n_iter = 50
# steps size
alpha = 0.02
# factor for average gradient
mu = 0.8
# factor for average squared gradient
nu = 0.999
# perform the gradient descent search with nadam
best, score = nadam(objective, derivative, bounds, n_iter, alpha, mu, nu)
print('Done!')
print('f(%s) = %f' % (best, score))

We created two different levels of loggers, nadam and nadam.iter. The child logger is used in the inner loop of nadam() to print some internal variables. When you run this script, it will print the following:

2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 0 variable 0: mhat=-0.597442 nhat=0.110055
2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 0 variable 1: mhat=1.586336 nhat=0.775909
2022-03-29 12:24:59,421|INFO|nadam|>0 f([-0.12993798 0.40463097]) = 0.18061
2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 1 variable 0: mhat=-0.680200 nhat=0.177413
2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 1 variable 1: mhat=2.020702 nhat=1.429384
2022-03-29 12:24:59,421|INFO|nadam|>1 f([-0.09764012 0.37082777]) = 0.14705
2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 2 variable 0: mhat=-0.687764 nhat=0.215332
2022-03-29 12:24:59,421|INFO|nadam.iter|Iteration 2 variable 1: mhat=2.304132 nhat=1.977457
2022-03-29 12:24:59,421|INFO|nadam|>2 f([-0.06799761 0.33805721]) = 0.11891
...
2022-03-29 12:24:59,449|INFO|nadam.iter|Iteration 49 variable 0: mhat=-0.000482 nhat=0.246709
2022-03-29 12:24:59,449|INFO|nadam.iter|Iteration 49 variable 1: mhat=-0.018244 nhat=3.966938
2022-03-29 12:24:59,449|INFO|nadam|>49 f([-5.54299505e-05 -1.00116899e-03]) = 0.00000
Done!
f([-5.54299505e-05 -1.00116899e-03]) = 0.000001

Setting different loggers allows us to not only set a different level or handlers, but it also allows us to differentiate where the log message comes from by looking at the logger’s name from the message printed.

Indeed, one useful trick is to create a logging decorator and apply it to some functions. We can keep track of every call to that function. For example, in the following code, we created a decorator and applied it to the functions objective() and derivative():

...

# A Python decorator to log the function call and return value
def loggingdecorator(name):
logger = logging.getLogger(name)
def _decor(fn):
function_name = fn.__name__
def _fn(*args, **kwargs):
ret = fn(*args, **kwargs)
argstr = [str(x) for x in args]
argstr += [key+"="+str(val) for key,val in kwargs.items()]
logger.debug("%s(%s) -> %s", function_name, ", ".join(argstr), ret)
return ret
return _fn
return _decor

# objective function
@loggingdecorator("nadam.function")
def objective(x, y):
return x**2.0 + y**2.0

# derivative of objective function
@loggingdecorator("nadam.function")
def derivative(x, y):
return asarray([x * 2.0, y * 2.0])

Then we will see the following in the log:

2022-03-29 13:14:07,542|DEBUG|nadam.function|objective(-0.165955990594852, 0.4406489868843162) -> 0.22171292045649288
2022-03-29 13:14:07,542|DEBUG|nadam.function|derivative(-0.165955990594852, 0.4406489868843162) -> [-0.33191198 0.88129797]
2022-03-29 13:14:07,542|INFO|nadam.iter|Iteration 0 variable 0: mhat=-0.597442 nhat=0.110055
2022-03-29 13:14:07,542|INFO|nadam.iter|Iteration 0 variable 1: mhat=1.586336 nhat=0.775909
2022-03-29 13:14:07,542|DEBUG|nadam.function|objective(-0.12993797816930272, 0.4046309737819536) -> 0.18061010311445824
2022-03-29 13:14:07,543|INFO|nadam|>0 f([-0.12993798 0.40463097]) = 0.18061
2022-03-29 13:14:07,543|DEBUG|nadam.function|derivative(-0.12993797816930272, 0.4046309737819536) -> [-0.25987596 0.80926195]
2022-03-29 13:14:07,543|INFO|nadam.iter|Iteration 1 variable 0: mhat=-0.680200 nhat=0.177413
2022-03-29 13:14:07,543|INFO|nadam.iter|Iteration 1 variable 1: mhat=2.020702 nhat=1.429384
2022-03-29 13:14:07,543|DEBUG|nadam.function|objective(-0.09764011794760165, 0.3708277653552375) -> 0.14704682419118062
2022-03-29 13:14:07,543|INFO|nadam|>1 f([-0.09764012 0.37082777]) = 0.14705
2022-03-29 13:14:07,543|DEBUG|nadam.function|derivative(-0.09764011794760165, 0.3708277653552375) -> [-0.19528024 0.74165553]
2022-03-29 13:14:07,543|INFO|nadam.iter|Iteration 2 variable 0: mhat=-0.687764 nhat=0.215332
...

In the message logged by the nadam.function logger, we can see the parameters and return values of each call to those two functions.

The terminal screen will become increasingly crowded as we receive more log messages. Using the Colorama module to highlight logs in color makes it easier to spot problems. You must first have the module installed:

pip install colorama

Here’s an example of how you can use the Colorama module in conjunction with the logging module to change the colors and brightness of your logs:

import logging
import colorama
from colorama import Fore, Back, Style

# Initialize the terminal for color
colorama.init(autoreset = True)

# Set up logger as usual
logger = logging.getLogger("color")
logger.setLevel(logging.DEBUG)
shandler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s:%(levelname)s:%(name)s:%(message)s')
shandler.setFormatter(formatter)
logger.addHandler(shandler)

# Emit log message with color
logger.debug('Debug message')
logger.info(Fore.GREEN + 'Info message')
logger.warning(Fore.BLUE + 'Warning message')
logger.error(Fore.YELLOW + Style.BRIGHT + 'Error message')
logger.critical(Fore.RED + Back.YELLOW + Style.BRIGHT + 'Critical message')

From the terminal, you would see the following:

where the Colorama module’s Fore, Back, and Style controls the foreground, background, and brightness style of the printed text This uses ANSI escape characters and works only on ANSI-compliant terminals. As a result, this is unsuitable for logging into a text file.

We may derive the Formatter class with:

...
colors = {"DEBUG":Fore.BLUE, "INFO":Fore.CYAN,
"WARNING":Fore.YELLOW, "ERROR":Fore.RED, "CRITICAL":Fore.MAGENTA}
class ColoredFormatter(logging.Formatter):
def format(self, record):
msg = logging.Formatter.format(self, record)
if record.levelname in colors:
msg = colors[record.levelname] + msg + Fore.RESET
return msg

and use this instead of logging.Formatter. The following is how we can further modify the Nadam example to add color:

# gradient descent optimization with nadam for a two-dimensional test function
import logging
import colorama
from colorama import Fore

from math import sqrt
from numpy import asarray
from numpy.random import rand
from numpy.random import seed

def loggingdecorator(name):
logger = logging.getLogger(name)
def _decor(fn):
function_name = fn.__name__
def _fn(*args, **kwargs):
ret = fn(*args, **kwargs)
argstr = [str(x) for x in args]
argstr += [key+"="+str(val) for key,val in kwargs.items()]
logger.debug("%s(%s) -> %s", function_name, ", ".join(argstr), ret)
return ret
return _fn
return _decor

# objective function
@loggingdecorator("nadam.function")
def objective(x, y):
return x**2.0 + y**2.0

# derivative of objective function
@loggingdecorator("nadam.function")
def derivative(x, y):
return asarray([x * 2.0, y * 2.0])

# gradient descent algorithm with nadam
def nadam(objective, derivative, bounds, n_iter, alpha, mu, nu, eps=1e-8):
logger = logging.getLogger("nadam")
# generate an initial point
x = bounds[:, 0] + rand(len(bounds)) * (bounds[:, 1] - bounds[:, 0])
score = objective(x[0], x[1])
# initialize decaying moving averages
m = [0.0 for _ in range(bounds.shape[0])]
n = [0.0 for _ in range(bounds.shape[0])]
# run the gradient descent
for t in range(n_iter):
iterlogger = logging.getLogger("nadam.iter")
# calculate gradient g(t)
g = derivative(x[0], x[1])
# build a solution one variable at a time
for i in range(bounds.shape[0]):
# m(t) = mu * m(t-1) + (1 - mu) * g(t)
m[i] = mu * m[i] + (1.0 - mu) * g[i]
# n(t) = nu * n(t-1) + (1 - nu) * g(t)^2
n[i] = nu * n[i] + (1.0 - nu) * g[i]**2
# mhat = (mu * m(t) / (1 - mu)) + ((1 - mu) * g(t) / (1 - mu))
mhat = (mu * m[i] / (1.0 - mu)) + ((1 - mu) * g[i] / (1.0 - mu))
# nhat = nu * n(t) / (1 - nu)
nhat = nu * n[i] / (1.0 - nu)
# x(t) = x(t-1) - alpha / (sqrt(nhat) + eps) * mhat
x[i] = x[i] - alpha / (sqrt(nhat) + eps) * mhat
iterlogger.info("Iteration %d variable %d: mhat=%f nhat=%f", t, i, mhat, nhat)
# evaluate candidate point
score = objective(x[0], x[1])
# report progress
logger.warning('>%d f(%s) = %.5f' % (t, x, score))
return [x, score]

# Prepare the colored formatter
colorama.init(autoreset = True)
colors = {"DEBUG":Fore.BLUE, "INFO":Fore.CYAN,
"WARNING":Fore.YELLOW, "ERROR":Fore.RED, "CRITICAL":Fore.MAGENTA}
class ColoredFormatter(logging.Formatter):
def format(self, record):
msg = logging.Formatter.format(self, record)
if record.levelname in colors:
msg = colors[record.levelname] + msg + Fore.RESET
return msg

# Create logger and assign handler
logger = logging.getLogger("nadam")
handler = logging.StreamHandler()
handler.setFormatter(ColoredFormatter("%(asctime)s|%(levelname)s|%(name)s|%(message)s"))
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)
logger = logging.getLogger("nadam.iter")
logger.setLevel(logging.DEBUG)
# seed the pseudo random number generator
seed(1)
# define range for input
bounds = asarray([[-1.0, 1.0], [-1.0, 1.0]])
# define the total iterations
n_iter = 50
# steps size
alpha = 0.02
# factor for average gradient
mu = 0.8
# factor for average squared gradient
nu = 0.999
# perform the gradient descent search with nadam
best, score = nadam(objective, derivative, bounds, n_iter, alpha, mu, nu)
print('Done!')
print('f(%s) = %f' % (best, score))

If we run it on a supporting terminal, we will see the following output:

It is worth noting that the colorful output can assist us in detecting any abnormal behavior. Logging aids debugging by allowing us to easily control how much detail we want to see by changing a few lines of code.

Summary

You learned how to use logging techniques in your scripts in this tutorial.

You specifically learned:

1. Logging techniques, both basic and advanced
2. How to use logging in a script and the advantages of doing so

Source link