Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
richpsharp opened this issue Apr 18, 2023 · 0 comments
Assignees
Labels
bug Something isn't working
Milestone

Comments

@richpsharp
Copy link
Collaborator

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)
@richpsharp richpsharp added the bug Something isn't working label Apr 18, 2023
@richpsharp richpsharp self-assigned this Apr 18, 2023
@phargogh phargogh added this to the 1.0 milestone Jun 9, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants