[lnkForumImage]
TotalShareware - Download Free Software

Confronta i prezzi di migliaia di prodotti.
Asp Forum
 Home | Login | Register | Search 


 

Forums >

comp.lang.python

logging: local functions ==> loss of lineno

Hellmut Weber

3/10/2010 9:23:00 PM

Hi Vinay Sajip,
I'm very glad discoverd your logging module ;-)
(That's what I would have liked 25 years ago when I was working as a
technical software developper!)

Now I'm writing just some personal tools, I like python and want to use
logging on a regular basis.

Logging works very well giving the filename and line number of the point
where it is called. As long as I use the loggers directly.
BUT when I have to wrap the logger call in some other function, I always
get file name and line number of the call of the logger inside the
wrapping function.

Is there a possibility to get this information in this situation too?

TIA

Hellmut

--
Dr. Hellmut Weber mail@hellmutweber.de
Degenfeldstraße 2 tel +49-89-3081172
D-80803 München-Schwabing mobil +49-172-8450321
please: No DOCs, no PPTs. why: tinyurl.com/cbgq

12 Answers

Peter Otten

3/11/2010 11:14:00 AM

0

Hellmut Weber wrote:

> Logging works very well giving the filename and line number of the point
> where it is called. As long as I use the loggers directly.
> BUT when I have to wrap the logger call in some other function, I always
> get file name and line number of the call of the logger inside the
> wrapping function.
>
> Is there a possibility to get this information in this situation too?

The official way is probably to write a custom Logger class that overrides
the findCaller() method.

Below is a hack that monkey-patches the logging._srcfile attribute to ignore
user-specified modules in the call stack:

$ cat wrapper.py
import logging
import os
import sys

logger = logging.getLogger()

class SrcFile(object):
def __init__(self, exclude_files):
self.files = set(exclude_files)
def __eq__(self, other):
return other in self.files

def fixname(filename):
if filename.lower().endswith((".pyc", ".pyo")):
filename = filename[:-4] + ".py"
return os.path.normcase(filename)

if "--monkey" in sys.argv:
print "patching"
logging._srcfile = SrcFile([logging._srcfile, fixname(__file__)])

def warn(*args, **kw):
logger.warn(*args, **kw)

$ cat main.py
import logging
logging.basicConfig(format="%(filename)s <%(lineno)s>: %(message)s")
import wrapper
wrapper.warn("foo")
wrapper.warn("bar")
wrapper.warn("baz")

$ python main.py
wrapper.py <23>: foo
wrapper.py <23>: bar
wrapper.py <23>: baz

$ python main.py --monkey
patching
main.py <4>: foo
main.py <5>: bar
main.py <6>: baz

$ python -V
Python 2.6.4

Peter

Hellmut Weber

3/15/2010 11:36:00 PM

0

Am 11.03.2010 12:14, schrieb Peter Otten:
> Hellmut Weber wrote:
>
>> Logging works very well giving the filename and line number of the point
>> where it is called. As long as I use the loggers directly.
>> BUT when I have to wrap the logger call in some other function, I always
>> get file name and line number of the call of the logger inside the
>> wrapping function.
>>
>> Is there a possibility to get this information in this situation too?
>
> The official way is probably to write a custom Logger class that overrides
> the findCaller() method.
>
> Below is a hack that monkey-patches the logging._srcfile attribute to ignore
> user-specified modules in the call stack:
>
> $ cat wrapper.py
> import logging
> import os
> import sys
>
> logger = logging.getLogger()
>
> class SrcFile(object):
> def __init__(self, exclude_files):
> self.files = set(exclude_files)
> def __eq__(self, other):
> return other in self.files
>
> def fixname(filename):
> if filename.lower().endswith((".pyc", ".pyo")):
> filename = filename[:-4] + ".py"
> return os.path.normcase(filename)
>
> if "--monkey" in sys.argv:
> print "patching"
> logging._srcfile = SrcFile([logging._srcfile, fixname(__file__)])
>
> def warn(*args, **kw):
> logger.warn(*args, **kw)
>
> $ cat main.py
> import logging
> logging.basicConfig(format="%(filename)s<%(lineno)s>: %(message)s")
> import wrapper
> wrapper.warn("foo")
> wrapper.warn("bar")
> wrapper.warn("baz")
>
> $ python main.py
> wrapper.py<23>: foo
> wrapper.py<23>: bar
> wrapper.py<23>: baz
>
> $ python main.py --monkey
> patching
> main.py<4>: foo
> main.py<5>: bar
> main.py<6>: baz
>
> $ python -V
> Python 2.6.4
>
> Peter

Hi Peter,
thanks for your help ;-)

I've been offline for a few days so I found your message only today.
I'll try your proposal tomorrow.

Thanks again

Hellmut

--
Dr. Hellmut Weber mail@hellmutweber.de
Degenfeldstraße 2 tel +49-89-3081172
D-80803 München-Schwabing mobil +49-172-8450321
please: No DOCs, no PPTs. why: tinyurl.com/cbgq

Hellmut Weber

3/18/2010 9:06:00 PM

0

Am 11.03.2010 12:14, schrieb Peter Otten:
> Hellmut Weber wrote:
>
>> Logging works very well giving the filename and line number of the point
>> where it is called. As long as I use the loggers directly.
>> BUT when I have to wrap the logger call in some other function, I always
>> get file name and line number of the call of the logger inside the
>> wrapping function.
>>
>> Is there a possibility to get this information in this situation too?
>
> The official way is probably to write a custom Logger class that overrides
> the findCaller() method.
>
> Below is a hack that monkey-patches the logging._srcfile attribute to ignore
> user-specified modules in the call stack:
>
> $ cat wrapper.py
> import logging
> import os
> import sys
>
> logger = logging.getLogger()
>
> class SrcFile(object):
> def __init__(self, exclude_files):
> self.files = set(exclude_files)
> def __eq__(self, other):
> return other in self.files
>
> def fixname(filename):
> if filename.lower().endswith((".pyc", ".pyo")):
> filename = filename[:-4] + ".py"
> return os.path.normcase(filename)
>
> if "--monkey" in sys.argv:
> print "patching"
> logging._srcfile = SrcFile([logging._srcfile, fixname(__file__)])
>
> def warn(*args, **kw):
> logger.warn(*args, **kw)
>
> $ cat main.py
> import logging
> logging.basicConfig(format="%(filename)s<%(lineno)s>: %(message)s")
> import wrapper
> wrapper.warn("foo")
> wrapper.warn("bar")
> wrapper.warn("baz")
>
> $ python main.py
> wrapper.py<23>: foo
> wrapper.py<23>: bar
> wrapper.py<23>: baz
>
> $ python main.py --monkey
> patching
> main.py<4>: foo
> main.py<5>: bar
> main.py<6>: baz
>
> $ python -V
> Python 2.6.4
>
> Peter

Hi Peter,
your hack is exactly what I was looking for.
It permits to configure my logging messages as I want, e.g. using
different colors for different classes of messages.

I do not yet understand all details WHY it is working but suppose some
study of the logging module will help me to understand.

Thank you very much

--
Dr. Hellmut Weber mail@hellmutweber.de
Degenfeldstraße 2 tel +49-89-3081172
D-80803 München-Schwabing mobil +49-172-8450321
please: No DOCs, no PPTs. why: tinyurl.com/cbgq

Peter Otten

3/19/2010 7:57:00 AM

0

Hellmut Weber wrote:

> your hack is exactly what I was looking for.
> It permits to configure my logging messages as I want, e.g. using
> different colors for different classes of messages.
>
> I do not yet understand all details WHY it is working but suppose some
> study of the logging module will help me to understand.

Have a look at Logger.findCaller() in logging/__init__.py. To find the
calling function it does something like

for frame in walk_callstack():
if filename_of(frame) == _srcfile:
continue
return filename_lineno_and_functionname_of(frame)

The _srcfile is normally logging/__init__.py, and it is skipped because a
user typically is interested only in what happens outside the logging
package.

My hack under the hood changes

filename_of(frame) == _srcfile

from a string comparison to a

filename_of(frame) in set_of_files

containment test (see SrcFile.__eq__() posted above).

Peter



Jean-Michel Pichavant

3/19/2010 10:40:00 AM

0

Hellmut Weber wrote:
> Am 11.03.2010 12:14, schrieb Peter Otten:
>> Hellmut Weber wrote:
>>
>>> Logging works very well giving the filename and line number of the
>>> point
>>> where it is called. As long as I use the loggers directly.
>>> BUT when I have to wrap the logger call in some other function, I
>>> always
>>> get file name and line number of the call of the logger inside the
>>> wrapping function.
>>>
>>> Is there a possibility to get this information in this situation too?
>>
>> The official way is probably to write a custom Logger class that
>> overrides
>> the findCaller() method.
>>
>> Below is a hack that monkey-patches the logging._srcfile attribute to
>> ignore
>> user-specified modules in the call stack:
>>
>> $ cat wrapper.py
>> import logging
>> import os
>> import sys
>>
>> logger = logging.getLogger()
>>
>> class SrcFile(object):
>> def __init__(self, exclude_files):
>> self.files = set(exclude_files)
>> def __eq__(self, other):
>> return other in self.files
>>
>> def fixname(filename):
>> if filename.lower().endswith((".pyc", ".pyo")):
>> filename = filename[:-4] + ".py"
>> return os.path.normcase(filename)
>>
>> if "--monkey" in sys.argv:
>> print "patching"
>> logging._srcfile = SrcFile([logging._srcfile, fixname(__file__)])
>>
>> def warn(*args, **kw):
>> logger.warn(*args, **kw)
>>
>> $ cat main.py
>> import logging
>> logging.basicConfig(format="%(filename)s<%(lineno)s>: %(message)s")
>> import wrapper
>> wrapper.warn("foo")
>> wrapper.warn("bar")
>> wrapper.warn("baz")
>>
>> $ python main.py
>> wrapper.py<23>: foo
>> wrapper.py<23>: bar
>> wrapper.py<23>: baz
>>
>> $ python main.py --monkey
>> patching
>> main.py<4>: foo
>> main.py<5>: bar
>> main.py<6>: baz
>>
>> $ python -V
>> Python 2.6.4
>>
>> Peter
>
> Hi Peter,
> your hack is exactly what I was looking for.
> It permits to configure my logging messages as I want, e.g. using
> different colors for different classes of messages.
>
> I do not yet understand all details WHY it is working but suppose some
> study of the logging module will help me to understand.
>
> Thank you very much
>
_scrFile is a private attribute of the logging module. Don't change it.

As you said yourself, 'The official way is probably to write a custom
Logger class that overrides
the findCaller() method'

JM

Peter Otten

3/19/2010 12:25:00 PM

0

Jean-Michel Pichavant wrote:

> Hellmut Weber wrote:
>> Am 11.03.2010 12:14, schrieb Peter Otten:
>>> Hellmut Weber wrote:
>>>
>>>> Logging works very well giving the filename and line number of the
>>>> point
>>>> where it is called. As long as I use the loggers directly.
>>>> BUT when I have to wrap the logger call in some other function, I
>>>> always
>>>> get file name and line number of the call of the logger inside the
>>>> wrapping function.
>>>>
>>>> Is there a possibility to get this information in this situation too?
>>>
>>> The official way is probably to write a custom Logger class that
>>> overrides
>>> the findCaller() method.
>>>
>>> Below is a hack that monkey-patches the logging._srcfile attribute to
>>> ignore
>>> user-specified modules in the call stack:
>>>
>>> $ cat wrapper.py
>>> import logging
>>> import os
>>> import sys
>>>
>>> logger = logging.getLogger()
>>>
>>> class SrcFile(object):
>>> def __init__(self, exclude_files):
>>> self.files = set(exclude_files)
>>> def __eq__(self, other):
>>> return other in self.files
>>>
>>> def fixname(filename):
>>> if filename.lower().endswith((".pyc", ".pyo")):
>>> filename = filename[:-4] + ".py"
>>> return os.path.normcase(filename)
>>>
>>> if "--monkey" in sys.argv:
>>> print "patching"
>>> logging._srcfile = SrcFile([logging._srcfile, fixname(__file__)])
>>>
>>> def warn(*args, **kw):
>>> logger.warn(*args, **kw)
>>>
>>> $ cat main.py
>>> import logging
>>> logging.basicConfig(format="%(filename)s<%(lineno)s>: %(message)s")
>>> import wrapper
>>> wrapper.warn("foo")
>>> wrapper.warn("bar")
>>> wrapper.warn("baz")
>>>
>>> $ python main.py
>>> wrapper.py<23>: foo
>>> wrapper.py<23>: bar
>>> wrapper.py<23>: baz
>>>
>>> $ python main.py --monkey
>>> patching
>>> main.py<4>: foo
>>> main.py<5>: bar
>>> main.py<6>: baz
>>>
>>> $ python -V
>>> Python 2.6.4
>>>
>>> Peter
>>
>> Hi Peter,
>> your hack is exactly what I was looking for.
>> It permits to configure my logging messages as I want, e.g. using
>> different colors for different classes of messages.
>>
>> I do not yet understand all details WHY it is working but suppose some
>> study of the logging module will help me to understand.
>>
>> Thank you very much
>>
> _scrFile is a private attribute of the logging module. Don't change it.
>
> As you said yourself, 'The official way is probably to write a custom
> Logger class that overrides
> the findCaller() method'

OK, I tried the this approach, too:

import logging
import os
import sys

from logging import currentframe

def fixname(filename):
if filename.lower().endswith((".pyc", ".pyo")):
filename = filename[:-4] + ".py"
return os.path.normcase(filename)

class MyLogger(logging.Logger):
exclude_files = set([logging._srcfile, fixname(__file__)])

def findCaller(self):
"""
Find the stack frame of the caller so that we can note the source
file name, line number and function name.
"""
f = currentframe()
#On some versions of IronPython, currentframe() returns None if
#IronPython isn't run with -X:Frames.
if f is not None:
f = f.f_back
rv = "(unknown file)", 0, "(unknown function)"
while hasattr(f, "f_code"):
co = f.f_code
filename = os.path.normcase(co.co_filename)
if filename in self.exclude_files:
f = f.f_back
continue
rv = (filename, f.f_lineno, co.co_name)
break
return rv

if "--custom-logger" in sys.argv:
print "setting custom logger"
logging.setLoggerClass(MyLogger)
logging.root = MyLogger("root", logging.WARNING)

logger = logging.getLogger()
def warn(*args, **kw):
logger.warn(*args, **kw)

I had to duplicate the original findCaller() method with only one line
changed. This means I have now some code duplication and I still have to
monitor future changes in the logging source.

In this case the "official way" seems to be more intrusive than the "hack".

Peter

Jean-Michel Pichavant

3/19/2010 1:49:00 PM

0

Peter Otten wrote:
> Jean-Michel Pichavant wrote:
>
>
>> Hellmut Weber wrote:
>>
>>> Am 11.03.2010 12:14, schrieb Peter Otten:
>>>
>>>> Hellmut Weber wrote:
>>>>
>>>>
>>>>> Logging works very well giving the filename and line number of the
>>>>> point
>>>>> where it is called. As long as I use the loggers directly.
>>>>> BUT when I have to wrap the logger call in some other function, I
>>>>> always
>>>>> get file name and line number of the call of the logger inside the
>>>>> wrapping function.
>>>>>
>>>>> Is there a possibility to get this information in this situation too?
>>>>>
>>>> The official way is probably to write a custom Logger class that
>>>> overrides
>>>> the findCaller() method.
>>>>
>>>> Below is a hack that monkey-patches the logging._srcfile attribute to
>>>> ignore
>>>> user-specified modules in the call stack:
>>>>
>>>> $ cat wrapper.py
>>>> import logging
>>>> import os
>>>> import sys
>>>>
>>>> logger = logging.getLogger()
>>>>
>>>> class SrcFile(object):
>>>> def __init__(self, exclude_files):
>>>> self.files = set(exclude_files)
>>>> def __eq__(self, other):
>>>> return other in self.files
>>>>
>>>> def fixname(filename):
>>>> if filename.lower().endswith((".pyc", ".pyo")):
>>>> filename = filename[:-4] + ".py"
>>>> return os.path.normcase(filename)
>>>>
>>>> if "--monkey" in sys.argv:
>>>> print "patching"
>>>> logging._srcfile = SrcFile([logging._srcfile, fixname(__file__)])
>>>>
>>>> def warn(*args, **kw):
>>>> logger.warn(*args, **kw)
>>>>
>>>> $ cat main.py
>>>> import logging
>>>> logging.basicConfig(format="%(filename)s<%(lineno)s>: %(message)s")
>>>> import wrapper
>>>> wrapper.warn("foo")
>>>> wrapper.warn("bar")
>>>> wrapper.warn("baz")
>>>>
>>>> $ python main.py
>>>> wrapper.py<23>: foo
>>>> wrapper.py<23>: bar
>>>> wrapper.py<23>: baz
>>>>
>>>> $ python main.py --monkey
>>>> patching
>>>> main.py<4>: foo
>>>> main.py<5>: bar
>>>> main.py<6>: baz
>>>>
>>>> $ python -V
>>>> Python 2.6.4
>>>>
>>>> Peter
>>>>
>>> Hi Peter,
>>> your hack is exactly what I was looking for.
>>> It permits to configure my logging messages as I want, e.g. using
>>> different colors for different classes of messages.
>>>
>>> I do not yet understand all details WHY it is working but suppose some
>>> study of the logging module will help me to understand.
>>>
>>> Thank you very much
>>>
>>>
>> _scrFile is a private attribute of the logging module. Don't change it.
>>
>> As you said yourself, 'The official way is probably to write a custom
>> Logger class that overrides
>> the findCaller() method'
>>
>
> OK, I tried the this approach, too:
>
> import logging
> import os
> import sys
>
> from logging import currentframe
>
> def fixname(filename):
> if filename.lower().endswith((".pyc", ".pyo")):
> filename = filename[:-4] + ".py"
> return os.path.normcase(filename)
>
> class MyLogger(logging.Logger):
> exclude_files = set([logging._srcfile, fixname(__file__)])
>
> def findCaller(self):
> """
> Find the stack frame of the caller so that we can note the source
> file name, line number and function name.
> """
> f = currentframe()
> #On some versions of IronPython, currentframe() returns None if
> #IronPython isn't run with -X:Frames.
> if f is not None:
> f = f.f_back
> rv = "(unknown file)", 0, "(unknown function)"
> while hasattr(f, "f_code"):
> co = f.f_code
> filename = os.path.normcase(co.co_filename)
> if filename in self.exclude_files:
> f = f.f_back
> continue
> rv = (filename, f.f_lineno, co.co_name)
> break
> return rv
>
> if "--custom-logger" in sys.argv:
> print "setting custom logger"
> logging.setLoggerClass(MyLogger)
> logging.root = MyLogger("root", logging.WARNING)
>
> logger = logging.getLogger()
> def warn(*args, **kw):
> logger.warn(*args, **kw)
>
> I had to duplicate the original findCaller() method with only one line
> changed. This means I have now some code duplication and I still have to
> monitor future changes in the logging source.
>
> In this case the "official way" seems to be more intrusive than the "hack".
>
> Peter
You are still accessing the private attribute of the module logging.
My previous remark was misleading, in fact there's nothing you can do
about it.
_srcfile is not meant to be used elsewhere than in the logging module
itself.

However, I don't wanna sound like I'm rejecting this solution, 1st the
OP is satisified with it and since this solution is working, it is still
more helpful than anyone noticing that you've accessed a private
attribute (some will successfully argue that python allows to do so).

At the very begining of this thread I've provided a complete different
approach, instead of using the builtin 'filename' and 'lineno' field of
the logging, use custom fileds with the extra parameter.

It has also some drawbacks but could be a possible alternative.

Cheers,

JM

in test.py:

import logging
import inspect

_logger = logging.getLogger(__name__)

class Foo:
def __init__(self):
self._logger = _logger

def info(self, msg):
# this is the method you don't want to appear in the logs,
instead the lineno and filename of this method caller
previousFrame = inspect.currentframe().f_back
self._logger.info(msg,
extra={'custom_lineno':previousFrame.f_lineno, 'custom_filename':
previousFrame.f_code.co_filename})

if __name__ == '__main__':
_logger.handlers=[]
_logger.addHandler(logging.StreamHandler())
_logger.handlers[-1].setFormatter(logging.Formatter('file
%(custom_filename)s line %(custom_lineno)d : %(message)s'))
_logger.setLevel(logging.DEBUG)
foo = Foo()
foo.info('a foo info')

In [3]: run test.py
file test.py line 20 : a foo info

Peter Otten

3/20/2010 8:36:00 AM

0

Jean-Michel Pichavant wrote:

> You are still accessing the private attribute of the module logging.

Just reading it is a significantly more conservative approach than setting
it to an object with an unusual notion of equality ;)

> My previous remark was misleading, in fact there's nothing you can do
> about it.

How about replacing logging._srcfile with fixname(logging.__file__)?

> _srcfile is not meant to be used elsewhere than in the logging module
> itself.

> However, I don't wanna sound like I'm rejecting this solution, 1st the
> OP is satisified with it and since this solution is working, it is still
> more helpful than anyone noticing that you've accessed a private
> attribute (some will successfully argue that python allows to do so).

Yeah, I had hoped that I could get away without drawing the "consenting
adults" wildcard...

> At the very begining of this thread I've provided a complete different
> approach, instead of using the builtin 'filename' and 'lineno' field of
> the logging, use custom fileds with the extra parameter.
>
> It has also some drawbacks but could be a possible alternative.

Having two filename/lineno sets ist likely to confuse.

Peter

Vinay Sajip

3/23/2010 8:11:00 AM

0

On Mar 20, 8:36 am, Peter Otten <__pete...@web.de> wrote:
> Jean-Michel Pichavant wrote:
> > You are still accessing the private attribute of the  modulelogging.
>
> Just reading it is a significantly more conservative approach than setting
> it to an object with an unusual notion of equality ;)
>
> > My previous remark was misleading, in fact there's nothing you can do
> > about it.
>
> How about replacinglogging._srcfile with fixname(logging.__file__)?
>
> > _srcfile is not meant to be used elsewhere than in theloggingmodule
> > itself.
> > However, I don't wanna sound like I'm rejecting this solution, 1st the
> > OP is satisified with it and since this solution is working, it is still
> > more helpful than anyone noticing that you've accessed a private
> > attribute (some will successfully argue that python allows to do so).
>
> Yeah, I had hoped that I could get away without drawing the "consenting
> adults" wildcard...
>
> > At the very begining of this thread I've provided a complete different
> > approach, instead of using the builtin 'filename' and 'lineno' field of
> > thelogging, use custom fileds with the extra parameter.
>
> > It has also some drawbacks but could be a possible alternative.
>
> Having two filename/lineno sets ist likely to confuse.
>
> Peter

Guys,

Sorry I'm a little late to this discussion. I could add a _findCaller
function to the module (not part of the public API, but replaceable by
someone who really needs to) which does the heavy lifting, and
Logger.findCaller just calls it. Then those who need to can implement
their own strategy, without needing to jump through hoops. Does that
approach sound helpful?

Regards,

Vinay Sajip

Peter Otten

3/24/2010 9:35:00 AM

0

Vinay Sajip wrote:

> Sorry I'm a little late to this discussion. I could add a _findCaller
> function to the module (not part of the public API, but replaceable by
> someone who really needs to) which does the heavy lifting, and
> Logger.findCaller just calls it. Then those who need to can implement
> their own strategy, without needing to jump through hoops. Does that
> approach sound helpful?

You mean you'd have to monkey-patch logging._findCaller() instead of
overriding logging.Logger.findCaller()?

I don't see a big advantage in that.

Here's an alternative proposal: simplify findCaller() by moving part of the
code into a generator:

def callers(self):
"""
Walk up the call stack.
Helper for findCaller().
"""
f = currentframe()
#On some versions of IronPython, currentframe() returns None if
#IronPython isn't run with -X:Frames.
if f is not None:
f = f.f_back
while hasattr(f, "f_code"):
co = f.f_code
filename = os.path.normcase(co.co_filename)
yield filename, f.f_lineno, co.co_name
f = f.f_back


def findCaller(self):
"""
Find the stack frame of the caller so that we can note the source
file name, line number and function name.
"""
for filename, lineno, funcname in self.callers():
if filename != _srcfile:
return filename, lineno, funcname
return UNKNOWN_CALLER

Another simplification might be to have setLoggerClass() implicitly set the
root logger and to drop the distinct RootLogger class completely.

Note that I have no strong opinion on all this. If you leave things as is
I'm fine with that.

Peter