classification
Title: Logger.findCaller needs to be smarter
Type: enhancement Stage: resolved
Components: Library (Lib) Versions: Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: glynnc, mrohan, ncoghlan, pitrou, vinay.sajip
Priority: normal Keywords: patch

Created on 2012-12-25 16:20 by glynnc, last changed 2018-06-08 10:17 by vinay.sajip. This issue is now closed.

Files
File name Uploaded Description Edit
skipcallers.diff vinay.sajip, 2012-12-28 23:03 First attempt to provide requested functionality. review
skipcallers_name.diff vinay.sajip, 2012-12-29 20:30 Changed to use the module name in the API. review
skipcallers_updated.diff vinay.sajip, 2013-12-28 08:08 Improved implementation review
Repositories containing patches
http://hg.python.org/sandbox/vsajip#fix16778
Messages (13)
msg178145 - (view) Author: Glynn Clements (glynnc) Date: 2012-12-25 16:20
The current behaviour of logging.Logger.findCaller() makes it awkward to add custom logging interfaces.

E.g. suppose that you define a custom logging level (NOTICE) then add a notice() function (analogous to logging.info() etc), the resulting LogRecord structure will have pathname, filename, module, funcName and lineno members which refer to the notice() function itself, rather than to its caller.

This can be hacked around e.g. by using code.compile_command to lie about the source filename, but that's ugly and highly unintuitive.
msg178262 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-12-27 01:25
What about subclassing Logger? Then you could override findCaller() to do whatever you need, as well as adding a notice() method, for example.

I agree using the source filename isn't ideal, but it's hard to know how people might arbitrarily wrap logging calls and still expect the wrappers to be skipped by findCaller(). Do you have any suggested mechanism for doing this?
msg178263 - (view) Author: Glynn Clements (glynnc) Date: 2012-12-27 02:37
Subclassing findCaller() is likely to be a bit hairy for the average user, as it deals with some fairly arcane aspects of Python internals.

As for mechanism, maybe allow functions/methods to be registered with the logging module, which would store a referenceto the function's func_code member. findCaller() would check the frame's f_code member against the set of registered functions, and continue up the stack until it found an unregistered function.
msg178308 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-12-27 18:43
I will give this some thought, but it won't be possible to add it to Python 2.x (which is closed for feature additions). Any enhancement in this area would apply to Python 3.4 and later.
msg178462 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-12-29 01:58
Passing a globals() instance looks hackish.
importlib uses another approach:
http://hg.python.org/cpython/file/5ef49659935f/Lib/importlib/_bootstrap.py#l303

Note that it is a pity that code objects don't have a __module__ attribute. Perhaps it would be a nice feature for 3.4.
msg178508 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-12-29 16:09
> Passing a globals() instance looks hackish.

Agreed it's not ideal, but we're constrained by what's available to compare against via the frame. Apart from globals() there's only really the filename, which isn't ideal either.
msg207022 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-12-28 08:15
Too late for 3.4 now, bumping to 3.5. Implementation now uses a set and '__name__' in f.f_globals to match module names passed in - this seems good enough. I plan to commit this as soon as default is updated to 3.5, unless there are alternative suggestions.
msg207074 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2013-12-29 14:49
I think we need to look seriously at the frame annotations idea discussed in other issues. Eliminating noise from tracebacks and correctly reporting user code rather than infrastructure could should be achievable through local state rather than needing global registries.

The workaround we put in place for importlib is an awful hack, and there's a problem where PEP 3144 allows the creation of exception *trees*, but we can currently only record stacks properly.
msg207078 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-12-29 15:30
> the frame annotations idea discussed in other issues

If you mean #19585 and #18861, they seem to be related to exceptions - the logging use case is not exception-related. I couldn't find any other discussions about frame annotations.
msg207088 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2013-12-30 00:09
My idea is to annotate the frames appropriately so they can be *displayed*
differently when showing a traceback (either hiding them entirely or
displaying additional information). This would be another use case -
annotating the frame to say the logging module should skip over it when
looking for the caller.
msg223550 - (view) Author: Michael Rohan (mrohan) Date: 2014-07-20 23:49
I recently implemented a custom logger derived from Logger and to get the
reporting of modules, etc, correct, I implemented the findCaller using
the same code as library code with the minor change of

if filename == _srcfile:

to

if filename in [logging._srcfile, _mysrcfile]:

with the local _mysrcfile being determined the same as in logging.

Maybe simply having a class list "srcfiles = [_srcfile]" and allowing
people who customize extend this would be the easiest way of handling
this: "Logger.srcfiles.append(_mysrcfile)"
msg223564 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2014-07-21 07:56
> Maybe simply having a class list

Thanks, I'm aware of this approach and have considered it. The current patch's skipCallers API seems better than exposing an internal list, but I have held off implementing this in the hope that an approach based on frame annotations can be used.
msg319043 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-06-08 10:17
This should be addressed by the fix for bpo-33165 - addition of a stacklevel parameter to the logging APIs.
History
Date User Action Args
2018-06-08 10:17:20vinay.sajipsetstatus: open -> closed
resolution: fixed
messages: + msg319043

stage: resolved
2014-07-21 07:56:35vinay.sajipsetmessages: + msg223564
2014-07-20 23:49:49mrohansetnosy: + mrohan
messages: + msg223550
2013-12-30 00:09:32ncoghlansetmessages: + msg207088
2013-12-29 15:30:10vinay.sajipsetmessages: + msg207078
2013-12-29 14:49:55ncoghlansetmessages: + msg207074
2013-12-28 19:45:58pitrousetnosy: + ncoghlan
2013-12-28 08:15:56vinay.sajipsetmessages: + msg207022
versions: + Python 3.5, - Python 3.4
2013-12-28 08:08:24vinay.sajipsetfiles: + skipcallers_updated.diff
2012-12-29 20:30:22vinay.sajipsetfiles: + skipcallers_name.diff
2012-12-29 16:09:14vinay.sajipsetmessages: + msg178508
2012-12-29 01:58:19pitrousetnosy: + pitrou
messages: + msg178462
2012-12-28 23:03:16vinay.sajipsetfiles: + skipcallers.diff
keywords: + patch
2012-12-28 23:02:49vinay.sajipsethgrepos: + hgrepo166
2012-12-27 18:43:03vinay.sajipsetmessages: + msg178308
versions: + Python 3.4, - Python 2.7
2012-12-27 02:37:36glynncsetmessages: + msg178263
2012-12-27 01:25:45vinay.sajipsetmessages: + msg178262
2012-12-25 16:26:34r.david.murraysetnosy: + vinay.sajip
2012-12-25 16:20:27glynnccreate