Почему оператор записи в python оценивается независимо от уровня?

Question

Почему оператор логирования в python оценивается независимо от уровня?

В этом коде, например, я ожидал, что оператор «Я был выполнен» будет напечатан только тогда, когда скрипт вызывается с «-d»,но это всегда печатается!Это означает, что оператор ведения журнала может неожиданно повлиять на выполнение кода на более высоких уровнях ведения журнала.

#!/usr/bin/env python3

#import time
import argparse
import logging

logging.basicConfig(format='==> %(module)s, %(funcName)s %(message)s', level=logging.ERROR)

def logme():
    #time.sleep(10)
    print('I was executed ☠')
    return 'loggging all the things...'

if __name__ == "__main__":
    parser = argparse.ArgumentParser()
    parser.add_argument("--debug", "-d",
                         action='store_true',
                         help="Debug mode (very verbose)",
                        )

    args = parser.parse_args()
    if args.debug:
        logging.getLogger().setLevel(logging.DEBUG)

print('hello')
logging.debug('{}'.format(logme()))
print('bye')

Это ошибка в модуле ведения журнала?

Answer 1

Другой ответ скажет вам, почему logme() всегда вычисляется, но если вы действительно хотите, вы можете избежать этого, гарантируя, что logme вызывается, только если результат преобразуется в строку:

#!/usr/bin/env python3

#import time
import argparse
import logging

logging.basicConfig(format='==> %(module)s, %(funcName)s %(message)s', level=logging.ERROR)

class LazyStr:
    def __init__(self, fn, *args, **kw):
        self.fn = fn
        self.args = args
        self.kw = kw

    def __str__(self):
        return str(self.fn(*self.args, **self.kw))


def logme(n, foo):
    #time.sleep(10)
    print('I was executed, n=%d, foo=%s' % (n, foo))
    return 'loggging all the things...'

if __name__ == "__main__":
    parser = argparse.ArgumentParser()
    parser.add_argument("--debug", "-d",
                         action='store_true',
                         help="Debug mode (very verbose)",
                        )

    args = parser.parse_args()
    if args.debug:
        logging.getLogger().setLevel(logging.DEBUG)

print('hello')
logging.debug('%s', LazyStr(logme, 42, foo='bar'))
print('bye')

Объект LazyStr будет создаваться всегда, но функция logme() вызывается только в том случае, если уровень журнала равен debug.Я добавил несколько аргументов в logme, чтобы показать, как вы можете передавать аргументы.

Вывод:

$ ./t.py
hello
bye
$ ./t.py --debug
hello
I was executed, n=42, foo=bar
==> t, <module> loggging all the things...
bye

Answer 2

Это сводится к тому, как оценивается утверждение.В

logging.debug('{}'.format(logme()))

Сначала оценивается параметр, затем вызывается logger.debug.Итак, мы оцениваем '{}'.format(logme()), а затем передаем результат в logging.debug.Это эффективно

x = '{}'.format(logme())
logging.debug(x)

Давайте проверим это:

def run_later(x):
    print("function call")

def effect():
    print("parameter evaluation")

run_later(effect())
>>> parameter evaluation
>>> function call

Answer 3

Это ошибка в модуле регистрации?

Нет.Во-первых, выходные данные различны (скопировал ваш код в test.py):

PS C:\Users\Matt> python test.py
hello
I was executed.
bye

против

PS C:\Users\Matt> python test.py -d
hello
I was executed.
==> test, <module> loggging all the things...
bye

Во-вторых, если вы позвоните logme()в любой точке вашей программы "I was executed" будет распечатан на вашем экране.Это потому, что logme() содержит утверждение print('I was executed ☠').Это конкретное поведение не имеет отношения к модулю logging.Он выводится на экран, потому что вы вызываете функцию logme , когда вы делаете:

logging.debug('{}'.format(logme()))

Однако регистрация не совпадает с печать , поэтому мы видим разные результаты."I was executed" будет всегда печататься при вызове, но учтите, что "==> test, <module> loggging all the things..." было зарегистрировано только logged , когда указан флаг -d.Просто так получилось, что вы настроили свою конфигурацию регистрации на print , когда она вызывается (то есть logging.basicConfig(format='==> %(module)s, %(funcName)s %(message)s', level=logging.ERROR).Вы можете войти в файлы или делать другие вещи такого рода.

Использование строк формата с модулем logging:

Более того, если вы хотите использовать строку формата с регистратором,вы на самом деле делаете это с помощью стиля "%", но вы не на самом деле хотите предоставить строку форматирования.Вместо этого предоставьте свои форматы как аргументы.Вы сделаете это, потому что тогда подстановка формата не произойдет, если регистратор не будет вызван на соответствующем уровне .Подстановка в строку формата является относительно дорогой операцией, особенно если (например) один из ваших операторов отладки находится в цикле.Пример того, что я имею в виду (замените ваше заявление logging.debug на приведенное ниже):

# logging.debug('{}'.format(logme()))    
logging.debug('Some %s format %s string', 'first', 'second')

Тогда мы получим:

PS C:\Users\Matt> python test.py
hello
bye

и:

PS C:\Users\Matt> python test.py -d
hello
==> test, <module> some first format second string
bye

НТН.

Answer 4

Именно внутри функции ведения журнала принимается решение что-то сделать, поэтому logging.debug должен быть хотя бы введен.Ваша функция logme запускается и оценивается до этого, так что ее результат может быть передан, вот почему вы видите "Я был выполнен?"распечатаны.