Sometimes when debugging we like to print/log out all the inputs and outputs of a method: name, args, kwargs, dict etc.

We would have some IDE debug features for this purpose but sometimes we need manual debugging.

And while manual debugging I don’t want to write logger.debug(<messsage>) to every one of two lines of a module.

The solution : Python Decorators

First configure a logger. In this post I will implement a default basic configuration. For a detailed configuration go to the post logging configuration post .

Then crate a module for debuggers in utils package, utils/debuggers.py like below:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31

#!/usr/bin/env python3
# -*- coding: utf-8 -*-

# utils/debuggers.py

import logging


logging.basicConfig(
    level=logging.DEBUG,
    format="[%(asctime)s] [%(levelname)s] %(name)s: %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S %z",
)
logger = logging.getLogger(__name__)


class Debugger:
    """ Debug a method and return it back"""

    def __init__(self, func):
        self.func = func

    def __call__(self, *args, **kwargs):
        logger.debug(f'Entering : {self.func.__name__}')
        logger.debug(f'args, kwargs : {args, kwargs}')

        result = self.func(*args, **kwargs)

        logger.debug(f'{self.func.__name__} returned : {result}')

        return result

Then call it and decorate your function like below:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22

#!/usr/bin/env python3
# -*- coding: utf-8 -*-

# main.py

from utils.debuggers import Debugger


@Debugger
def my_func(a, b, c, d):
    return a + b + c + d


if __name__ == "__main__":
    kwargs = dict(
        a=1,
        b=2,
        c=5,
        d=-10
    )

    my_func(**kwargs)

Output will be like:

2019-07-21 18:43:25,635 [DEBUG] debuggers: Entering : my_func
2019-07-21 18:43:25,635 [DEBUG] debuggers: args, kwargs: ((), {'a': 1, 'b': 2, 'c': 5, 'd': -10})
2019-07-21 18:43:25,635 [DEBUG] debuggers: my_func returned -2

If you want a function instead of a class for debugging:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32

#!/usr/bin/env python3
# -*- coding: utf-8 -*-

# utils/decorators.py

import functools
import logging


logging.basicConfig(
    level=logging.DEBUG,
    format="[%(asctime)s] [%(levelname)s] %(name)s: %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S %z",
)
logger = logging.getLogger(__name__)


def debugmethod(func):
    """ Debug a method and return it back"""

    @functools.wraps(func)
    def wrapper(*args, **kwargs):
        logger.debug(f'Calling : {func.__name__}')
        logger.debug(f'args, kwargs: {args, kwargs}')

        result = func(*args, **kwargs)

        logger.debug(f'{func.__name__} returned {result}')

        return result

    return wrapper

Also if you like to know the execution time of the method:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32

#!/usr/bin/env python3
# -*- coding: utf-8 -*-

# utils/debuggers.py

import functools
import logging
import time


logging.basicConfig(
    level=logging.DEBUG,
    format="[%(asctime)s] [%(levelname)s] %(name)s: %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S %z",
)
logger = logging.getLogger(__name__)


def timerun(func):
    """ Calculate the execution time of a method and return it back"""

    @functools.wraps(func)
    def wrapper(*args, **kwargs):
        start = time.time()
        result = func(*args, **kwargs)
        duration = time.time() - start

        logger.debug(f"Duration of {func.__name__} function was {duration}")

        return result

    return wrapper

Output:

2019-07-21 18:43:25,636 [DEBUG] debuggers: Duration of my_func was 0.00023937225341796875

You can combine your decorators as below:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

#!/usr/bin/env python3
# -*- coding: utf-8 -*-

# main.py

from utils.debuggers import debugmethod, timerun


@timerun
@debugmethod
def my_func(a, b, c, d):
    return a + b + c + d


if __name__ == "__main__":
    kwargs = dict(
        a=1,
        b=2,
        c=5,
        d=-10
    )

    my_func(**kwargs)

Output should be like this:

2019-07-21 18:43:25,635 [DEBUG] debuggers: Calling : my_func
2019-07-21 18:43:25,635 [DEBUG] debuggers: args, kwargs: ((), {'a': 1, 'b': 2, 'c': 5, 'd': -10})
2019-07-21 18:43:25,635 [DEBUG] debuggers: my_func returned -2
2019-07-21 18:43:25,636 [DEBUG] debuggers: Duration of my_func was 0.00023937225341796875

OK, all done.

Changelog

  • 2022-05-11 :
    • Fixed Debugger: multiple func call and possible bug for modified args/kwargs. Thanks @dwysocki for pointing that out.
    • Added basic logging config.
    • Added line numbers to code snippets.