bpo-45171: Fix stacklevel handling in logging. (GH-28287) #28287

joukewitteveen · 2021-09-11T13:25:57Z

I identified a few problems with the stacklevel handling code in the logging module:

currentframe was not marked as 'private', which would be desirable.
The fallback implementation of currentframe was different from the default implementation in that it did not skip any frames.
The number of frames skipped did not account for any direct calls to findCaller (and it did not provide a measurable speed-up).
stacklevel skipping did not use the same logic as in the warnings module, despite the documentation describing the argument as "The name of this parameter mirrors the equivalent one in the warnings module."

Regarding the last point, I did not know what to do in case more frames are to be skipped than the height of the stack. I listed three possibilities in the code which I think would all be sensible. The current behavior of using the top of the stack seems very odd to me.

https://bugs.python.org/issue45171

evandrocoan · 2021-09-11T15:01:25Z

Lib/logging/__init__.py

@@ -160,9 +160,9 @@ def addLevelName(level, levelName):
        _releaseLock()

 if hasattr(sys, '_getframe'):
-    currentframe = lambda: sys._getframe(3)
+    _currentframe = lambda: sys._getframe(1)


I am not sure if renaming this now is good because probably there is code out there using this, and this would break and force them up to add the infamous if python version < xxx.

I agree and restored the original name. However, I do think either renaming currentframe to _currentframe or documenting it as an official method should be considered.

Lib/logging/__init__.py

evandrocoan · 2021-09-11T15:27:23Z

Lib/logging/__init__.py

+                ## If we want to mimic the warnings module:
+                #return ("sys", 1, "(unknown function)", None)
+                ## If we want to be pedantic:
+                #raise ValueError("call stack is not deep enough")


So far, findCaller did not throw, so to keep the more backward-compatible I think it would be better if it did not throw.

evandrocoan · 2021-09-11T15:31:30Z

Lib/logging/__init__.py

+            # warnings._is_internal_frame
+            if filename == _srcfile or (
+                "importlib" in filename and "_bootstrap" in filename):
+            ):


Why start skipping importlib and _bootstrap? Does the warning module have a reason for that? Why would the logging module benefit from it? If so, I would it would be better just call their function _is_internal_frame instead of copying its contents.

Initially, the warnings module was used for it, but then I realized that no underscore methods of other modules are used in this file. Therefore, this implementation of logging could in principle be used in Python implementations that have a different implementation of warnings. For this reason, I chose to duplicate that piece of code. I noted that the currentframe code was initially lifted from inspect.

Skipping importlib._bootstrap was done to allow module-level warnings (here: log messages) with stacklevels that point to the importing module and not to the import mechanism. A useful thing, I'd say.

Thanks for explaining it. I am not sure if it would be a problem for the logging module to show the stack trace from importlib or _bootstrap as it was a problem for the warning module. What if I am using the logging module inside importlib? Disregarding this last scenario, I would wait to see what someone more experienced with Python library think about this.

Just out of curiosity, did you have trouble with the logging module showing stack traces of importlib or _bootstrap which lead you to bring this checking from the warning module or you just happened to know about their protection and thought it would be good to add it here too?

It is not "importlib or _bootstrap" that is checked for, but "importlib and _bootstrap" (i.e. importlib._bootstrap). There is no logging in Lib/importlib/_bootstrap.py and that module doesn't import anything (for obvious reasons), so I think we can safely say that the logging module is not used in importlib._bootstrap :-).

I ran into the stacklevel oddity mentioned in bpo-45171 and read that stacklevel was supposed to work like "the equivalent [parameter] in the warnings module". Thus I read how warnings chases the stack and copied the logic to logging.

joukewitteveen · 2021-09-13T18:22:34Z

Lib/logging/__init__.py

-        if not f:
-            f = orig_f
-        rv = "(unknown file)", 0, "(unknown function)", None
-        while hasattr(f, "f_code"):


Note that the new code doesn't verify that frame object contain an f_code attribute. It does verify that the frame object is not None. The f_code attribute is prescribed by the CPython data model and the warnings module doesn't check for it's presence either (it does check for stack exhaustion/None, like the new code here).

github-actions · 2021-10-14T00:05:41Z

This PR is stale because it has been open for 30 days with no activity.

joukewitteveen · 2021-10-14T06:31:34Z

@vsajip: I'm sorry to bother you, but you seem to be the chief-of-logging. Is there anything I can do to advance this pull request?

joukewitteveen · 2022-02-26T17:52:19Z

@vsajip, I still stand behind this MR since it solves a real bug (the current code does not pass the tests added in this MR). Could you comment on its feasibility?

vsajip · 2022-03-15T08:59:17Z

@joukewitteveen Sorry, been busy lately with other commitments. Will get to looking at this as soon as I can.

vsajip · 2022-03-25T09:20:07Z

I'll close and reopen to unblock stalled checks.

joukewitteveen · 2022-03-27T14:05:43Z

Lib/logging/__init__.py

+            if next_f is None:
+                ##TODO: We've got options here
+                ## If we want to use the last (deepest) frame:
+                break
+                ## If we want to mimic the warnings module:
+                #return ("sys", 1, "(unknown function)", None)
+                ## If we want to be pedantic:
+                #raise ValueError("call stack is not deep enough")


@vsajip Thanks for the approval and merge! Note that there was a TODO here which I summarized in the original PR description as:

Regarding the last point, I did not know what to do in case more frames are to be skipped than the height of the stack. I listed three possibilities in the code which I think would all be sensible.

Having it merged like this is not wrong per se (it will use the deepest available frame if the stack is exhausted), but it would be good to at least remove the TODO: part on line 1571. Maybe all of the above could even be replaced with

if next_f is None: # Not enough stack frames. We use the last (deepest) one. break

Or maybe leave it as a reminder in case this needs revisiting for any reason?

Indeed, but in that case I would still remove the word TODO:, since nothing needs to be done.

Anyway, I really appreciate that you took a look at this PR. Thanks!

joukewitteveen requested a review from vsajip as a code owner September 11, 2021 13:25

the-knights-who-say-ni added the CLA signed label Sep 11, 2021

bedevere-bot added the awaiting review label Sep 11, 2021

joukewitteveen mentioned this pull request Sep 11, 2021

bpo-33165: Remove redundant stack unwind for findCaller() #17714

Closed

joukewitteveen force-pushed the logging-stacklevel branch from f4f78ab to a7c6ccb Compare September 11, 2021 14:07

evandrocoan reviewed Sep 11, 2021

View reviewed changes

Lib/logging/__init__.py Outdated Show resolved Hide resolved

evandrocoan reviewed Sep 11, 2021

View reviewed changes

joukewitteveen force-pushed the logging-stacklevel branch 2 times, most recently from 214a707 to 188e6d9 Compare September 11, 2021 16:21

bpo-45171: Fix stacklevel handling in logging module

a35493e

joukewitteveen force-pushed the logging-stacklevel branch from 188e6d9 to a35493e Compare September 13, 2021 18:13

joukewitteveen commented Sep 13, 2021

View reviewed changes

github-actions bot added the stale Stale PR or inactive for long period of time. label Oct 14, 2021

github-actions bot removed the stale Stale PR or inactive for long period of time. label Oct 15, 2021

vsajip closed this Mar 25, 2022

vsajip reopened this Mar 25, 2022

vsajip approved these changes Mar 27, 2022

View reviewed changes

bedevere-bot added awaiting merge and removed awaiting review labels Mar 27, 2022

vsajip changed the title ~~bpo-45171: Fix stacklevel handling in logging module~~ bpo-45171: Fix stacklevel handling in logging. (GH-28287) Mar 27, 2022

vsajip merged commit 5ca6d74 into python:main Mar 27, 2022

bedevere-bot removed the awaiting merge label Mar 27, 2022

joukewitteveen commented Mar 27, 2022

View reviewed changes

joukewitteveen mentioned this pull request Mar 27, 2022

bpo-45171: Remove tests of deprecated logger.warn(). (GH-32139) #32139

Merged

joukewitteveen deleted the logging-stacklevel branch March 27, 2022 19:04

joukewitteveen mannequin mentioned this pull request Apr 10, 2022

stacklevel handling in logging module is inconsistent #89334

Closed

bastimeyer mentioned this pull request Oct 5, 2022

py311: incorrect logging.LogRecord.module value (and related attrs) when using a custom log-level method #97941

Closed

joukewitteveen mentioned this pull request Aug 8, 2024

Remove deprecated logging.Logger.warn() method in Python 3.13 #105376

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

bpo-45171: Fix stacklevel handling in logging. (GH-28287) #28287

bpo-45171: Fix stacklevel handling in logging. (GH-28287) #28287

joukewitteveen commented Sep 11, 2021 •

edited by bedevere-bot

Loading

evandrocoan Sep 11, 2021

joukewitteveen Sep 11, 2021

evandrocoan Sep 11, 2021

evandrocoan Sep 11, 2021

joukewitteveen Sep 11, 2021

joukewitteveen Sep 11, 2021

evandrocoan Sep 13, 2021

joukewitteveen Sep 13, 2021

joukewitteveen Sep 13, 2021

github-actions bot commented Oct 14, 2021

joukewitteveen commented Oct 14, 2021

joukewitteveen commented Feb 26, 2022

vsajip commented Mar 15, 2022

vsajip commented Mar 25, 2022

joukewitteveen Mar 27, 2022

vsajip Mar 27, 2022

joukewitteveen Mar 27, 2022

bpo-45171: Fix stacklevel handling in logging. (GH-28287) #28287

bpo-45171: Fix stacklevel handling in logging. (GH-28287) #28287

Conversation

joukewitteveen commented Sep 11, 2021 • edited by bedevere-bot Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot commented Oct 14, 2021

joukewitteveen commented Oct 14, 2021

joukewitteveen commented Feb 26, 2022

vsajip commented Mar 15, 2022

vsajip commented Mar 25, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joukewitteveen commented Sep 11, 2021 •

edited by bedevere-bot

Loading