python - 为什么 python 日志记录日志文件不按顺序？

Question

我有方法:

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

如您所见，它们以某种奇怪的顺序分组。

有谁知道日志组是如何记录日志的？因为目前如果你从一个测试中检查我的日志的时间顺序，应该一一显示哪些方法，你会发现它们没有顺序。

Answer 1

原因是它重复了处理程序。

解决方案是添加检查处理程序是否存在:

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