Регистрация Python с несколькими модулями

Question

У меня есть различные модули, в которых я интенсивно использую логирование Python. Когда я импортирую их в основной модуль, как описано в документации по Python, и пытаюсь его запустить, я не получаю никакого вывода из логирования. Кто-нибудь понял, что происходит?

Ведение журнала вызывается в модуле, импортированном из модуля public, импортированного ниже (фрагмент кода слишком велик, чтобы его можно было разместить здесь). В следующем фрагменте кода запускается вся программа и инициализируется регистрация:

import logging
from bottle import run, debug
import public

logging.basicConfig(level=logging.DEBUG)

if __name__ == '__main__':
   logging.info('Started')
   debug(mode=True)
   run(host='localhost', port = 8080, reloader=True)
   logging.info('Finished')

Answer 1

Возможно, ваша проблема вызвана оператором import public, который звонит на logging.debug(...) или что-то подобное. Что тогда происходит, это:

1. Вы import public. В качестве побочного эффекта это вызывает, например, logging.debug или аналогичный, который автоматически вызывает basicConfig, который добавляет StreamHandler к корневому логгеру, но не меняет уровень.
2. Затем вы вызываете basicConfig, но, поскольку у корневого регистратора уже есть обработчик, он ничего не делает (как задокументировано).
3. Поскольку уровень ведения журнала по умолчанию равен WARNING, ваши вызовы info и debug не выдают результатов.

Вы действительно должны избегать побочных эффектов при импорте: например, ваш вызов basicConfig должен быть в предложении if __name__ == '__main__'. С этим public.py:

import logging

def main():
    logging.debug('Hello from public')

и это main.py:

import logging
from bottle import run, debug
import public

def main():
    logging.basicConfig(level=logging.DEBUG)
    logging.info('Started')
    debug(mode=True)
    public.main()
    run(host='localhost', port = 8080, reloader=True)
    logging.info('Finished')

if __name__ == '__main__':
    main()

Вы получите следующий вывод:

$ python main.py
INFO:root:Started
DEBUG:root:Hello from public
INFO:root:Started
DEBUG:root:Hello from public
Bottle server starting up (using WSGIRefServer())...
Listening on http://localhost:8080/
Hit Ctrl-C to quit.

^CINFO:root:Finished
$ Shutdown...
INFO:root:Finished

Из этого вы увидите, что Bottle фактически повторно запускает скрипт в отдельном процессе, который учитывает удвоение количества сообщений. Вы можете проиллюстрировать это, используя строку формата, которая показывает идентификатор процесса: если вы используете

logging.basicConfig(level=logging.DEBUG,
                    format='%(process)s %(levelname)s %(message)s')

тогда вы получите вывод, как

$ python main.py
13839 INFO Started
13839 DEBUG Hello from public
13840 INFO Started
13840 DEBUG Hello from public
Bottle server starting up (using WSGIRefServer())...
Listening on http://localhost:8080/
Hit Ctrl-C to quit.

^C13839 INFO Finished
$ Shutdown...
13840 INFO Finished

Обратите внимание, что если вы добавите оператор создания побочного эффекта к public.py, например:

logging.debug('Side-effect from public')

на уровне модуля, тогда вы вообще не получаете вывод журнала:

$ python main.py
Bottle server starting up (using WSGIRefServer())...
Listening on http://localhost:8080/
Hit Ctrl-C to quit.

^C$ Shutdown...

, который, по-видимому, подтверждает приведенный выше анализ.

Answer 2

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

import logging
import logging.handlers
from logging.config import dictConfig

logger = logging.getLogger(__name__)

DEFAULT_LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
}
def configure_logging(logfile_path):
    """
    Initialize logging defaults for Project.

    :param logfile_path: logfile used to the logfile
    :type logfile_path: string

    This function does:

    - Assign INFO and DEBUG level to logger file handler and console handler

    """
    dictConfig(DEFAULT_LOGGING)

    default_formatter = logging.Formatter(
        "[%(asctime)s] [%(levelname)s] [%(name)s] [%(funcName)s():%(lineno)s] [PID:%(process)d TID:%(thread)d] %(message)s",
        "%d/%m/%Y %H:%M:%S")

    file_handler = logging.handlers.RotatingFileHandler(logfile_path, maxBytes=10485760,backupCount=300, encoding='utf-8')
    file_handler.setLevel(logging.INFO)

    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.DEBUG)

    file_handler.setFormatter(default_formatter)
    console_handler.setFormatter(default_formatter)

    logging.root.setLevel(logging.DEBUG)
    logging.root.addHandler(file_handler)
    logging.root.addHandler(console_handler)



[31/10/2015 22:00:33] [DEBUG] [yourmodulename] [yourfunction_name():9] [PID:61314 TID:140735248744448] this is logger infomation from hello module

Я пробовал этот код в моем проекте.запустите configure_loggint (logpath) в главном.

, и вы можете использовать

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

import logging

logger = logging.getLogger(__name__)

def hello():
    logger.debug("this is logger infomation from hello module")

Answer 3

РЕДАКТИРОВАТЬ 1:

Следующее основано на неправильном понимании кода ОП (из комментария) и ложном предположении с моей стороны.Таким образом, он недействителен.

Произошла хотя бы одна ошибка с предоставленным вами кодом.debug(mode=True) неверно по двум причинам:

1. он вызывается сам по себе, как метод, который вы определили, которого у вас нет
2. mode=True - это назначение, а непроверка на равенство

Следующее, без каких-либо вспомогательных модулей и кода, запускает и регистрирует для меня:

import logging

mode = False

logging.basicConfig(level=logging.DEBUG)
logging.info('Started')
logging.debug(mode is True)
# ... other code ...
logging.info('Finished')

Запуск из командной строки:

$ python my_logger.py
INFO:root:Started
DEBUG:root:False
INFO:root:Finished