logging: local functions ==> loss of lineno

Discussion in 'Python' started by Hellmut Weber, Mar 10, 2010.

  1. 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
    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, Mar 10, 2010
    #1
    1. Advertising

  2. Hellmut Weber

    Peter Otten Guest

    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
     
    Peter Otten, Mar 11, 2010
    #2
    1. Advertising

  3. 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
    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, Mar 15, 2010
    #3
  4. 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
    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, Mar 18, 2010
    #4
  5. Hellmut Weber

    Peter Otten Guest

    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
     
    Peter Otten, Mar 19, 2010
    #5
  6. 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
     
    Jean-Michel Pichavant, Mar 19, 2010
    #6
  7. Hellmut Weber

    Peter Otten Guest

    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
     
    Peter Otten, Mar 19, 2010
    #7
  8. 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
     
    Jean-Michel Pichavant, Mar 19, 2010
    #8
  9. Hellmut Weber

    Peter Otten Guest

    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
     
    Peter Otten, Mar 20, 2010
    #9
  10. Hellmut Weber

    Vinay Sajip Guest

    On Mar 20, 8:36 am, Peter Otten <> 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
     
    Vinay Sajip, Mar 23, 2010
    #10
  11. Hellmut Weber

    Peter Otten Guest

    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
     
    Peter Otten, Mar 24, 2010
    #11
  12. Peter Otten wrote:
    > 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?
    >>

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

    Agreed, I'm not sure it's worth the effort Vinay.

    JM
     
    Jean-Michel Pichavant, Mar 24, 2010
    #12
  13. Hellmut Weber

    Vinay Sajip Guest

    On Mar 24, 9:34 am, Peter Otten <> wrote:
    >
    > 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
     
    Vinay Sajip, Mar 24, 2010
    #13
  14. 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.


    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__)

    --
    Dr. Hellmut Weber
    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, Mar 30, 2010
    #14
  15. Hellmut Weber

    Peter Otten Guest

    Hellmut Weber wrote:

    > 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
     
    Peter Otten, Mar 31, 2010
    #15
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. Laszlo Nagy

    ply yacc lineno not working?

    Laszlo Nagy, May 16, 2008, in forum: Python
    Replies:
    0
    Views:
    451
    Laszlo Nagy
    May 16, 2008
  2. Laszlo Nagy

    Re: ply yacc lineno not working?

    Laszlo Nagy, May 16, 2008, in forum: Python
    Replies:
    1
    Views:
    516
    inhahe
    May 16, 2008
  3. Belorion
    Replies:
    4
    Views:
    107
    Brian Schröder
    Nov 18, 2005
  4. Bil Kleb

    FasterCSV.foreach lineno?

    Bil Kleb, Apr 24, 2008, in forum: Ruby
    Replies:
    4
    Views:
    343
    James Gray
    Apr 24, 2008
  5. Ilias Lazaridis

    Obtain Filename and Lineno of the Function Caller

    Ilias Lazaridis, Jun 6, 2007, in forum: Perl Misc
    Replies:
    3
    Views:
    123
    Ilias Lazaridis
    Jun 7, 2007
Loading...

Share This Page