From dde9fdbe453925279ac3d2a6a72102f6f9ef247c Mon Sep 17 00:00:00 2001 From: Vinay Sajip Date: Tue, 5 Jun 2018 17:24:18 +0100 Subject: [PATCH] bpo-33165: Added stacklevel parameter to logging APIs. (GH-7424) --- Doc/library/logging.rst | 50 +++++++++++++------ Lib/logging/__init__.py | 13 +++-- Lib/test/test_logging.py | 31 ++++++++++++ .../2018-06-05-12-43-25.bpo-33165.9TIsVf.rst | 2 + 4 files changed, 77 insertions(+), 19 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2018-06-05-12-43-25.bpo-33165.9TIsVf.rst diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst index 2b4401ac682..774bd83f410 100644 --- a/Doc/library/logging.rst +++ b/Doc/library/logging.rst @@ -160,8 +160,8 @@ is the module's name in the Python package namespace. *msg* using the string formatting operator. (Note that this means that you can use keywords in the format string, together with a single dictionary argument.) - There are three keyword arguments in *kwargs* which are inspected: - *exc_info*, *stack_info*, and *extra*. + There are four keyword arguments in *kwargs* which are inspected: + *exc_info*, *stack_info*, *stacklevel* and *extra*. If *exc_info* does not evaluate as false, it causes exception information to be added to the logging message. If an exception tuple (in the format returned by @@ -188,11 +188,19 @@ is the module's name in the Python package namespace. This mimics the ``Traceback (most recent call last):`` which is used when displaying exception frames. - The third keyword argument is *extra* which can be used to pass a - dictionary which is used to populate the __dict__ of the LogRecord created for - the logging event with user-defined attributes. These custom attributes can then - be used as you like. For example, they could be incorporated into logged - messages. For example:: + The third optional keyword argument is *stacklevel*, which defaults to ``1``. + If greater than 1, the corresponding number of stack frames are skipped + when computing the line number and function name set in the :class:`LogRecord` + created for the logging event. This can be used in logging helpers so that + the function name, filename and line number recorded are not the information + for the helper function/method, but rather its caller. The name of this + parameter mirrors the equivalent one in the :mod:`warnings` module. + + The fourth keyword argument is *extra* which can be used to pass a + dictionary which is used to populate the __dict__ of the :class:`LogRecord` + created for the logging event with user-defined attributes. These custom + attributes can then be used as you like. For example, they could be + incorporated into logged messages. For example:: FORMAT = '%(asctime)-15s %(clientip)s %(user)-8s %(message)s' logging.basicConfig(format=FORMAT) @@ -213,9 +221,9 @@ is the module's name in the Python package namespace. If you choose to use these attributes in logged messages, you need to exercise some care. In the above example, for instance, the :class:`Formatter` has been set up with a format string which expects 'clientip' and 'user' in the attribute - dictionary of the LogRecord. If these are missing, the message will not be - logged because a string formatting exception will occur. So in this case, you - always need to pass the *extra* dictionary with these keys. + dictionary of the :class:`LogRecord`. If these are missing, the message will + not be logged because a string formatting exception will occur. So in this case, + you always need to pass the *extra* dictionary with these keys. While this might be annoying, this feature is intended for use in specialized circumstances, such as multi-threaded servers where the same code executes in @@ -230,6 +238,9 @@ is the module's name in the Python package namespace. .. versionchanged:: 3.5 The *exc_info* parameter can now accept exception instances. + .. versionadded:: 3.8 + The *stacklevel* parameter was added. + .. method:: Logger.info(msg, *args, **kwargs) @@ -300,12 +311,19 @@ is the module's name in the Python package namespace. Removes the specified handler *hdlr* from this logger. - .. method:: Logger.findCaller(stack_info=False) + .. method:: Logger.findCaller(stack_info=False, stacklevel=1) Finds the caller's source filename and line number. Returns the filename, line number, function name and stack information as a 4-element tuple. The stack information is returned as ``None`` unless *stack_info* is ``True``. + The *stacklevel* parameter is passed from code calling the :meth:`debug` + and other APIs. If greater than 1, the excess is used to skip stack frames + before determining the values to be returned. This will generally be useful + when calling logging APIs from helper/wrapper code, so that the information + in the event log refers not to the helper/wrapper code, but to the code that + calls it. + .. method:: Logger.handle(record) @@ -646,9 +664,9 @@ sophisticated criteria than levels, they get to see every record which is processed by the handler or logger they're attached to: this can be useful if you want to do things like counting how many records were processed by a particular logger or handler, or adding, changing or removing attributes in -the LogRecord being processed. Obviously changing the LogRecord needs to be -done with some care, but it does allow the injection of contextual information -into logs (see :ref:`filters-contextual`). +the :class:`LogRecord` being processed. Obviously changing the LogRecord needs +to be done with some care, but it does allow the injection of contextual +information into logs (see :ref:`filters-contextual`). .. _log-record: @@ -702,13 +720,13 @@ wire). be used. .. versionchanged:: 3.2 - The creation of a ``LogRecord`` has been made more configurable by + The creation of a :class:`LogRecord` has been made more configurable by providing a factory which is used to create the record. The factory can be set using :func:`getLogRecordFactory` and :func:`setLogRecordFactory` (see this for the factory's signature). This functionality can be used to inject your own values into a - LogRecord at creation time. You can use the following pattern:: + :class:`LogRecord` at creation time. You can use the following pattern:: old_factory = logging.getLogRecordFactory() diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index a3617b16c4d..e6c9f3280e1 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1397,7 +1397,7 @@ class Logger(Filterer): if self.isEnabledFor(level): self._log(level, msg, args, **kwargs) - def findCaller(self, stack_info=False): + def findCaller(self, stack_info=False, stacklevel=1): """ Find the stack frame of the caller so that we can note the source file name, line number and function name. @@ -1407,6 +1407,12 @@ class Logger(Filterer): #IronPython isn't run with -X:Frames. if f is not None: f = f.f_back + orig_f = f + while f and stacklevel > 1: + f = f.f_back + stacklevel -= 1 + if not f: + f = orig_f rv = "(unknown file)", 0, "(unknown function)", None while hasattr(f, "f_code"): co = f.f_code @@ -1442,7 +1448,8 @@ class Logger(Filterer): rv.__dict__[key] = extra[key] return rv - def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False): + def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False, + stacklevel=1): """ Low-level logging routine which creates a LogRecord and then calls all the handlers of this logger to handle the record. @@ -1453,7 +1460,7 @@ class Logger(Filterer): #exception on some versions of IronPython. We trap it here so that #IronPython can use logging. try: - fn, lno, func, sinfo = self.findCaller(stack_info) + fn, lno, func, sinfo = self.findCaller(stack_info, stacklevel) except ValueError: # pragma: no cover fn, lno, func = "(unknown file)", 0, "(unknown function)" else: # pragma: no cover diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index e02bb31c339..5098866237c 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4057,6 +4057,37 @@ class LoggerTest(BaseTest): self.assertEqual(len(called), 1) self.assertEqual('Stack (most recent call last):\n', called[0]) + def test_find_caller_with_stacklevel(self): + the_level = 1 + + def innermost(): + self.logger.warning('test', stacklevel=the_level) + + def inner(): + innermost() + + def outer(): + inner() + + records = self.recording.records + outer() + self.assertEqual(records[-1].funcName, 'innermost') + lineno = records[-1].lineno + the_level += 1 + outer() + self.assertEqual(records[-1].funcName, 'inner') + self.assertGreater(records[-1].lineno, lineno) + lineno = records[-1].lineno + the_level += 1 + outer() + self.assertEqual(records[-1].funcName, 'outer') + self.assertGreater(records[-1].lineno, lineno) + lineno = records[-1].lineno + the_level += 1 + outer() + self.assertEqual(records[-1].funcName, 'test_find_caller_with_stacklevel') + self.assertGreater(records[-1].lineno, lineno) + def test_make_record_with_extra_overwrite(self): name = 'my record' level = 13 diff --git a/Misc/NEWS.d/next/Library/2018-06-05-12-43-25.bpo-33165.9TIsVf.rst b/Misc/NEWS.d/next/Library/2018-06-05-12-43-25.bpo-33165.9TIsVf.rst new file mode 100644 index 00000000000..b3b2126479d --- /dev/null +++ b/Misc/NEWS.d/next/Library/2018-06-05-12-43-25.bpo-33165.9TIsVf.rst @@ -0,0 +1,2 @@ +Added a stacklevel parameter to logging calls to allow use of wrapper/helper +functions for logging APIs.