Почему Python ведет логи файлов не в порядке? - PullRequest
Новая
       4

Почему Python ведет логи файлов не в порядке?

0 голосов
/ 15 ноября 2018

У меня есть метод: 

def custom_logger():
    logger_name = inspect.stack()[1][3]
    logger = logging.getLogger(logger_name)
    logger.setLevel(logging.DEBUG)
    console_handler = logging.StreamHandler()
    file_handler = logging.FileHandler(os.path.join(os.path.pardir, os.path.pardir, os.path.pardir, "resources", "automation.log"), mode='w')
    file_handler.setLevel(logging.DEBUG)
    formatter = logging.Formatter('%(asctime)s - %(name)s - %(funcName)s - %(levelname)s: %(message)s',
                                  datefmt='%m/%d/%Y %I:%M:%S %p')
    file_handler.setFormatter(formatter)
    console_handler.setLevel(logging.WARNING)
    console_handler.setFormatter(formatter)
    logger.addHandler(file_handler)
    logger.addHandler(console_handler)
    return logger

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

1/15/2018 11:13:34 AM - base.class.__init__ - get_link_ssh - INFO: Parsing link for ssh
11/15/2018 11:13:34 AM - base.class.__init__ - get_username - INFO: Parsing username 
11/15/2018 11:14:07 AM - base.class.__init__ - get_link_ssh - INFO: Parsing link for ssh
11/15/2018 11:14:07 AM - base.class.__init__ - get_username_enterprise - INFO: Parsing username
11/15/2018 11:14:36 AM - base.class.__init__ - get_link_ent_ssh - INFO: Parsing link for ssh 
11/15/2018 11:14:36 AM - base.class.__init__ - get_username_enterprise - INFO: Parsing username 
.object_init - get_username - INFO: Parsing username
11/15/2018 11:13:34 AM - add_upd_del_test.object_init - get_link_ssh - INFO: Parsing link for ssh
11/15/2018 11:13:34 AM - add_upd_del_test.object_init - get_username - INFO: Parsing username 
11/15/2018 11:13:34 AM - add_upd_del_test.object_init - ssh_perform - INFO: Performing ssh command
11/15/2018 11:13:54 AM - add_upd_del_test.object_init - wait_for_element - INFO: Creating 10 seconds wait for element at locator:
11/15/2018 11:14:02 AM - add_upd_del_test.object_init - wait_for_element - INFO: Creating 10 seconds wait for element at locator:
11/15/2018 11:14:04 AM - add_upd_del_test.object_init - get_link_ssh - INFO: Parsing link for ssh
11/15/2018 11:14:04 AM - add_upd_del_test.object_init - get_username - INFO: Parsing username 
11/15/2018 11:14:05 AM - add_upd_del_test.object_init - get_link_ssh - INFO: Parsing link for ssh
11/15/2018 11:14:05 AM - add_upd_del_test.object_init - get_username - INFO: Parsing username 
11/15/2018 11:14:06 AM - add_upd_del_test.object_init - get_link_ssh - INFO: Parsing link for ssh
11/15/2018 11:14:06 AM - add_upd_del_test.object_init - get_username - INFO: Parsing username 
11/15/2018 11:14:07 AM - add_upd_del_test.object_init - ssh_perform - INFO: Performing ssh command
11/15/2018 11:14:16 AM - add_upd_del_test.object_init - get_link - INFO: Parsing link 
11/15/2018 11:14:27 AM - add_upd_del_test.object_init - wait_for_element - INFO: Creating 10 seconds wait for element at locator: 
11/15/2018 11:14:34 AM - add_upd_del_test.object_init - wait_for_element - INFO: Creating 10 seconds wait for element at locator: 
11/15/2018 11:14:36 AM - add_upd_del_test.object_init - ssh_perform - INFO: Performing ssh command: 
11/15/2018 11:14:57 AM - add_upd_del_test.object_init - get_link - INFO: Parsing link for ssh 
11/15/2018 11:14:57 AM - add_upd_del_test.object_init - get_username - INFO: Parsing username 
t.browser_init - ssh_perform - INFO: Performing ssh command: 
11/15/2018 11:14:06 AM - add_upd_del_test.browser_init - ssh_perform - INFO: Performing ssh command:
11/15/2018 11:14:07 AM - add_upd_del_test.browser_init - add - INFO: Adding
11/15/2018 11:14:16 AM - add_upd_del_test.browser_init - INFO: Opening 
11/15/2018 11:14:16 AM - add_upd_del_test.browser_init - get_window_handle - INFO: Getting handle of current window
11/15/2018 11:14:26 AM - add_upd_del_test.browser_init - click_new_button - INFO: Clicking on 'New' button for creating new 
11/15/2018 11:14:26 AM - add_upd_del_test.browser_init - click_test - INFO: Clicking on 
11/15/2018 11:14:27 AM - add_upd_del_test.browser_init - switch_to_new_window - INFO: Switching to new window
11/15/2018 11:14:27 AM - add_upd_del_test.browser_init - text_to_field - INFO: Entering text field:
11/15/2018 11:14:29 AM - add_upd_del_test.browser_init - restart_run_all - INFO: Restart kernel and running all cells
11/15/2018 11:14:33 AM - add_upd_del_test.browser_init - verify_output_requests_version - INFO: Verifying that requests version is displayed after running corresponding code
11/15/2018 11:14:34 AM - add_upd_del_test.browser_init - get_name_notebook - INFO: Getting name of 
11/15/2018 11:14:34 AM - add_upd_del_test.browser_init - click_save_button - INFO: Clicking on save button
11/15/2018 11:14:35 AM - add_upd_del_test.browser_init - click_checkbox - INFO: Clicking on checkbox 
11/15/2018 11:14:35 AM - add_upd_del_test.browser_init - delete_notebook - INFO: Deleting notebook
11/15/2018 11:14:36 AM - add_upd_del_test.browser_init - del_kernel - INFO: Deleting 
11/15/2018 11:14:49 AM - add_upd_del_test.browser_init - click_new_button - INFO: Clicking on 'New' button 
11/15/2018 11:14:49 AM - add_upd_del_test.browser_init - array_size - INFO: Finding elements with new name
11/15/2018 11:14:54 AM - add_upd_del_test.browser_init - click_logout_button - INFO: Clicking on logout button
11/15/2018 11:14:55 AM - add_upd_del_test.browser_init - located_on_login_page - INFO: Verifying that  button is displayed and we are located on login page
11/15/2018 11:14:57 AM - add_upd_del_test.browser_init - ssh_perform - INFO: Performing ssh command

Как вы можете видеть, они сгруппированы в каком-то странном порядке.

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

1 Ответ

0 голосов
/ 19 ноября 2018

Причина была в том, что он дублировал обработчики.

Решением было добавить проверку наличия обработчиков: 

def custom_logger():
    logger_name = inspect.stack()[4].function
    logger = logging.getLogger(logger_name)
    logger.setLevel(logging.DEBUG)

    if not logger.handlers:         # THIS LINE WAS ADDED.
        console_handler = logging.StreamHandler()
        console_handler.setLevel(logging.WARNING)
        formatter = logging.Formatter('%(asctime)s - %(name)s - %(funcName)s - %(levelname)s: %(message)s',
                                      datefmt='%m/%d/%Y %I:%M:%S %p')
        console_handler.setFormatter(formatter)
        logger.addHandler(console_handler)

        file_handler = logging.FileHandler(os.path.join(os.path.pardir, os.path.pardir, os.path.pardir, "resources", "automation.log"), mode='a')
        file_handler.setLevel(logging.DEBUG)
        file_handler.setFormatter(formatter)
        logger.addHandler(file_handler)

    return logger
...