logging: local functions ==> loss of lineno
Hellmut Weber
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 ma...@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
Jean-Michel Pichavant
> 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
>
feature can only assume that you want the line number of the logger call.
i.e.
in test.py:
import logging
import inspect
_logger = logging.getLogger(__name__)
class Foo:
def __init__(self):
self._logger = _logger
def info(self, msg):
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
note that you cannot override the logging builtin 'lineno' key with the
extra dictionary, that is why I'm using the 'custom_lineno' key. I don't
know why the logger forbids it though, would have been nice to override
lineno without the need of adding a new key.
JM
Peter Otten
> 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
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 Weber
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
Peter Otten
> 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
> Am 11.03.2010 12:14, schrieb Peter Otten:
> 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.
>
>
_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
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
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
Peter Otten
> 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
> 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.
>
>
> > _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
>
> > 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
> 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
Jean-Michel Pichavant
> 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?
>>
>
> Note that I have no strong opinion on all this. If you leave things as is
> I'm fine with that.
>
> Peter
>
JM
Vinay Sajip
>
> You mean you'd have to monkey-patchlogging._findCaller() instead of
> overridinglogging.Logger.findCaller()?
>
> I don't see a big advantage in that.
>
Only that you just have to replace a function, and not have to
subclass Logger + override findCaller. And it's not especially monkey-
patching if the function is put there specifically to be replaced when
needed :-)
> Another simplification might be to have setLoggerClass() implicitly set the
> root logger and to drop the distinct RootLogger class completely.
I can't remember now why I created a separate class for the root - I
thought it might have some specialization which never happened. Of
course, I'm not sure if anyone is using it, so I can't just get rid of
it. Anyway, the root logger is in some sense special so it might be
more useful in the future.
> Note that I have no strong opinion on all this. If you leave things as is
> I'm fine with that.
Yes, it's hardly a common case that the OP is mentioning. AFAIK this
is the first time it's come up. I just thought from your and Jean-
Michel's solutions that there might be a need felt by more people to
have this functionality be more flexible.
Regards,
Vinay Sajip
Hellmut Weber
thanks for all your hints and pieces of code.
It took me a while to play around with what I got from you (and some
study of Vinay's module documentation.
Now I have come up with a more complete solution I'm quite satisfied
with. And I would be very glad to receive your comments on my code
indicating what I could do better, given that I'm still at the very
beginning with python.
Cheers + TIA
Hellmut
Here is my module and a corresponding test program:
leo@sylvester hw_logg $ cat loc_logg.py
#!/bin/env python
# -*- coding: utf-8 -*-
"""Hw's local logging module
To be done:
Factorize 'trace' decorator to own module
(to permit dependency on debug level) ???
"""
import sys # Basic system functions
import logging # Logging base
import logging.handlers
import inspect # monkey patch caller filename
# --- color change strings for terminal output ---
#
pc_yell = '\033[01;93m'
pc_purp = '\033[01;33m'
pc_gren = '\033[01;92m'
pc_blue = '\033[01;94m'
#
pc_bold = '\033[01;1m'
pc_norm = '\033[0m'
#
pc_reed = '\033[01;91m'
pc_cyan = '\033[01;96m'
level_color = {
'fatal': pc_yell,
'error': pc_yell,
'warning': pc_purp,
'info': pc_gren,
'debug': pc_blue,
'bold': pc_bold,
'normal': pc_norm
}
# --- define string building help function ---
#
def argskw_2_string(*args, **kwargs):
"""Generate String from *args and **kwargs
Return string with
*args list (comma separated) in first line
**kwargs key=val list (comma separated) in second line
"""
_str_lines = []
if args:
_args_strings = ''
for a in args:
_args_strings += str(a) + ', '
_str_lines.append(_args_strings)
if kwargs:
_kwargs_strings = ''
for k in kwargs:
_kwargs_strings += str(k)+' = '+str(kwargs[k]) + ', '
_str_lines.append(_kwargs_strings)
return ''.join(_str_lines)
# --- Class for all logging functionality ---
#
class locLogg():
_logger = None
def __init__(self, newlogg=None):
if not locLogg._logger:
locLogg._logger = newlogg
def init_logging(self,
loclogg_output='line', # stream or/and file
loclogg_fname='loggfile.txt',
loclogg_dblevel='DEBUG'
):
"""Initiate logging with locLogg._logger
Defines the logging handler to be used
and initiates it.
Possible values for loclogg_output:
line ==> output to console
file ==> log_file must be given
both ==> log_file must be given
null ==> no logging (NullHandler)
"""
locLogg._logger.handlers=[]
if loclogg_output in ('null'):
class NullHandler(logging.Handler):
def emit(self, record):
pass
locLogg._logger.addHandler(NullHandler())
if loclogg_output in ('line', 'both'):
locLogg._logger.addHandler(logging.StreamHandler())
if loclogg_output in ('file', 'both'):
locLogg._logger.addHandler(
logging.handlers.RotatingFileHandler(loclogg_fname,
maxBytes=200000, backupCount=5)
)
for _loc_logger in locLogg._logger.handlers:
_loc_logger.setFormatter(logging.Formatter(
'%(asctime)s ' + \
'%(custom_filename)s <%(custom_lineno)d>:' + \
'%(levelname)s %(message)s'))
# Can this be done better ?
_loc_levels = {'NOTSET': 0, 'DEBUG': 10,
'INFO': 20, 'WARNING': 30, 'ERROR': 40, 'CRITICAL': 50}
locLogg._logger.setLevel(_loc_levels[loclogg_dblevel])
def info_log(self, msg, *args, **kwargs):
previousFrame = inspect.currentframe().f_back
locLogg._logger.info(str(level_color['info'])+msg+pc_norm + \
' ' + argskw_2_string(*args, **kwargs),
extra={'custom_lineno': previousFrame.f_lineno,
'custom_filename': previousFrame.f_code.co_filename })
def debug_log(self, msg, *args, **kwargs):
previousFrame = inspect.currentframe().f_back
locLogg._logger.debug(str(level_color['debug'])+msg+pc_norm + \
' ' + argskw_2_string(*args, **kwargs),
extra={'custom_lineno':previousFrame.f_lineno,
'custom_filename': previousFrame.f_code.co_filename })
def warn_log(self, msg, *args, **kwargs):
previousFrame = inspect.currentframe().f_back
locLogg._logger.debug(str(level_color['warning'])+msg+pc_norm + \
' ' + argskw_2_string(*args, **kwargs),
extra={'custom_lineno':previousFrame.f_lineno,
'custom_filename': previousFrame.f_code.co_filename })
def error_log(self, msg, *args, **kwargs):
previousFrame = inspect.currentframe().f_back
locLogg._logger.error(str(level_color['error'])+msg+pc_norm + \
' ' + argskw_2_string(*args, **kwargs),
extra={'custom_lineno':previousFrame.f_lineno,
'custom_filename': previousFrame.f_code.co_filename })
def fatal_log(self, msg, *args, **kwargs):
previousFrame = inspect.currentframe().f_back
locLogg._logger.fatal(str(level_color['fatal'])+msg+pc_norm + \
' ' + argskw_2_string(*args, **kwargs),
extra={'custom_lineno':previousFrame.f_lineno,
'custom_filename': previousFrame.f_code.co_filename })
# --- Permit definition of a tracing decorator ---
from decorator import decorator
@decorator
def trace(f, *args, **kw):
print "@trace: calling %s with args %s, %s" % (f.func_name, args, kw)
return f(*args, **kw)
# cf. doc of Michele Simoniato's decorator module
if __name__ == '__main__':
_logger = logging.getLogger('jmp_logg__main__')
foo = locLogg(_logger)
foo.init_logging()
foo.info_log('a foo info')
foo.info_log('another bar info', 1,2,3, a=11, b=22, c=44)
foo.debug_log('a debug bar info', 'a', '1aA', qwe=2, asd=99)
foo.warn_log('a test info', 'ggg', '2U2', yxcv=2, asdf=99)
try:
b = 123
c = 0
a = b / c
except:
foo.fatal_log('Division by zero', b=123, c=0)
leo@sylvester hw_logg $ cat test_loclogg.py
#!/bin/env python
# -*- coding: utf-8 -*-
import logging
_logger = logging.getLogger()
import sys
pyDevelDir = '/home/leo/leo/brbeit/py-devel/Modules'
sys.path.append(pyDevelDir)
from hw_logg.loc_logg import locLogg
foo = locLogg(_logger)
foo.init_logging(
loclogg_output='both',
loclogg_dblevel='DEBUG')
import loc_module as jm
foo.info_log('First info with args in string: %d %d %d' % (1,2,3))
foo.warn_log('First warning')
foo.debug_log('First debug message TestTestTest', '----------', 4,5,6,
12*25, d=34, e='qwe')
foo.debug_log('Before calling jm.doIt()')
jm.doIt(True)
foo.info_log('Second info with kwargs separate:', a=11,b=22,c=33)
x = jm.MyClass(1, 2, 'abc')
x.mymethod()
x.mymethod(123, 234, a=1, b=2, c=3)
try:
jm.doIt(0)
except Exception, e:
foo.error_log(str(e), 1,5,8)
foo.fatal_log('Fatal message')
leo@sylvester hw_logg $ cat loc_module.py
# -*- coding: utf-8 -*-
import logging
_logger = logging.getLogger('jmp_logger')
import sys
pyDevelDir = '/home/leo/leo/brbeit/py-devel/Modules'
sys.path.append(pyDevelDir)
from hw_logg.loc_logg import locLogg, trace
foo = locLogg(_logger)
foo.info_log("Start importing "+__name__)
def doIt(yn=None):
foo.debug_log("doin' stuff, yn =", str(yn)) # logLevel at calling
point !
print '=====> Output from doIt:', yn
#do stuff...but suppose an error occurs?
if yn:
foo.info_log('yn: good value')
else:
raise TypeError, "bogus type error for testing"
class MyClass(object):
@trace
def __init__(self, *args, **kwargs):
print 'MyClass.__init__'
@trace
def mymethod(self, *args, **kwargs):
print 'MyClass.mymethod'
foo.info_log("End importing "+__name__)
Peter Otten
> Hi Peter and Jean-Michel,
> thanks for all your hints and pieces of code.
>
> It took me a while to play around with what I got from you (and some
> study of Vinay's module documentation.
>
> Now I have come up with a more complete solution I'm quite satisfied
> with. And I would be very glad to receive your comments on my code
> indicating what I could do better, given that I'm still at the very
> beginning with python.
> Here is my module and a corresponding test program:
> # --- color change strings for terminal output ---
> #
> pc_yell = '\033[01;93m'
> pc_purp = '\033[01;33m'
> pc_gren = '\033[01;92m'
Hw lng wld psts + prgrms b wr it nt 4 z art of clvr + ez 2 mmrz
abbreviations ;)
> # --- Class for all logging functionality ---
> #
> class locLogg():
> _logger = None
>
> def debug_log(self, msg, *args, **kwargs):
> def warn_log(self, msg, *args, **kwargs):
> def error_log(self, msg, *args, **kwargs):
It should be easy to factor out most the code in your xxx_log() methods into
a common helper.
> def fatal_log(self, msg, *args, **kwargs):
> previousFrame = inspect.currentframe().f_back
> locLogg._logger.fatal(str(level_color['fatal'])+msg+pc_norm + \
> ' ' + argskw_2_string(*args, **kwargs),
> extra={'custom_lineno':previousFrame.f_lineno,
> 'custom_filename': previousFrame.f_code.co_filename })
I think the formatting belongs into another layer. That's the purpose of the
logging.Formatter class. You could enhance it along those lines:
class Formatter(logging.Formatter):
markers = {
logging.INFO: ("<info>", "</info>"),
logging.WARN: ("<warn>", "</warn>"),
}
def format(self, record):
message = logging.Formatter.format(self, record)
try:
prefix, suffix = self.markers[record.levelno]
except KeyError:
pass
else:
message = prefix + message + suffix
return message
My general impression is that you are fighting the logging library's
structure rather than trying to use it as effectively as possible.
> foo.info_log('another bar info', 1,2,3, a=11, b=22, c=44)
You could achieve something similar with a standard logger by passing your
extra information through the extra parameter, e. g:
def extra(*args, **kw):
return dict(argskw=(args, kw))
foo.info("another...", extra=extra(1, 2, 3, a=11, b=22))
Peter