Python logging: show variable name without specifying it explicitly A lot of the Python code that I write looks something like this:

import logging
import shlex
import subprocess

logger = logging.getLogger(__name__)


def execute(system_command, **kwargs):
    """Execute a system command, with sane defaults."""
    # Question is mainly about these two lines:
    logger.info("system_command: '%s'", system_command)
    logger.debug("kwargs: %s", kwargs)
    process = subprocess.run(
        shlex.split(system_command),
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
        universal_newlines=True,
        **kwargs)
    if process.returncode != 0:
        logger.info(process.stdout.strip())
        logger.error(process.stderr.strip())
    return process


The logging statements are typically added when I am trying to debug something, but then i forget to remove them and they stay there.

My question is: "Does this code look reasonable?". Is there a way for me to write logger.debug(arg1) and the logger to automatically show the name of the variable being printed, for the sake of DRY?
This is good for narrowing down dirty fixes. I used to do this, but don't think it's the correct solution to the problem. Instead if you make smaller functions that are less complicated, and you have a test suite to test these functions, you should reduce the amount of bugs that you have, and not need this. The only time I used something like this, other than when I was debugging, was for a school project that was anal about logging.



You're correct, this isn't very DRY. To make it dry however would be best with a decorator, and inspect.signature.
This way, you can use the standard decorator sugar, to allow for easily toggleable debugging on the functions.
This for example could be:

@log(logger, debug=False)
def fn(arg1, arg2):
    ...

@log(logger, debug=True)
def fn(arg1, arg2):
    ...


The difference being that the second turns debugging on, where the former doesn't. It won't show anything.
Doing this, you can also include default arguments and types to every function, without any extra effort.
To do this could be with:

from inspect import signature, Parameter
import logging

logger = logging.getLogger(__name__)
DEBUG = True


def log(logger_=None, debug=False):
    debug = DEBUG and debug
    if logger_ is None:
        logger_ = logger
    def wrapper(fn):
        sig = signature(fn)
        formats = {}
        for name, param in sig.parameters.items():
            fmt = '{}() {}'.format(fn.__name__, name)
            if param.annotation is not Parameter.empty:
                fmt += ': {0.__name__}'.format(param.annotation)
            if param.default is not Parameter.empty:
                fmt += '={!r}'.format(param.default)
            fmt += ' -&gt; {value}'
            formats[name] = fmt
        def inner(*args, **kwargs):
            if debug:
                ba = sig.bind(*args, **kwargs)
                ba.apply_defaults()
                for key, value in ba.arguments.items():
                    logger_.debug(formats[key].format(value=value))
            return fn(*args, **kwargs)
        return inner
    return wrapper


@log(debug=True)
def execute(system_command, **kwargs):
    process = subprocess.run(
        shlex.split(system_command),
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
        universal_newlines=True,
        **kwargs)
    if process.returncode != 0:
        logger.info(process.stdout.strip())
        logger.error(process.stderr.strip())
    return process

@log(debug=True)
def test(a: int, b:str='b'):
    return a, b

test(1)
# Displays:
# test() a: int -&gt; 1
# test() b: str='b' -&gt; b


Also I'd not be surprised if there is a somewhat large performance difference, with and without the occurrence of @log. Which should be something to keep in mind.