Logging in Python #AI - The Entrepreneurial Way with A.I.

Breaking

Friday, April 8, 2022

Home A.I. Daniel Chung Khareem Sudlow Logging in Python #AI

Logging in Python #AI

#A.I.

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.

After completing this tutorial, you will know:

  • Why we would like to use the logging module
  • How to use the logging module
  • How to customize the logging mechanism

Let’s get started.

Logging in Python
Photo by ilaria88. Some rights reserved.

Tutorial Overview

This tutorial is divided into four parts; they are:

  • The benefits of logging
  • Basic logging
  • Advanced configuration to logging
  • An example of the use of logging

Benefits of Logging

You may ask: “Why not just use printing?”

When you run an algorithm and want to confirm it is doing what you expected, it is natural to add some print() statements at strategic locations to show the program’s 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.

With 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.

Basic Logging

Python has a built-in library, logging, for this purpose. It is simple to create a “logger” to log messages or information that you would like to see.

The 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() 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.

There are 5 different logging levels that indicate the severity of the logs, shown in increasing severity:

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

A very simple example of logging is shown below, 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 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:

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 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.

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. Here’s an example:

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 produce no output to the screen but will have 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 call to logging.basicConfig() 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.

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

Although 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:

logger = logging.getLogger("logger_name")

Internally, the loggers are organized in a hierarchy. A logger created with:

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

will be a child logger created under the logger with the name “parent,” 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 “parent.child” is created as well as one with the name "parent" implicitly.

Upon creation, a child logger has all the properties of its parent logger until reconfigured. We can demonstrate this with the following example:

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 output only one line:

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

which is created by the StreamHandler object with the customized format string. It happens only after we reconfigured the logger for parent because otherwise, the root logger’s configuration prevails, and no messages at level INFO will be printed.

Advanced Configuration to Logging

As we saw in the last example, we can configure the loggers we made.

Threshold of Level

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 of the level of a logger to INFO:

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

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") because there are no handlers assigned for this logger. In fact, there are no handlers for root logger as well unless you set up one with logging.basicConfig().

Log Handlers

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 and FileHandler. With StreamHandler, the logger will output to the terminal, while with FileHandler, the logger will output to a particular file.

Here’s an example of using StreamHandler to output 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')

In the code above, there are two handlers created: A FileHandler created by logging.basicConfig() for the root logger and a StreamHandler created for the parent logger.

Note that even though there is a StreamHandler that sends the logs to the terminal, logs from the parent logger are still being sent to file.log since it is a child of the root logger, and the root logger’s handler is also active for the child’s log messages. We can see that the logs to the terminal include INFO level messages and above:

Info message
Warning message
Error message
Critical message

But the output to the terminal is not formatted, as we have not used a Formatter yet. The log to file.log, however, has a Formatter set up, and it will be like the following:

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

Alternatively, we can use FileHandler in the above example of parent_logger:

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 example above demonstrated that you can also set the level of a handler. The level of parent_fhandler filters out logs that are not WARNING level or higher. However, if you set the handler’s level to DEBUG, that would be the same as not setting the level because DEBUG logs would already be filtered out by the logger’s level, which is INFO.

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

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 logger’s level will determine if the message is severe enough to be handled. If the logger’s level is not set, the level of its parent (and ultimately the root logger) will be used for this consideration.
  2. If the log message will be handled, all handlers ever added along the logger hierarchy up to the root logger will receive a copy of the message. Each handler’s level will determine if this particular handler should honor this message.

Formatters

To configure the format of the logger, we use a Formatter. It allows us to set the format of the log, similarly to how we did so in the root logger’s basicConfig(). This is how we can add a formatter to 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, 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.

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 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

Below is the visualization of the flow of loggers, handlers, and formatters from the documentation of the logging module:

Flow chart of loggers and handlers in the logging module

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 simplest use case is to use logging to replace the print() function. We can make the following change: First, create a logger with the name nadam before we run any code and assign 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

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(), we re-create a logger nadam, but since it has already been set up, the level and handlers persisted. At the end of each outer for-loop in nadam(), we replaced the print() function with logger.info() so the message will be 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]

...

If we are interested in the deeper mechanics of the Nadam algorithm, we may add more logs. The following is the complete code:

# 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 prepared two level of loggers, nadam and nadam.iter, and set them in different levels. In the inner loop of nadam(), we use the child logger 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 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’s name from the message printed.

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() 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
...

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

As 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 module. You need to have the module installed first:

pip install colorama

Here’s an example of how you can use the colorama module with the logging module to change your log colors and text brightness:

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 Fore, Back, and Style from the colorama 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.

In fact, 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:

Note 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.

Further Reading

This section provides more resources on the topic if you are looking to go deeper.

APIs

Articles

Summary

In this tutorial, you learned how to implement logging techniques in your scripts.

Specifically, you learned:

  • Basic and advanced logging techniques
  • How to apply logging to a script and the benefits of doing so

The post Logging in Python appeared first on Machine Learning Mastery.



via https://AIupNow.com

Daniel Chung, Khareem Sudlow
Tags
Author Image

About BruceDayne

By at
Labels: , ,

Author Details

Block-Chain Evangelist and Entrepreneur, Khareem Sudlow now founded, advised and invested in various blockchain projects.