[ python-Bugs-1470422 ] Logging doesn't report the correct filename or line numbers

[SourceForge.net]

Bugs item #1470422, was opened at 2006-04-14 11:48
Message generated for change (Comment added) made by michaeltsai
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1470422&group_id=5470

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: Python Library
Group: Python 2.4
Status: Open
Resolution: None
Priority: 5
Submitted By: Michael Tsai (michaeltsai)
Assigned to: Vinay Sajip (vsajip)
Summary: Logging doesn't report the correct filename or line numbers

Initial Comment:
I have a logger that prints out %(filename)s:%(lineno)d along with the 
message. Instead of printing the file and line in my code where I call the 
logger, it prints out a location in logging/__init__.py.

I was able to fix this, at least for my purposes, by changing 
logging.currentframe from sys._getframe to lambda:sys._getframe(3).


----------------------------------------------------------------------

>Comment By: Michael Tsai (michaeltsai)
Date: 2006-04-21 15:04

Message:
Logged In: YES 
user_id=817528

I'm running on Mac OS X 10.4.6.

Here's a simple script:
"""#!/usr/local/bin/python2.4

import logging
logging.basicConfig(format=u"%(filename)s:%(lineno)d %(message)s")
log = logging.getLogger("test")
log.error(u"this is an error")
"""

Unfortunately, it doesn't reliably fail; most of the time it works. I haven't 
figured out how to trigger it.

It does reliably fail when I use a frozen system created with "py2app -A" in 
which the Python libraries are symlinked in (rather than in a Zip). Then, 
logging._srcfile is "logging/__init__.py", but __file__ is something like "/
System/Library/Frameworks/Python.framework/Versions/2.3/lib/python2.3/
logging/__init__.py" Maybe py2app shouldn't set sys.frozen in this case? 

Anyway, I don't think that's the real problem, because I've seen this happen 
when not using py2app (but, sorry, I'm not able to reliably duplicate it at this 
time).

My patch isn't really the right fix, but I do think it works because, at least with 
the current logging module, currentframe() is always called with the same 
sequence of frames on the top of the stack.

----------------------------------------------------------------------

Comment By: Vinay Sajip (vsajip)
Date: 2006-04-21 14:20

Message:
Logged In: YES 
user_id=308438

Please can you provide a small script which demonstrates the
problem? Which platform are you running on? Is there
anything unusual about your setup (e.g. running from a
frozen system)?

I'm not sure your patch is the correct solution. The system
looks up the call stack until a file is found which is not
the source file of the logging module itself - that is
presumed to be the caller. However, determining the source
file of the logging module can come unstuck in scenarios
such as py2exe-ified programs.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1470422&group_id=5470