logging: local functions ==> loss of lineno

[Jean-Michel Pichavant]

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