18.8. Logging Use Cases

18.8.1. Case Study

def main():
    print('Function `main()` start')

    print('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    print('Users processing start')
    for user in data:
        print(f'User process: {user}')
        result = user.upper()
        print(result)
    print('Users processing end')

    print('Function `main()` end')
    return ...


if __name__ == '__main__':
    print('Program start')
    main()
    print('Program end')

# $ python main.py
# Program start
# Function `main()` start
# Users prepare...
# Users processing start
# User process: Alice
# ALICE
# User process: Bob
# BOB
# User process: Carol
# CAROL
# Users processing end
# Function `main()` end
# Program end

import logging


def main():
    logging.debug('Function `main()` start')

    logging.info('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    logging.debug('Users processing start')
    for user in data:
        logging.info(f'User process: {user}')
        result = user.upper()
        print(result)
    logging.debug('Users processing end')

    logging.debug('Function `main()` end')
    return ...


if __name__ == '__main__':
    logging.warning('Program start')
    main()
    logging.warning('Program end')

# $ python main.py
# WARNING:root:Program start
# ALICE
# BOB
# CAROL
# WARNING:root:Program end

import logging


log = logging.getLogger('myapp')


def main():
    log.debug('Function `main()` start')

    log.info('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    log.debug('Users processing start')
    for user in data:
        log.info(f'User process: {user}')
        result = user.upper()
        print(result)
    log.debug('Users processing end')

    log.debug('Function `main()` end')
    return ...


if __name__ == '__main__':
    log.warning('Program start')
    main()
    log.warning('Program end')

# $ python main.py
# Program start
# ALICE
# BOB
# CAROL
# Program end

import logging


logging.basicConfig(level='DEBUG')
log = logging.getLogger('myapp')


def main():
    log.debug('Function `main()` start')

    log.info('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    log.debug('Users processing start')
    for user in data:
        log.info(f'User process: {user}')
        result = user.upper()
        print(result)
    log.debug('Users processing end')

    log.debug('Function `main()` end')
    return ...


if __name__ == '__main__':
    log.warning('Program start')
    main()
    log.warning('Program end')

# $ python main.py
# WARNING:myapp:Program start
# DEBUG:myapp:Function `main()` start
# INFO:myapp:Users prepare...
# DEBUG:myapp:Users processing start
# INFO:myapp:User process: Alice
# ALICE
# INFO:myapp:User process: Bob
# BOB
# INFO:myapp:User process: Carol
# CAROL
# DEBUG:myapp:Users processing end
# DEBUG:myapp:Function `main()` end
# WARNING:myapp:Program end

import logging
import argparse


parser = argparse.ArgumentParser()
parser.add_argument('--debug', action='store_const', dest='level', const='DEBUG', help='Enable debug logging')
parser.add_argument('--info', action='store_const', dest='level', const='INFO', help='Enable info logging')
parser.add_argument('--warning', action='store_const', dest='level', const='WARNING', help='Enable warning logging')
parser.add_argument('--error', action='store_const', dest='level', const='ERROR', help='Enable error logging')
parser.add_argument('--critical', action='store_const', dest='level', const='CRITICAL', help='Enable critical logging')
args = parser.parse_args()

logging.basicConfig(level=args.level or 'ERROR')
log = logging.getLogger('myapp')


def main():
    log.debug('Function `main()` start')

    log.info('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    log.debug('Users processing start')
    for user in data:
        log.info(f'User process: {user}')
        result = user.upper()
        print(result)
    log.debug('Users processing end')

    log.debug('Function `main()` end')
    return ...


if __name__ == '__main__':
    log.warning('Program start')
    main()
    log.warning('Program end')

# $ python main.py
# ALICE
# BOB
# CAROL

# $ python main.py --critical
# ALICE
# BOB
# CAROL

# $ python main.py --error
# ALICE
# BOB
# CAROL

# $ python main.py --warning
# WARNING:myapp:Program start
# ALICE
# BOB
# CAROL
# WARNING:myapp:Program end

# $ python main.py --info
# WARNING:myapp:Program start
# INFO:myapp:Users prepare...
# INFO:myapp:User process: Alice
# ALICE
# INFO:myapp:User process: Bob
# BOB
# INFO:myapp:User process: Carol
# CAROL
# WARNING:myapp:Program end

# $ python main.py --debug
# WARNING:myapp:Program start
# DEBUG:myapp:Function `main()` start
# INFO:myapp:Users prepare...
# DEBUG:myapp:Users processing start
# INFO:myapp:User process: Alice
# ALICE
# INFO:myapp:User process: Bob
# BOB
# INFO:myapp:User process: Carol
# CAROL
# DEBUG:myapp:Users processing end
# DEBUG:myapp:Function `main()` end
# WARNING:myapp:Program end

import logging
import argparse


parser = argparse.ArgumentParser()
parser.add_argument('--debug', action='store_const', dest='level', const='DEBUG', help='Enable debug logging')
parser.add_argument('--info', action='store_const', dest='level', const='INFO', help='Enable info logging')
parser.add_argument('--warning', action='store_const', dest='level', const='WARNING', help='Enable warning logging')
parser.add_argument('--error', action='store_const', dest='level', const='ERROR', help='Enable error logging')
parser.add_argument('--critical', action='store_const', dest='level', const='CRITICAL', help='Enable critical logging')
args = parser.parse_args()

logging.basicConfig(
    level=args.level or 'DEBUG',
    format='%(asctime).19s, %(pathname)s:%(lineno)s, %(levelname)s, %(message)s',
)

log = logging.getLogger('myapp')


def main():
    log.debug('Function `main()` start')

    log.info('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    log.debug('Users processing start')
    for user in data:
        log.info(f'User process: {user}')
        result = user.upper()
        print(result)
    log.debug('Users processing end')

    log.debug('Function `main()` end')
    return ...


if __name__ == '__main__':
    log.warning('Program start')
    main()
    log.warning('Program end')

# $ python main.py
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:39, WARNING, Program start
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:22, DEBUG, Function `main()` start
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:24, INFO, Users prepare...
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:27, DEBUG, Users processing start
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:29, INFO, User process: Alice
# ALICE
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:29, INFO, User process: Bob
# BOB
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:29, INFO, User process: Carol
# CAROL
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:32, DEBUG, Users processing end
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:34, DEBUG, Function `main()` end
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:41, WARNING, Program end

import logging
import argparse


parser = argparse.ArgumentParser()
parser.add_argument('--debug', action='store_const', dest='level', const='DEBUG', help='Enable debug logging')
parser.add_argument('--info', action='store_const', dest='level', const='INFO', help='Enable info logging')
parser.add_argument('--warning', action='store_const', dest='level', const='WARNING', help='Enable warning logging')
parser.add_argument('--error', action='store_const', dest='level', const='ERROR', help='Enable error logging')
parser.add_argument('--critical', action='store_const', dest='level', const='CRITICAL', help='Enable critical logging')
args = parser.parse_args()

logging.basicConfig(
    level=args.level or 'DEBUG',
    format='$asctime, $pathname:$lineno, $levelname, $message',
    style='$'
)

log = logging.getLogger('myapp')


def main():
    log.debug('Function `main()` start')

    log.info('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    log.debug('Users processing start')
    for user in data:
        log.info(f'User process: {user}')
        result = user.upper()
        print(result)
    log.debug('Users processing end')

    log.debug('Function `main()` end')
    return ...


if __name__ == '__main__':
    log.warning('Program start')
    main()
    log.warning('Program end')

# $ python main.py
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:39, WARNING, Program start
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:22, DEBUG, Function `main()` start
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:24, INFO, Users prepare...
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:27, DEBUG, Users processing start
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:29, INFO, User process: Alice
# ALICE
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:29, INFO, User process: Bob
# BOB
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:29, INFO, User process: Carol
# CAROL
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:32, DEBUG, Users processing end
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:34, DEBUG, Function `main()` end
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:41, WARNING, Program end

import logging
import argparse


parser = argparse.ArgumentParser()
parser.add_argument('--debug', action='store_const', dest='level', const='DEBUG', help='Enable debug logging')
parser.add_argument('--info', action='store_const', dest='level', const='INFO', help='Enable info logging')
parser.add_argument('--warning', action='store_const', dest='level', const='WARNING', help='Enable warning logging')
parser.add_argument('--error', action='store_const', dest='level', const='ERROR', help='Enable error logging')
parser.add_argument('--critical', action='store_const', dest='level', const='CRITICAL', help='Enable critical logging')
args = parser.parse_args()

logging.basicConfig(
    level=args.level or 'DEBUG',
    format='{asctime}, {pathname}:{lineno}, {levelname}, {message}',
    style='{'
)

log = logging.getLogger('myapp')


def main():
    log.debug('Function `main()` start')

    log.info('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    log.debug('Users processing start')
    for user in data:
        log.info(f'User process: {user}')
        result = user.upper()
        print(result)
    log.debug('Users processing end')

    log.debug('Function `main()` end')
    return ...


if __name__ == '__main__':
    log.warning('Program start')
    main()
    log.warning('Program end')

# $ python main.py
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:39, WARNING, Program start
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:22, DEBUG, Function `main()` start
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:24, INFO, Users prepare...
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:27, DEBUG, Users processing start
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:29, INFO, User process: Alice
# ALICE
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:29, INFO, User process: Bob
# BOB
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:29, INFO, User process: Carol
# CAROL
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:32, DEBUG, Users processing end
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:34, DEBUG, Function `main()` end
# 2000-01-01 00:00:00,000, /home/alice/myapp/main.py:41, WARNING, Program end

import logging
import argparse


parser = argparse.ArgumentParser()
parser.add_argument('--debug', action='store_const', dest='level', const='DEBUG', help='Enable debug logging')
parser.add_argument('--info', action='store_const', dest='level', const='INFO', help='Enable info logging')
parser.add_argument('--warning', action='store_const', dest='level', const='WARNING', help='Enable warning logging')
parser.add_argument('--error', action='store_const', dest='level', const='ERROR', help='Enable error logging')
parser.add_argument('--critical', action='store_const', dest='level', const='CRITICAL', help='Enable critical logging')
args = parser.parse_args()

logging.basicConfig(
    level=args.level or 'DEBUG',
    format='{asctime}, {pathname}:{lineno}, {levelname}, {message}',
    datefmt='%Y-%m-%d, %H:%M',
    style='{'
)

log = logging.getLogger('myapp')


def main():
    log.debug('Function `main()` start')

    log.info('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    log.debug('Users processing start')
    for user in data:
        log.info(f'User process: {user}')
        result = user.upper()
        print(result)
    log.debug('Users processing end')

    log.debug('Function `main()` end')
    return ...


if __name__ == '__main__':
    log.warning('Program start')
    main()
    log.warning('Program end')

# $ python main.py
# 2000-01-01 00:00, /home/alice/myapp/main.py:39, WARNING, Program start
# 2000-01-01 00:00, /home/alice/myapp/main.py:22, DEBUG, Function `main()` start
# 2000-01-01 00:00, /home/alice/myapp/main.py:24, INFO, Users prepare...
# 2000-01-01 00:00, /home/alice/myapp/main.py:27, DEBUG, Users processing start
# 2000-01-01 00:00, /home/alice/myapp/main.py:29, INFO, User process: Alice
# ALICE
# 2000-01-01 00:00, /home/alice/myapp/main.py:29, INFO, User process: Bob
# BOB
# 2000-01-01 00:00, /home/alice/myapp/main.py:29, INFO, User process: Carol
# CAROL
# 2000-01-01 00:00, /home/alice/myapp/main.py:32, DEBUG, Users processing end
# 2000-01-01 00:00, /home/alice/myapp/main.py:34, DEBUG, Function `main()` end
# 2000-01-01 00:00, /home/alice/myapp/main.py:41, WARNING, Program end

import logging
import argparse


parser = argparse.ArgumentParser()
parser.add_argument('--debug', action='store_const', dest='level', const='DEBUG', help='Enable debug logging')
parser.add_argument('--info', action='store_const', dest='level', const='INFO', help='Enable info logging')
parser.add_argument('--warning', action='store_const', dest='level', const='WARNING', help='Enable warning logging')
parser.add_argument('--error', action='store_const', dest='level', const='ERROR', help='Enable error logging')
parser.add_argument('--critical', action='store_const', dest='level', const='CRITICAL', help='Enable critical logging')
args = parser.parse_args()

logging.basicConfig(
    level=args.level or 'DEBUG',
    format='{asctime}, {pathname}:{lineno}, {levelname}, {message}',
    datefmt='%Y-%m-%d, %H:%M:%S',
    style='{',
    filename='/tmp/myfile.log',
)

log = logging.getLogger('myapp')


def main():
    log.debug('Function `main()` start')

    log.info('Users prepare...')
    data = ['Alice', 'Bob', 'Carol']

    log.debug('Users processing start')
    for user in data:
        log.info(f'User process: {user}')
        result = user.upper()
        print(result)
    log.debug('Users processing end')

    log.debug('Function `main()` end')
    return ...


if __name__ == '__main__':
    log.warning('Program start')
    main()
    log.warning('Program end')

# $ python main.py
# ALICE
# BOB
# CAROL

# $ cat /tmp/myfile.log
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:42, WARNING, Program start
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:25, DEBUG, Function `main()` start
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:27, INFO, Users prepare...
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:30, DEBUG, Users processing start
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:32, INFO, User process: Alice
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:32, INFO, User process: Bob
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:32, INFO, User process: Carol
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:35, DEBUG, Users processing end
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:37, DEBUG, Function `main()` end
# 2000-01-01, 00:00:00, /home/alice/myapp/main.py:44, WARNING, Program end

18.8.2. Use Case - 1

import logging
import os

logging.basicConfig(
    format='"{asctime}", "{levelname}", "{message}"',
    filename='...',
    style='{'
)

log = logging.getLogger(__name__)
level = os.getenv('LOG_LEVEL', 'INFO')
log.setLevel(level)


log.critical('Critical error... finishing')
log.error('Some problem but can continue')
log.warning('Warning, this is important')
log.info('Typical message')
log.debug('Debug message with extra information')


logging.getLogger('requests').setLevel('DEBUG')
logging.getLogger('_tmp').setLevel('ERROR')

18.8.3. Use Case - 2

from datetime import datetime
import logging

logging.basicConfig(
    level='DEBUG',
    datefmt='%Y-%m-%d %H:%M:%S',
    format='[{levelname}] {message}',
    style='{'
)


def timeit(func):
    def wrapper(*args, **kwargs):
        time_start = datetime.now()
        result = func(*args, **kwargs)
        time_end = datetime.now()
        time = time_end - time_start
        logging.debug(f'Time: {time}')
        return result
    return wrapper


def debug(func):
    def wrapper(*args, **kwargs):
        function = func.__name__
        logging.debug(f'Calling: {function=}, {args=}, {kwargs=}')
        result = func(*args, **kwargs)
        logging.debug(f'Result: {result}')
        return result
    return wrapper


@timeit
@debug
def add_numbers(a, b):
    return a + b


add_numbers(1, 2)
# [DEBUG] Calling: function='add_numbers', args=(1, 2), kwargs={}
# [DEBUG] Result: 3
# [DEBUG] Time: 0:00:00.000105

add_numbers(1, b=2)
# [DEBUG] Calling: function='add_numbers', args=(1,), kwargs={'b': 2}
# [DEBUG] Result: 3
# [DEBUG] Time: 0:00:00.000042

add_numbers(a=1, b=2)
# [DEBUG] Calling: function='add_numbers', args=(), kwargs={'a': 1, 'b': 2}
# [DEBUG] Result: 3
# [DEBUG] Time: 0:00:00.000040

18.8.4. Use Case - 3

>>> from datetime import datetime
>>> from uuid import uuid1
>>> import logging
>>>
>>>
>>> logging.basicConfig(
...     level='WARNING',
...     datefmt='%Y-%m-%d %H:%M:%S',
...     format='[{levelname}] {message}',
...     style='{'
... )
>>>
>>>
>>> class MyError(Exception):
...     def __init__(self, *args, **kwargs):
...         self.name = self.__class__.__name__
...         self.reason = self.args[0]
...
...         # make a UUID based on the host ID and current time
...         self.uuid = str(uuid1())
...
...         # save when exception occurred
...         self.when = datetime.now()
...
...         # run normal processing of the exception
...         super().__init__(*args, **kwargs)
>>>
>>>
>>> def run():
...     raise MyError('Error, because it is not working')
>>>
>>>
>>> try:
...     run()
... except Exception as error:
...     name = self.name
...     reason = self.reason
...     when = error.when.strftime('%Y-%m-%d %H:%M:%S')
...     identifier = error.uuid
...
...     # you can write this error to the database
...     # or print it on the stderr
...     logging.error(f'Error happened: {name=}, {reason=}, {when=}, {identifier=}')
[ERROR] Error happened: name='MyError', reason='Error, because it is not working', when='1969-07-21 02:56:15', identifier='886a59c4-8431-11ec-95bc-acde48001122'