jeudi 15 novembre 2018

Why python logging logs files not in order?

I have method:

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

I'm using it in my automation testing framework. I've called method in methods of pages. But after running a test I see that log file is not in order.

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

as you can see, they are grouped in some strange order.

Does anyone know how logging groups logs? Cause currently if you check time order of my logs from one test, which methods should be displayed one by one, you can see that they are not in order.

Aucun commentaire:

Enregistrer un commentaire