Пример кода модуля регистрации повторяет сообщения n-раз-каждый вызов - PullRequest
0 голосов
/ 12 мая 2018

Я удивлен выводом из модуля журналирования Python.Я написал Python.org How-To для ведения журнала .Когда я запускаю пример кода, возникает много (запутанного) дублирования.

StreamHandler дублирует сообщения журнала, по одному для каждой перезагрузки файла в iPython с помощью волшебства %run

In [4]: %run main.py
2018-05-11 2127:33 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:33 - ERROR - 4. Here is an error
2018-05-11 2127:33 - CRITICAL - 5. This is f-ing critical!
[...]
In [7]: %run main.py
2018-05-11 2127:38 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:38 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:38 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:38 - ERROR - 4. Here is an error
2018-05-11 2127:38 - ERROR - 4. Here is an error
2018-05-11 2127:38 - ERROR - 4. Here is an error
2018-05-11 2127:38 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2127:38 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2127:38 - CRITICAL - 5. This is f-ing critical!

Я добавил FileHandler:

fh = logging.FileHandler("app.log")
fh.setLevel(logging.DEBUG)
fh.setFormatter(formatter)
logger.addHandler(fh)

Это также дублирует:

xtian@spaceghost> cat app.log
2018-05-11 2159:24 - WARNING - 3. This is a warning!
2018-05-11 2159:24 - ERROR - 4. This is an error
2018-05-11 2159:24 - CRITICAL - 5. This is fucking critical!
[...]
2018-05-11 2201:00 - WARNING - 3. This is a warning, yous!
2018-05-11 2201:00 - WARNING - 3. This is a warning, yous!
2018-05-11 2201:00 - WARNING - 3. This is a warning, yous!
2018-05-11 2201:00 - ERROR - 4. Here is an error.
2018-05-11 2201:00 - ERROR - 4. Here is an error.
2018-05-11 2201:00 - ERROR - 4. Here is an error.
2018-05-11 2201:00 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2201:00 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2201:00 - CRITICAL - 5. This is f-ing critical!

Я также последовал советам других сообщений и добавил эти строки непосредственно перед вызовом сообщения:

# propagation fix
logger.propagate = False

Результаты одинаковы.


При настройке на публикацию я вижу похожий вопрос:

Что может заставить модуль журналирования регистрировать записьнесколько раз?

Но все это отладка для оригинального пользовательского кода OP.Моя проблема связана с примером кода, который, как я ожидаю, должен предупредить или лучше объяснить, что происходит.

В документах сказано:

Примечание.Если вы присоедините обработчик к логгеру и одному или нескольким его предкам, он может отправлять одну и ту же запись несколько раз.В общем случае вам не нужно подключать обработчик к нескольким регистраторам - если вы просто присоедините его к соответствующему регистратору, который является самым высоким в иерархии регистраторов, то он увидит все события, записанные всеми регистраторами-потомками, при условии, что они распространяются.для параметра оставлено значение True.Распространенный сценарий - присоединить обработчики только к корневому логгеру и позволить распространению позаботиться обо всем остальном.

Полный тестовый файл main.py можно посмотреть здесь , чтобыпосмотрите, есть ли у меня 'более одного регистратора' .

import logging

# Root Logger
logger = logging.getLogger(__name__)

# Console handler
ch = logging.StreamHandler()
ch.setLevel(logging.WARNING)

# Formatter
formatter = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(message)s' , datefmt='%Y-%m-%d %H%M:%S', style='%')

# Add formatter to Console handler ch
ch.setFormatter(formatter)

# Add ch to logger
logger.addHandler(ch)

# Text File handler
fh = logging.FileHandler("app.log")
fh.setLevel(logging.DEBUG)
fh.setFormatter(formatter)
logger.addHandler(fh)

# propagation fix
logger.propagate = False

# Example Application code
logger.debug("1. This is a debug message.")
logger.info("2. This is an info message.")
logger.warning('3. This is a warning!')
logger.error('4. This is an error')
logger.critical("5. This is fucking critical!")

1 Ответ

0 голосов
/ 12 мая 2018

logger, возвращаемое logging.getLogger(__name__), является одним и тем же регистратором при каждом выполнении %run main.py. Но

ch = logging.StreamHandler()

каждый раз создает новый StreamHandler, который затем добавляется к logger:

logger.addHandler(ch)

Таким образом, при последующих запусках %run main.py, logger имеет несколько обработчиков прикрепленный к нему, и запись обрабатывается каждым обработчиком.


In [5]: %run main.py
2018-05-11 2251:17 - WARNING - 3. This is a warning!
2018-05-11 2251:17 - ERROR - 4. This is an error
2018-05-11 2251:17 - CRITICAL - 5. This is fucking critical!

In [6]: logger
Out[6]: <logging.Logger at 0x7f5d0152fe10>

При первом запуске %run main.py к logger прикрепляются два обработчика:

In [7]: logger.handlers
Out[12]: 
[<logging.StreamHandler at 0x7f5d0152fdd8>,
 <logging.FileHandler at 0x7f5d014c40f0>]

In [13]: %run main.py
2018-05-11 2251:44 - WARNING - 3. This is a warning!
2018-05-11 2251:44 - WARNING - 3. This is a warning!
2018-05-11 2251:44 - ERROR - 4. This is an error
2018-05-11 2251:44 - ERROR - 4. This is an error
2018-05-11 2251:44 - CRITICAL - 5. This is fucking critical!
2018-05-11 2251:44 - CRITICAL - 5. This is fucking critical!

Во второй раз теперь есть четыре обработчика:

In [14]: logger.handlers
Out[14]: 
[<logging.StreamHandler at 0x7f5d0152fdd8>,
 <logging.FileHandler at 0x7f5d014c40f0>,
 <logging.StreamHandler at 0x7f5d014c4668>,
 <logging.FileHandler at 0x7f5d014c4550>]

In [15]: logger
Out[15]: <logging.Logger at 0x7f5d0152fe10> 

Чтобы избежать дублирования, вы можете звонить logger.removeHandler между %run вызовами:

In [29]: for handler in logger.handlers: logger.removeHandler(handler)

In [30]: %run main.py
2018-05-11 2257:30 - WARNING - 3. This is a warning!
2018-05-11 2257:30 - ERROR - 4. This is an error
2018-05-11 2257:30 - CRITICAL - 5. This is fucking critical!

или измените main.py, чтобы новые обработчики не подключались при каждом вызове %run. Например, вы можете настроить logger, используя logging.config.dictConfig:

import logging
import logging.config

# Modified using https://stackoverflow.com/a/7507842/190597 as a template
logging_config = { 
    'version': 1,
    'formatters': { 
        'standard': { 
            'format': '%(asctime)s - %(levelname)s - %(message)s'
        },
    },
    'handlers': { 
        'stream': { 
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
        },
        'file': { 
            'level': 'DEBUG',
            'formatter': 'standard',
            'class': 'logging.FileHandler',
            'filename': 'app.log'
        },
    },
    'loggers': { 
        __name__: { 
            'handlers': ['stream', 'file'],
            'level': 'WARN',
            'propagate': False
        },
    } 
}
logging.config.dictConfig(logging_config)
logger = logging.getLogger(__name__)

# Example Application code
logger.debug("1. This is a debug message.")
logger.info("2. This is an info message.")
logger.warning('3. This is a warning!')
logger.error('4. This is an error')
logger.critical("5. This is fucking critical!")

Используя этот код, %run main.py каждый раз выдает один и тот же вывод.

...