Блог

Я пытаюсь использовать функцию печати до и после использования двух объектов logger, которые будут выводить выходные данные на консоль. Дело в том, что я получаю действительно беспорядочный вывод, который не в ожидаемом порядке.

Я попытался изменить print () на logger_object.info () и это работает так, как задумано.

Полный код с неожиданным выводом :

 import logging

# Create logger objects and set  level
loggerA = logging.getLogger()
loggerA.setLevel(logging.DEBUG)

loggerB = logging.getLogger()
loggerB.setLevel(logging.DEBUG)

# Set log output format
log_format = logging.Formatter('%(asctime)s - %(levelname)s - %(name)s - %(message)s', datefmt='%m/%d/%Y - %I:%M:%S %p')

# Create a console stream handler
stream_handler = logging.StreamHandler()
stream_handler.setFormatter(log_format)

# Add handlers to the loggers
loggerA.addHandler(stream_handler)
loggerB.addHandler(stream_handler)


def main():
    for i in range(10):
        print('Starting loop number {}'.format(i))
        loggerA.info("loop number {}".format(i))
        loggerB.info("loop number {}".format(i))
        print('Finished loop number {}'.format(i))

if __name__ == '__main__':
    main()
  

Добавление объекта loggerC для замены print() на loggerC.info () :

 ...
loggerC = logging.getLogger()
loggerC.setLevel(logging.DEBUG)
...
def main():
    for i in range(10):
        loggerC('Starting loop number {}'.format(i))
        loggerA.info("loop number {}".format(i))
        loggerB.info("loop number {}".format(i))
        loggerC('Finished loop number {}'.format(i))
...
  

Первый случай использования неожиданного вывода print() — это :

 04/06/2019 - 10:10:34 AM - INFO - loggerA - loop number 1
Starting loop number 1
04/06/2019 - 10:10:34 AM - INFO - loggerB - loop number 1
04/06/2019 - 10:10:34 AM - INFO - loggerA - loop number 2
04/06/2019 - 10:10:34 AM - INFO - loggerB - loop number 2
Finished loop number 1
Starting loop number 2
Finished loop number 2
Starting loop number 3
Finished loop number 3
04/06/2019 - 10:10:34 AM - INFO - loggerA - loop number 3
04/06/2019 - 10:10:34 AM - INFO - loggerB - loop number 3
  

Второй случай с использованием loggerC.info () вместо print (), который является ожидаемым результатом :

 04/06/2019 - 10:12:21 AM - INFO - loggerC - Starting loop number 1
04/06/2019 - 10:12:21 AM - INFO - loggerA - loop number 1
04/06/2019 - 10:12:21 AM - INFO - loggerB - loop number 1
04/06/2019 - 10:12:21 AM - INFO - loggerC - Finished loop number 1
04/06/2019 - 10:12:21 AM - INFO - loggerC - Starting loop number 2
04/06/2019 - 10:12:21 AM - INFO - loggerA - loop number 2
04/06/2019 - 10:12:21 AM - INFO - loggerB - loop number 2
04/06/2019 - 10:12:21 AM - INFO - loggerC - Finished loop number 2
04/06/2019 - 10:12:21 AM - INFO - loggerC - Starting loop number 3
04/06/2019 - 10:12:21 AM - INFO - loggerA - loop number 3
04/06/2019 - 10:12:21 AM - INFO - loggerB - loop number 3
04/06/2019 - 10:12:21 AM - INFO - loggerC - Finished loop number 3
  

Ваша проблема, вероятно, связана со стандартными потоками. По умолчанию print использует std::out и logger.info использует std::err . Оба потока привязаны к вашему терминалу, но у них могут быть разные flush обновления или триггеры.

Вот почему ваши выходные данные смешаны, функции записывают в разные потоки, и они по-разному выводятся на терминал, что приводит к очевидному противоречивому результату.

Измените ваш первый код, чтобы заставить logger.info использовать один и тот же поток, чем print решите вашу проблему:

 import sys
stream_handler = logging.StreamHandler(sys.stdout)
  

Теперь он возвращает правильный вывод:

 -- Starting loop number 0
04/06/2019 - 07:41:34 AM - INFO - root - loop number 0
04/06/2019 - 07:41:34 AM - INFO - root - loop number 0
-- Finished loop number 0
-- Starting loop number 1
04/06/2019 - 07:41:34 AM - INFO - root - loop number 1
04/06/2019 - 07:41:34 AM - INFO - root - loop number 1
-- Finished loop number 1
-- Starting loop number 2
04/06/2019 - 07:41:34 AM - INFO - root - loop number 2
04/06/2019 - 07:41:34 AM - INFO - root - loop number 2
-- Finished loop number 2
-- Starting loop number 3
04/06/2019 - 07:41:34 AM - INFO - root - loop number 3
04/06/2019 - 07:41:34 AM - INFO - root - loop number 3
-- Finished loop number 3
  

Поскольку оба print и logger.info передают один и тот же поток в правильном порядке всякий раз, когда он сбрасывается на ваш терминал, результат правильный.

Вы также можете сохранить разные потоки и принудительно std::out сбрасывать поток явно:

 def main():
    for i in range(10):
        print('-- Starting loop number {}'.format(i))
        # Force std::out stream (fed by print) to be flushed to the terminal
        # before logger feeds std::err and also flushes
        sys.stdout.flush() 
        loggerA.info("loop number {}".format(i))
        loggerB.info("loop number {}".format(i))
        print('-- Finished loop number {}'.format(i))
        sys.stdout.flush()
  

Эта вторая версия также выдает желаемый результат.

Также помните, что это logger по определению потокобезопасно, но print таковым не является. Если вы собираетесь создать модуль с использованием thread, используйте только logger для отслеживания выполнения.