From a4ce6aa96517ecc5bd3b8ed9ea812024fa3350d0 Mon Sep 17 00:00:00 2001 From: Jack Hindmarch Date: Tue, 24 May 2022 23:38:37 +0100 Subject: [PATCH 1/7] Add taskName to logging attributes --- Doc/howto/logging.rst | 3 +++ Doc/library/logging.rst | 4 ++++ Lib/logging/__init__.py | 21 ++++++++++++++++++--- Lib/test/test_logging.py | 23 +++++++++++++++++++---- 4 files changed, 44 insertions(+), 7 deletions(-) diff --git a/Doc/howto/logging.rst b/Doc/howto/logging.rst index 93400627136e35..125bde29152270 100644 --- a/Doc/howto/logging.rst +++ b/Doc/howto/logging.rst @@ -1101,6 +1101,9 @@ need: | Current process name when using ``multiprocessing`` | Set ``logging.logMultiprocessing`` to ``False``. | | to manage multiple processes. | | +-----------------------------------------------------+---------------------------------------------------+ +| Current :class:`asyncio.Task` name when using | Set ``logging.logAsyncioTasks`` to ``False``. | +| ``asyncio``. | | ++-----------------------------------------------------+---------------------------------------------------+ Also note that the core logging module only includes the basic handlers. If you don't import :mod:`logging.handlers` and :mod:`logging.config`, they won't diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst index 3310c73656258f..7c496834960462 100644 --- a/Doc/library/logging.rst +++ b/Doc/library/logging.rst @@ -872,10 +872,14 @@ the options available to you. +----------------+-------------------------+-----------------------------------------------+ | threadName | ``%(threadName)s`` | Thread name (if available). | +----------------+-------------------------+-----------------------------------------------+ +| taskName | ``%(taskName)s`` | :class:`asyncio.Task` name (if available). | ++----------------+-------------------------+-----------------------------------------------+ .. versionchanged:: 3.1 *processName* was added. +.. versionchanged:: 3.12 + *taskname* was added. .. _logger-adapter: diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 79e4b7d09bfa43..597e3c83ff9dd1 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -64,20 +64,25 @@ raiseExceptions = True # -# If you don't want threading information in the log, set this to zero +# If you don't want threading information in the log, set this to False # logThreads = True # -# If you don't want multiprocessing information in the log, set this to zero +# If you don't want multiprocessing information in the log, set this to False # logMultiprocessing = True # -# If you don't want process information in the log, set this to zero +# If you don't want process information in the log, set this to False # logProcesses = True +# +# If you don't want asyncio task information in the log, set this to False +# +logAsyncioTasks = True + #--------------------------------------------------------------------------- # Level related stuff #--------------------------------------------------------------------------- @@ -360,6 +365,15 @@ def __init__(self, name, level, pathname, lineno, self.process = os.getpid() else: self.process = None + if logAsyncioTasks: + asyncio = sys.modules.get('asyncio') + if asyncio is not None: + try: + self.taskName = asyncio.current_task().get_name() + except RuntimeError as e: + self.taskName = None + else: + self.taskName = None def __repr__(self): return ''%(self.name, self.levelno, @@ -566,6 +580,7 @@ class Formatter(object): (typically at application startup time) %(thread)d Thread ID (if available) %(threadName)s Thread name (if available) + %(taskName)s Task name (if available) %(process)d Process ID (if available) %(message)s The result of record.getMessage(), computed just as the record is emitted diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index fd562322a76372..3377b9fbb4b463 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -18,7 +18,7 @@ Copyright (C) 2001-2021 Vinay Sajip. All Rights Reserved. """ - +import asyncio import logging import logging.handlers import logging.config @@ -4552,12 +4552,15 @@ def test_multiprocessing(self): import multiprocessing def test_optional(self): - r = logging.makeLogRecord({}) + NONE = self.assertIsNone NOT_NONE = self.assertIsNotNone + + r = logging.makeLogRecord({}) NOT_NONE(r.thread) NOT_NONE(r.threadName) NOT_NONE(r.process) NOT_NONE(r.processName) + NONE(r.taskName) log_threads = logging.logThreads log_processes = logging.logProcesses log_multiprocessing = logging.logMultiprocessing @@ -4566,16 +4569,28 @@ def test_optional(self): logging.logProcesses = False logging.logMultiprocessing = False r = logging.makeLogRecord({}) - NONE = self.assertIsNone + NONE(r.thread) NONE(r.threadName) NONE(r.process) NONE(r.processName) + NONE(r.taskName) finally: logging.logThreads = log_threads logging.logProcesses = log_processes logging.logMultiprocessing = log_multiprocessing + def test_taskName(self): + async def log_record(assertion): + r = logging.makeLogRecord({}) + assertion(r.taskName) + + logging.logAsyncioTasks = True + asyncio.run(log_record(self.assertIsNotNone)) + logging.logAsyncioTasks = False + asyncio.run(log_record(self.assertIsNone)) + + class BasicConfigTest(unittest.TestCase): """Test suite for logging.basicConfig.""" @@ -5644,7 +5659,7 @@ def test__all__(self): 'logThreads', 'logMultiprocessing', 'logProcesses', 'currentframe', 'PercentStyle', 'StrFormatStyle', 'StringTemplateStyle', 'Filterer', 'PlaceHolder', 'Manager', 'RootLogger', 'root', - 'threading'} + 'threading', 'logAsyncioTasks'} support.check__all__(self, logging, not_exported=not_exported) From 1b99b1de9c45948ad47cd245fea7e0dbd9be6b04 Mon Sep 17 00:00:00 2001 From: Jack Hindmarch Date: Wed, 25 May 2022 00:58:52 +0100 Subject: [PATCH 2/7] Make taskName a @property of LogRecord. Teardown after test_taskName. --- Lib/logging/__init__.py | 11 +++++++---- Lib/test/test_logging.py | 12 ++++++++---- 2 files changed, 15 insertions(+), 8 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 597e3c83ff9dd1..b26d0f99e39177 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -365,15 +365,18 @@ def __init__(self, name, level, pathname, lineno, self.process = os.getpid() else: self.process = None + + @property + def taskName(self): if logAsyncioTasks: asyncio = sys.modules.get('asyncio') if asyncio is not None: try: - self.taskName = asyncio.current_task().get_name() - except RuntimeError as e: - self.taskName = None + return asyncio.current_task().get_name() + except Exception: + return None else: - self.taskName = None + return None def __repr__(self): return ''%(self.name, self.levelno, diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 3377b9fbb4b463..694dd73ada5d9c 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4585,10 +4585,14 @@ async def log_record(assertion): r = logging.makeLogRecord({}) assertion(r.taskName) - logging.logAsyncioTasks = True - asyncio.run(log_record(self.assertIsNotNone)) - logging.logAsyncioTasks = False - asyncio.run(log_record(self.assertIsNone)) + try: + with asyncio.Runner() as runner: + logging.logAsyncioTasks = True + runner.run(log_record(self.assertIsNotNone)) + logging.logAsyncioTasks = False + runner.run(log_record(self.assertIsNone)) + finally: + asyncio.set_event_loop_policy(None) class BasicConfigTest(unittest.TestCase): From c099bcbf189bd75abf4addb1817ecac54c58adf9 Mon Sep 17 00:00:00 2001 From: "blurb-it[bot]" <43283697+blurb-it[bot]@users.noreply.github.com> Date: Wed, 25 May 2022 00:21:29 +0000 Subject: [PATCH 3/7] =?UTF-8?q?=F0=9F=93=9C=F0=9F=A4=96=20Added=20by=20blu?= =?UTF-8?q?rb=5Fit.?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst | 1 + 1 file changed, 1 insertion(+) create mode 100644 Misc/NEWS.d/next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst diff --git a/Misc/NEWS.d/next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst b/Misc/NEWS.d/next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst new file mode 100644 index 00000000000000..b5e4063b6e0576 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst @@ -0,0 +1 @@ +Added ``%(taskName)s`` attribute to :mod:`logging` module for use with :mod:`asyncio` tasks. From 354dec9f3235b559deb347a546e69cf58ba33864 Mon Sep 17 00:00:00 2001 From: Jack Hindmarch Date: Wed, 25 May 2022 01:52:31 +0100 Subject: [PATCH 4/7] Revert taskName @property change --- Lib/logging/__init__.py | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index b26d0f99e39177..7f561da2968767 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -365,18 +365,15 @@ def __init__(self, name, level, pathname, lineno, self.process = os.getpid() else: self.process = None - - @property - def taskName(self): if logAsyncioTasks: asyncio = sys.modules.get('asyncio') if asyncio is not None: try: - return asyncio.current_task().get_name() + self.taskName = asyncio.current_task().get_name() except Exception: - return None + self.taskName = None else: - return None + self.taskName = None def __repr__(self): return ''%(self.name, self.levelno, From 3c7270367c33ebda02c76315f79a6569416c5a98 Mon Sep 17 00:00:00 2001 From: Jack Hindmarch Date: Wed, 25 May 2022 02:26:11 +0100 Subject: [PATCH 5/7] Adding a test for formatting of taskName attribute --- Lib/test/test_logging.py | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 694dd73ada5d9c..d727e6efc85472 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4872,6 +4872,30 @@ def dummy_handle_error(record): # didn't write anything due to the encoding error self.assertEqual(data, r'') + def test_log_taskName(self): + async def log_record(): + logging.warning('hello world') + + try: + encoding = 'utf-8' + logging.basicConfig(filename='test.log', errors='strict', encoding=encoding, + format='%(taskName)s - %(message)s', level=logging.WARNING) + + self.assertEqual(len(logging.root.handlers), 1) + handler = logging.root.handlers[0] + self.assertIsInstance(handler, logging.FileHandler) + + with asyncio.Runner(debug=True) as runner: + logging.logAsyncioTasks = True + runner.run(log_record()) + finally: + asyncio.set_event_loop_policy(None) + handler.close() + with open('test.log', encoding='utf-8') as f: + data = f.read().strip() + os.remove('test.log') + self.assertEqual('Task-1 - hello world', data) + def _test_log(self, method, level=None): # logging.root has no handlers so basicConfig should be called From 57abfdc81438c1f34dee87705bf290946dd82169 Mon Sep 17 00:00:00 2001 From: Jack Hindmarch Date: Wed, 25 May 2022 09:30:06 +0100 Subject: [PATCH 6/7] Added test for path where `asyncio` is not imported. Minor refactor in LogRecord.__init__ as per suggestions. Fixed typo in docs. --- Doc/library/logging.rst | 2 +- Lib/logging/__init__.py | 8 ++++---- Lib/test/test_logging.py | 29 ++++++++++++++++++++++------- 3 files changed, 27 insertions(+), 12 deletions(-) diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst index 7c496834960462..ac86bc8077ef74 100644 --- a/Doc/library/logging.rst +++ b/Doc/library/logging.rst @@ -879,7 +879,7 @@ the options available to you. *processName* was added. .. versionchanged:: 3.12 - *taskname* was added. + *taskName* was added. .. _logger-adapter: diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 7f561da2968767..e7636e18bec4ab 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -365,15 +365,15 @@ def __init__(self, name, level, pathname, lineno, self.process = os.getpid() else: self.process = None + + self.taskName = None if logAsyncioTasks: asyncio = sys.modules.get('asyncio') - if asyncio is not None: + if asyncio: try: self.taskName = asyncio.current_task().get_name() except Exception: - self.taskName = None - else: - self.taskName = None + pass def __repr__(self): return ''%(self.name, self.levelno, diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index d727e6efc85472..67a007ae190738 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -18,7 +18,6 @@ Copyright (C) 2001-2021 Vinay Sajip. All Rights Reserved. """ -import asyncio import logging import logging.handlers import logging.config @@ -50,6 +49,7 @@ from test.support.logging_helper import TestHandler import textwrap import threading +import asyncio import time import unittest import warnings @@ -4564,10 +4564,12 @@ def test_optional(self): log_threads = logging.logThreads log_processes = logging.logProcesses log_multiprocessing = logging.logMultiprocessing + log_asyncio_tasks = logging.logAsyncioTasks try: logging.logThreads = False logging.logProcesses = False logging.logMultiprocessing = False + logging.logAsyncioTasks = False r = logging.makeLogRecord({}) NONE(r.thread) @@ -4579,18 +4581,31 @@ def test_optional(self): logging.logThreads = log_threads logging.logProcesses = log_processes logging.logMultiprocessing = log_multiprocessing + logging.logAsyncioTasks = log_asyncio_tasks - def test_taskName(self): - async def log_record(assertion): - r = logging.makeLogRecord({}) - assertion(r.taskName) + async def _make_record_async(self, assertion): + r = logging.makeLogRecord({}) + assertion(r.taskName) + def test_taskName_with_asyncio_imported(self): try: + make_record = self._make_record_async with asyncio.Runner() as runner: logging.logAsyncioTasks = True - runner.run(log_record(self.assertIsNotNone)) + runner.run(make_record(self.assertIsNotNone)) + logging.logAsyncioTasks = False + runner.run(make_record(self.assertIsNone)) + finally: + asyncio.set_event_loop_policy(None) + + def test_taskName_without_asyncio_imported(self): + try: + make_record = self._make_record_async + with asyncio.Runner() as runner, support.swap_item(sys.modules, 'asyncio', None): + logging.logAsyncioTasks = True + runner.run(make_record(self.assertIsNone)) logging.logAsyncioTasks = False - runner.run(log_record(self.assertIsNone)) + runner.run(make_record(self.assertIsNone)) finally: asyncio.set_event_loop_policy(None) From 12d2f45629a3d491568e716c2d6983d09b5508a0 Mon Sep 17 00:00:00 2001 From: Jack Hindmarch Date: Wed, 25 May 2022 16:22:35 +0100 Subject: [PATCH 7/7] Changing taskName assertion to regex in case numbering becomes inconsistent. Removed percent styling from News entry. --- Lib/test/test_logging.py | 2 +- .../next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 67a007ae190738..07804a2686a140 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4909,7 +4909,7 @@ async def log_record(): with open('test.log', encoding='utf-8') as f: data = f.read().strip() os.remove('test.log') - self.assertEqual('Task-1 - hello world', data) + self.assertRegex(data, r'Task-\d+ - hello world') def _test_log(self, method, level=None): diff --git a/Misc/NEWS.d/next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst b/Misc/NEWS.d/next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst index b5e4063b6e0576..f9f93767ed173d 100644 --- a/Misc/NEWS.d/next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst +++ b/Misc/NEWS.d/next/Library/2022-05-25-00-21-28.gh-issue-91513.9VyCT4.rst @@ -1 +1 @@ -Added ``%(taskName)s`` attribute to :mod:`logging` module for use with :mod:`asyncio` tasks. +Added ``taskName`` attribute to :mod:`logging` module for use with :mod:`asyncio` tasks.