uologging 0.10.0

Auto-Configuration solution for Python built-in logging.

UOLogging is a solution for configuring Python's built-in logging module, including a utility for tracing multithreaded downloads.

Install

pip install uologging[optional]

ℹ Use the '[optional] suffix to download the (†very small) humanize package as well.

humanize makes logs human-readable when dealing with large numbers.

† The humanize package is 78.5 kB as of version 4.9.0.

Enable console logging

Simply call "init_console()" to initializing Python's root logger to log to console:

# ⚠ Inadvisable: Enable logging for ALL python packages/modules
uologging.init_console()

⚠ WARNING: It is inadvisable to "init" the overall root logger except for debugging. Why? The console can get very noisy when using 3rd party libraries (that use Python logging module).

In general, you will want to specify your package name. To enable logging within your package only, you can provide your package name.

The handy invocation of __name__.split('.')[0] will provide your package's name from anywhere within your package.

# ✅ Best Practice: Enable logging only for your package.
my_package_name = __name__.split('.')[0]
uologging.init_console(my_package_name)

Enable (Linux) syslog logging

Similarly, you can call "init_syslog()":

# Best Practice: Enable logging for your python package
my_package_name = __name__.split('.')[0]
uologging.init_syslog(my_package_name)

# Inadvisable: Enable logging for ALL python packages/modules
uologging.init_syslog()

Set Logging Verbosity

Per Python logging suggestion: WARNING, ERROR, and CRITICAL messages are all logged by default.

If you are interested in seeing the DEBUG and INFO log messages, you'll need to update the logging verbosity in your application. We provide the method set_verbosity() for this purpose. Higher number means more logging.

Choices are [0,2]. Default is 0. Default will captures WARNING, ERROR, and CRITICAL logs. Provide 1 to also capture INFO logs. Provide 2 to also capture DEBUG logs.

# Enable maximum logging for your python package
my_package_name = __name__.split('.')[0]
uologging.set_verbosity(2, args.verbosity_flag, my_package_name)

# Enable maximum logging for ALL python packages/modules
uologging.set_verbosity(2)

argparse 'verbosity flag'

For CLI tools, we provide an integration with argparse to set the logging verbosity. This integration enables the tool's user to add -vv at the command-line for maximum logging verbosity.

-v will enable INFO messages, but not DEBUG.

The verbosity_flag can be gathered via argparse using "add_verbosity_flag(parser)":

import uologging
import argparse

parser = argparse.ArgumentParser()
uologging.add_verbosity_flag(parser)

args = parser.parse_args(['-vv'])
# args.verbosity_flag == 2

Now, simply call "set_verbosity()" with args.verbosity_flag for your package:

my_package_name = __name__.split('.')[0]
uologging.set_verbosity(args.verbosity_flag, my_package_name)

Example: Configuring CLI tool with console & syslog logging

Let's imagine you have a package "examplepkg" with a CLI tool in the "mytool" module.

# my_cli_tool.py
import argparse
import uologging

# Parse CLI arguments, '-vv' will result in maximum logging verbosity.
parser = argparse.ArgumentParser()
uologging.add_verbosity_flag(parser)
args = parser.parse_args()

# Initialize logging
my_package_name = __name__.split('.')[0]
uologging.init_console(my_package_name)
uologging.init_syslog(my_package_name)
uologging.set_verbosity(args.verbosity_flag, my_package_name)

Logging messages format

The formatting for log messages can be set via the log_format parameter of the init_console() and init_syslog() functions.

Here are a couple of lines showing what you can expect your logs to looks like by default (VERBOSE format):

2022-01-07 15:40:09 DEBUG    Some simle message for you [hello.py:10]
2022-01-07 15:40:09 DEBUG    Finished: example.hello:hello((),{}) [hello.py:10] 
2022-01-07 15:40:09 DEBUG    example.hello:hello((),{}) execution time: 0.00 sec [hello.py:10] 

There are some predefined formats you can use from uologging.format:

• TERSE - Only the message is logged.
• TIMESTAMP - Adds iso-datetime, severity/level
• VERBOSE (default) - Adds source file/line (along with everything in TIMESTAMP)

Override the default format by providing the log_format parameter to init_console() or init_syslog():

uologging.init_console(my_package_name, log_format=uologging.format.TERSE)

Tracing a function

There is a simple trace decorator you can use in your python modules to log the 'execution time' of any of your functions.

The trace decorator logs at DEBUG level by default. So, call set_verbosity(>=2) to see the trace messages in your logs.

# hello.py
import logging
import uologging

logger = logging.getLogger(__name__)

@uologging.trace(logger)
def hello():
    print('hello!')

hello()

Expect the following messages to be logged:

2022-01-07 15:40:09 DEBUG    Starting: example.hello:hello((),{}) [hello.py:10]
hello!
2022-01-07 15:40:09 DEBUG    Finished: example.hello:hello((),{}) [hello.py:10] 
2022-01-07 15:40:09 DEBUG    example.hello:hello((),{}) execution time: 0.00 sec [hello.py:10]

Large argument summarization

When capture_args=True (the default), the trace decorator logs function arguments. To keep logs readable when functions receive large data structures, arguments are automatically summarized:

• Dicts, lists, tuples, sets, and frozensets with more than 10 items are logged as <type[N]> — for example, <list[250]> or <dict[42]>.
• Any repr() longer than 200 characters is truncated and suffixed with ….

This means a bulk-prefetch cache passed as an argument will appear as <dict[5000]> rather than thousands of characters of noise. Use capture_args=False to suppress argument logging entirely (e.g. for functions that receive credentials).

Tracing Concurrent Downloads

Assume you have some service, and you need to make several http requests to download lots of gobs of data. You want to do it concurrently, to save on time.

ℹ 'Downloading data via several http requests' is an example of an 'embarrassingly parallel' problem. I.e. for each concurrent worker we add, we gain 1x speedup Lots of speedup. Ex. using 8 workers will give 8x speedup.

For this big, concurrent download, you would like to see:

1. download progress indications, to know that the download is indeed happening, and
2. when the download is completed, how much in total was downloaded.

There is the uologging.DownloadTracer for that!

The download tracer logs a message for every 1 MB downloaded by default (customizable via 'threshold_bytes').

Trace a concurrent downloads using the DownloadTracer with python requests package like the following:

from concurrent.futures import ThreadPoolExecutor
import requests
import uologging

download_tracer = DownloadTracer('MyService', threshold_bytes=750000)
ALL_MY_URLS = ['http://ex1.io', 'http://ex2.io', 'http://ex3.io']  # ... Replace with your actual list of URLs

def http_get(url):
    respons = requests.get(url)
    download_tracer.trace(len(response.content))
    return response

with ThreadPoolExecutor(max_workers=4) as executor:
    map(http_get, ALL_MY_URLS)

logging Best Practices

Use the Python logging package per the following best practices:

1. logger = logging.getLogger(__name__) to get the logger for each module/script.
2. Then, use logger.debug(), logger.info(), logger.warning(), etc to add tracing to your Python modules/scripts.

Example

A trivial example demonstrating best practices:

# hello.py
import logging

logger = logging.getLogger(__name__)

def hello():
    logger.debug('About to say "hello!"')
    print('hello!')
    logger.debug('Said "hello!"')