14.1. Logging

14.1.1. Rationale

  • Do not print

  • Always use logger

  • Logs can be displayed on console

  • Logs can be redirected to file

  • Logs can be redirected to database

  • Logs can be silenced (certain level)

  • Logs can be rotated

  • Logs can change format

>>> def run():
...     print('Program start')
...     for number in range(0,3):
...         print(f'Current number: {number}')
...     print('Program end')
>>>
>>>
>>> run()
Program start
Current number: 0
Current number: 1
Current number: 2
Program end
>>> import logging
>>>
>>>
>>> def run():
...     logging.warning('Program start')
...     for number in range(0,3):
...         logging.info(f'Current number: {number}')
...     logging.warning('Program end')
>>>
>>>
>>> run()  
WARNING:root:Program start
WARNING:root:Program end

14.1.2. Logging levels

  • Critical - Error, cannot continue

  • Error - Error, can continue

  • Warning - Warning, will do something important

  • Info - I will do something

  • Debug - This is how I am doing this

Default level is WARNING, so all the information with level below will not be displayed.

>>> import logging
>>>
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')

In logging you can set minimum level required. Setting it to DEBUG will show all the information above DEBUG level, which means everything.

>>> import logging
>>>
>>>
>>> logging.basicConfig(level='DEBUG')
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')

Setting it to ERROR will display only error and critical information.

>>> import logging
>>>
>>>
>>> logging.basicConfig(level='ERROR')
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')

You can also use logging.ERROR constant. Note, that similar constants exists for other levels too.

>>> import logging
>>>
>>>
>>> logging.basicConfig(level=logging.ERROR)
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')

14.1.3. Redirect to File

>>> import logging
>>>
>>>
>>> logging.basicConfig(filename='/tmp/myapp.log')
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')

14.1.4. Log Format

>>> import logging
>>>
>>>
>>> logging.basicConfig(format='%(asctime).19s %(levelname)s %(message)s')
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')

14.1.5. Date Format

>>> import logging
>>>
>>>
>>> logging.basicConfig(
...     format='%(asctime)s %(levelname)s %(message)s',
...     datefmt='"%Y-%m-%d" "%H:%M:%S"',)
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')

14.1.6. Log Style

Logs has three distinct styles:

  • { - curly brackets; compare to f-string formatting

  • % - percent sign; compare to formatting string with %

  • $ - dollar sign; compare to template vars from other languages

Default mode is % percent.

>>> import logging
>>>
>>>
>>> logging.basicConfig(
...     format='%(asctime)s %(levelname)s %(message)s',
...     style='%')
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')
>>> import logging
>>>
>>>
>>> logging.basicConfig(
...     format='{asctime}, "{levelname}", "{message}"',
...     style='{')
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')
>>> import logging
>>>
>>>
>>> logging.basicConfig(
...     format='$asctime, "$levelname", "$message"',
...     style='$')
>>>
>>> logging.critical('Error, cannot continue')
>>> logging.error('Error, can continue')
>>> logging.warning('Information, warn about something')
>>> logging.info('Information, inform about something')
>>> logging.debug('Debug, show detailed debugging information')

14.1.7. Get Logger

>>> import logging
>>>
>>>
>>> log = logging.getLogger('myapp')
>>>
>>> log.critical('Error, cannot continue')
>>> log.error('Error, can continue')
>>> log.warning('Information, warn about something')
>>> log.info('Information, inform about something')
>>> log.debug('Debug, show detailed debugging information')
>>> import logging
>>>
>>>
>>> log = logging.getLogger(__name__)
>>>
>>> log.critical('Error, cannot continue')
>>> log.error('Error, can continue')
>>> log.warning('Information, warn about something')
>>> log.info('Information, inform about something')
>>> log.debug('Debug, show detailed debugging information')

14.1.8. Use Case - CSV log format

>>> import logging
>>>
>>>
>>> logging.basicConfig(
...     level='DEBUG',
...     datefmt='"%Y-%m-%d" "%H:%M:%S"',
...     format='{asctime}, "{levelname}", "{message}"',
...     style='{',
...     filename='/tmp/myapp-log.csv')
>>>
>>> log = logging.getLogger(__name__)
>>>
>>> log.critical('Error, cannot continue')
>>> log.error('Error, can continue')
>>> log.warning('Information, warn about something')
>>> log.info('Information, inform about something')
>>> log.debug('Debug, show detailed debugging information')
import logging


logging.basicConfig(
    level=logging.DEBUG,
    format='"%(asctime).19s", "%(levelname)s", "%(message)s"',
    filename='log.csv',
)

logging.info('Loop start')

i = 0
while i <= 3:
    logging.info(f'Computing {i}')
    i += 1

logging.info('Loop end')
import logging

logging.basicConfig(
    level=logging.INFO,
    filename='/tmp/logging.csv',
    format='"%(asctime).19s", "%(levelname)s", "%(message)s"'
)

log = logging.getLogger(__name__)

log.warning('warning!')  # zostanie zapisana do pliku
log.debug('Debug message')  # nie zostanie zapisana, bo level jest INFO, czyli powyżej DEBUG

14.1.9. Logowanie zdarzeń

import logging
log = logging.getLogger(__name__)

def sum(a, b):
    log.debug('Function `sum()` executed with: %s', locals())
    value = a + b
    log.debug(f'Will produce "{value}" as result')
    return value

sum(1, 2)
# Function `sum()` executed with: {'b': 2, 'a': 1}
# Will produce "3" as result
# 3

14.1.10. Wyciszanie logowania

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format='[%(asctime).19s] [%(levelname)s] %(message)s')

logging.getLogger('requests').setLevel(logging.WARNING)
log = logging.getLogger(__name__)

log.debug('Debug message')

14.1.11. Konfiguracja formatowania logów

Format

Description

args

The tuple of arguments merged into msg to produce message, or a dict whose values are used for the merge (when there is only one argument, and it is a dictionary). You shouldn't need to format this yourself.

%(asctime)s

Human-readable time when the LogRecord was created. By default this is of the form '2003-07-08 16:49:45,896' (the numbers after the comma are millisecond portion of the time).

%(created)f

Time when the LogRecord was created (as returned by time.time).

exc_info

Exception tuple (à la sys.exc_info) or, if no exception has occurred, None. You shouldn't need to format this yourself.

%(filename)s

Filename portion of pathname.

%(funcName)s

Name of function containing the logging call.

%(levelname)s

Text logging level for the message ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL').

%(levelno)s

Numeric logging level for the message (DEBUG, INFO, WARNING, ERROR, CRITICAL).

%(lineno)d

Source line number where the logging call was issued (if available).

%(module)s

Module (name portion of filename).

%(msecs)d

Millisecond portion of the time when the LogRecord was created.

%(message)s

The logged message, computed as msg % args. This is set when Formatter.format is invoked.

msg

The format string passed in the original logging call. Merged with args to produce message, or an arbitrary object (see arbitrary-object-messages). You shouldn't need to format this yourself.

%(name)s

Name of the logger used to log the call.

%(pathname)s

Full pathname of the source file where the logging call was issued (if available).

%(process)d

Process ID (if available).

%(processName)s

Process name (if available).

%(relativeCreated)d

Time in milliseconds when the LogRecord was created, relative to the time the logging module was loaded.

stack_info

Stack frame information (where available) from the bottom of the stack in the current thread, up to and including the stack frame of the logging call which resulted in the creation of this record. You shouldn't need to format this yourself.

%(thread)d

Thread ID (if available).

%(threadName)s

Thread name (if available).

14.1.12. DictConfig

{
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'standard': {
            'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
        },
    },
    'handlers': {
        'default': {
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        '': {
            'handlers': ['default'],
            'level': 'INFO',
            'propagate': True
        },
        'django.request': {
            'handlers': ['default'],
            'level': 'WARN',
            'propagate': False
        },
    }
}
Table 14.1. DictConfig

Format

Description

filename

Specifies that a FileHandler be created, using the specified filename, rather than a StreamHandler

filemode

If filename is specified, open the file in this mode. Defaults to 'a'

format

Use the specified format string for the handler

datefmt

Use the specified date/time format, as accepted by time.strftime()

style

If format is specified, use this style for the format string. One of '%', '{' or '$' for printf-style, str.format() or string.Template respectively. Defaults to '%'

level

Set the root logger level to the specified level

stream

Use the specified stream to initialize the StreamHandler. Note that this argument is incompatible with filename - if both are present, a ValueError is raised

handlers

If specified, this should be an iterable of already created handlers to add to the root logger. Any handlers which don’t already have a formatter set will be assigned the default formatter created in this function. Note that this argument is incompatible with filename or stream - if both are present, a ValueError is raised

14.1.13. Rotate

  • logging.handlers.WatchedFileHandler

  • logging.handlers.RotatingFileHandler

  • logging.handlers.TimedRotatingFileHandler

from logging import handlers

handler = handlers.TimedRotatingFileHandler(filename, when=LOG_ROTATE)

handler.setFormatter(logging.Formatter(log_format, datefmt='%Y-%m-%d %H:%M:%S'))

#LOG_ROTATE = midnight
#set your log format

14.1.14. Examples

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

Decorators:

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

14.1.15. Further Reading