Skip to content

gh-91513: Add 'asyncio' taskName to logging LogRecord attributes. (GH-93193) #93193

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

Merged
merged 10 commits into from
May 26, 2022
3 changes: 3 additions & 0 deletions Doc/howto/logging.rst
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 4 additions & 0 deletions Doc/library/logging.rst
Original file line number Diff line number Diff line change
Expand Up @@ -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:

Expand Down
21 changes: 18 additions & 3 deletions Lib/logging/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
#---------------------------------------------------------------------------
Expand Down Expand Up @@ -361,6 +366,15 @@ def __init__(self, name, level, pathname, lineno,
else:
self.process = None

self.taskName = None
if logAsyncioTasks:
asyncio = sys.modules.get('asyncio')
if asyncio:
try:
self.taskName = asyncio.current_task().get_name()
except Exception:
pass

def __repr__(self):
return '<LogRecord: %s, %s, %s, %s, "%s">'%(self.name, self.levelno,
self.pathname, self.lineno, self.msg)
Expand Down Expand Up @@ -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
Expand Down
66 changes: 62 additions & 4 deletions Lib/test/test_logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,6 @@

Copyright (C) 2001-2021 Vinay Sajip. All Rights Reserved.
"""

import logging
import logging.handlers
import logging.config
Expand Down Expand Up @@ -50,6 +49,7 @@
from test.support.logging_helper import TestHandler
import textwrap
import threading
import asyncio
import time
import unittest
import warnings
Expand Down Expand Up @@ -4552,29 +4552,63 @@ 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
log_asyncio_tasks = logging.logAsyncioTasks
try:
logging.logThreads = False
logging.logProcesses = False
logging.logMultiprocessing = False
logging.logAsyncioTasks = 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
logging.logAsyncioTasks = log_asyncio_tasks

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(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(make_record(self.assertIsNone))
finally:
asyncio.set_event_loop_policy(None)
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tearing down, else we end up with:

== Tests result: SUCCESS ==

406 tests OK.

1 test altered the execution environment:
    test_logging

29 tests skipped:
    test_curses test_dbm_gnu test_devpoll test_epoll test_gdb
    test_idle test_ioctl test_launcher test_msilib
    test_multiprocessing_fork test_ossaudiodev test_smtpnet
    test_socketserver test_spwd test_ssl test_startfile test_tcl
    test_tix test_tk test_ttk_guionly test_ttk_textonly test_turtle
    test_urllib2net test_urllibnet test_winconsoleio test_winreg
    test_winsound test_xmlrpc_net test_zipfile64



class BasicConfigTest(unittest.TestCase):

Expand Down Expand Up @@ -4853,6 +4887,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.assertRegex(data, r'Task-\d+ - hello world')
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

handler = None
try:
    ...
finally:
    asyncio.set_event_loop_policy(None)
    if handler is not None:
        handler.close()
    if os.path.exists('test.log'):
        ....

to prevent sub-exceptions in the finally block if there is an exception/assertion error in the try block ?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would have put the self.assertRegex(data, r'Task-\d+ - hello world') at the end of the try block too.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, that's a fair point. This test probably needs tidying up a little.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was following the pattern of the encoding tests above this one.
Happy to raise a new PR and fix it up along with the others.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's OK, I've just done it. I'm working on logging tests for something else.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's #93265.



def _test_log(self, method, level=None):
# logging.root has no handlers so basicConfig should be called
Expand Down Expand Up @@ -5644,7 +5702,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)


Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Added ``taskName`` attribute to :mod:`logging` module for use with :mod:`asyncio` tasks.