natcap/taskgraph

Taskgraph can log messages in subprocesses that have a lower priority than the parent log level

Opened this issue · 0 comments

To observe this, update the test that tests for multiprocesssed logging to this and watch it fail:

    def test_multiprocessed_logging(self):
        """TaskGraph: ensure tasks can log from multiple processes."""
        logger_name = 'test.task.queuelogger'
        log_message = 'This is coming from another process'
        logger = logging.getLogger(logger_name)
        file_log_path = os.path.join(
            self.workspace_dir, 'test_multiprocessed_logging.log')
        file_handler = logging.FileHandler(file_log_path)
        file_handler.setFormatter(
            logging.Formatter(fmt=':%(processName)s:%(message)s:'))
        logger.addHandler(file_handler)

        task_graph = taskgraph.TaskGraph(self.workspace_dir, 1)
        # this first message shouldn't print because logger level is a warning
        # and _log_from_another_process is info level
        logger.setLevel(logging.WARNING)
        log_task = task_graph.add_task(
            func=_log_from_another_process,
            args=(logger_name, 'YOU WILL NOT SEE THIS'))
        log_task.join()

        # second should log because logger level is set to info
        logger.setLevel(logging.INFO)
        log_task = task_graph.add_task(
            func=_log_from_another_process,
            args=(logger_name, log_message))
        log_task.join()

        task_graph.close()
        task_graph.join()
        file_handler.flush()
        file_handler.close()

        @retrying.retry(wait_exponential_multiplier=100,
                        wait_exponential_max=1000,
                        stop_max_attempt_number=5)
        def get_name_and_message():
            with open(file_log_path, 'r') as log_file:
                message = log_file.read().rstrip()
            process_name, logged_message = re.match(
                ':([^:]*):([^:]*):', message).groups()
            return process_name, logged_message

        process_name, logged_message = get_name_and_message()
        self.assertEqual(logged_message, log_message)
        self.assertNotEqual(
            process_name, multiprocessing.current_process().name)