gh-115233: Fix currentframe to get the frame of original caller

[Agent-Hellboy]

• Issue: LoggerAdapter and %(funcName)s prints the wrong function name #115233

[Agent-Hellboy]

Unit test is passing, I will try to check, but what's the issue here, we should try to look for the most deepest frame possible so that we don't miss the exact caller.

…

On Sun, 11 Feb, 2024, 00:16 Vinay Sajip, ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In Lib/logging/__init__.py <#115241 (comment)>: > @@ -164,7 +164,7 @@ def addLevelName(level, levelName): _nameToLevel[levelName] = level if hasattr(sys, "_getframe"): - currentframe = lambda: sys._getframe(1) + currentframe = lambda: sys._getframe(3) I can understand that you have to add extra frames to allow for code in the LoggerAdapter, but what about code that doesn't use an adapter? What changed in 3.11 and later to cause the related issue? — Reply to this email directly, view it on GitHub <#115241 (review)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AHPPFO6SG4UQNWZ33SI4CYDYS66BJAVCNFSM6AAAAABDCVP5HOVHI2DSMVQWIX3LMV43YUDVNRWFEZLROVSXG5CSMV3GSZLXHMYTQNZTHEZDGOJSGE> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[vsajip]

I deleted my comment because just after I posted it, I remembered the earlier issue whose fix was in this area. I think the test should include calls both via the adapter and not, to ensure that the correct funcName value is computed in either case.

[serhiy-storchaka]

If it fixes LoggerAdapter, it breaks Logger.

I think that the proper fix should add the stacklevel parameter in LoggerAdapter._log() and call self.logger._log() with the proper value of stacklevel. You need also to balance stacklevel for LoggerAdapter.log() and other logging methods. The simplest way is to move some code from LoggerAdapter.log() to LoggerAdapter._log() and use ._log() instead of log() in other methods.

[bedevere-app]

A Python core developer has requested some changes be made to your pull request before we can consider merging it. If you could please address their requests along with any other requests in other reviews from core developers that would be appreciated.

Once you have made the requested changes, please leave a comment on this pull request containing the phrase I have made the requested changes; please review again. I will then notify any core developers who have left a review that you're ready for them to take another look at this pull request.

[Agent-Hellboy]

Hi @serhiy-storchaka , I have made the requested changes; please review again, but it has changed the way records are getting pushed in the handler,
should I fix the test or did I do anything wrong?
https://github.com/python/cpython/actions/runs/7859692843/job/21446066942?pr=115241#step:18:820

[serhiy-storchaka]

There is a test for formatting funcName in Logger: test_find_caller_with_stacklevel. Just add a similar test, but with LoggerAdapter (in class LoggerAdapterTest).

[serhiy-storchaka]

It will be simpler to just pass **kwargs, as in Logger methods, and just do a double correction in _log().

Also, it will be more efficient to pass args instead of *args.

[Agent-Hellboy]

Done, please check

[Agent-Hellboy]

There is a test for formatting funcName in Logger: test_find_caller_with_stacklevel. Just add a similar test, but with LoggerAdapter (in class LoggerAdapterTest).

sure, let me explore, I will add it, btw, I am still figuring out why below is failing

FAIL: test_nested (__main__.LoggerAdapterTest.test_nested)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/agent-hellboy/cpython/Lib/test/test_logging.py", line 5515, in test_nested
    self.assertEqual(record.args, (self.recording,))
    ~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: Tuples differ: ((<RecordingHandler (NOTSET)>,),) != (<RecordingHandler (NOTSET)>,)

First differing element 0:
(<RecordingHandler (NOTSET)>,)
<RecordingHandler (NOTSET)>

- ((<RecordingHandler (NOTSET)>,),)
? -                              --

+ (<RecordingHandler (NOTSET)>,)

[vsajip]

I am still figuring out why below is failing

An extra comma somewhere making something a tuple when that's not intended?

[Agent-Hellboy]

I am still figuring out why the below is failing

An extra comma somewhere making something a tuple when that's not intended?

Hi @vsajip
one adapter took the args and passed it to another and the other consumed it as an element ((args,),)
I added one more layer of the adapter and it started giving me (((<RecordingHandler (NOTSET)>,),),)

this is expected now as after restructuring, every adapter is going to hit _log and it will update the (extra context) args @serhiy-storchaka
I have verified it after running it on the main and my PR

previously, it was calling logger.log now it is calling logger._log which saves context.

    def test_nested(self):
        class Adapter(logging.LoggerAdapter):
            prefix = 'Adapter'

            def process(self, msg, kwargs):
                return f"{self.prefix} {msg}", kwargs

        msg = 'Adapters can be nested, yo.'
        adapter = Adapter(logger=self.logger, extra=None)
        adapter_adapter = Adapter(logger=adapter, extra=None)
        adapter_adapter.prefix = 'AdapterAdapter'
        self.assertEqual(repr(adapter), repr(adapter_adapter))
        adapter_adapter.log(logging.CRITICAL, msg, self.recording)
        self.assertEqual(len(self.recording.records), 1)
        record = self.recording.records[0]

[serhiy-storchaka]

It was surprising that new tests are passed with the unmodified code. It means that either the code was not broken, or that the new tests do not work as intended. I played with the code yesterday, and came to conclusion that both are true. The new tests did not test LoggerAdapter, and the code worked as intended while we use standard classes, the problem was in the example.

So I created a new PR #115325 which includes the fixed example and fixed tests.

[Agent-Hellboy]

Okay, got you.

[Agent-Hellboy]

should i close my PR? @serhiy-storchaka

[serhiy-storchaka]

Yes, I think nothing to do here. This issue was not as it seemed at first glance.