Logging: added stack_info argument.

This commit is contained in:
Vinay Sajip 2010-11-14 21:33:04 +00:00
parent b6b76c2f78
commit 8593ae6451
3 changed files with 113 additions and 21 deletions

View File

@ -757,13 +757,31 @@ functions.
*msg* using the string formatting operator. (Note that this means that you can
use keywords in the format string, together with a single dictionary argument.)
There are two keyword arguments in *kwargs* which are inspected: *exc_info*
There are three keyword arguments in *kwargs* which are inspected: *exc_info*
which, if it does not evaluate as false, causes exception information to be
added to the logging message. If an exception tuple (in the format returned by
:func:`sys.exc_info`) is provided, it is used; otherwise, :func:`sys.exc_info`
is called to get the exception information.
The other optional keyword argument is *extra* which can be used to pass a
The second optional keyword argument is *stack_info*, which defaults to
False. If specified as True, stack information is added to the logging
message, including the actual logging call. Note that this is not the same
stack information as that displayed through specifying *exc_info*: The
former is stack frames from the bottom of the stack up to the logging call
in the current thread, whereas the latter is information about stack frames
which have been unwound, following an exception, while searching for
exception handlers.
You can specify *stack_info* independently of *exc_info*, e.g. to just show
how you got to a certain point in your code, even when no exceptions were
raised. The stack frames are printed following a header line which says::
Stack (most recent call last):
This mimics the `Traceback (most recent call last):` which is used when
displaying exception frames.
The third optional keyword argument is *extra* which can be used to pass a
dictionary which is used to populate the __dict__ of the LogRecord created for
the logging event with user-defined attributes. These custom attributes can then
be used as you like. For example, they could be incorporated into logged
@ -796,6 +814,8 @@ functions.
above example). In such circumstances, it is likely that specialized
:class:`Formatter`\ s would be used with particular :class:`Handler`\ s.
.. versionadded:: 3.2
The *stack_info* parameter was added.
.. function:: info(msg, *args, **kwargs)
@ -1038,13 +1058,31 @@ instantiated directly, but always through the module-level function
*msg* using the string formatting operator. (Note that this means that you can
use keywords in the format string, together with a single dictionary argument.)
There are two keyword arguments in *kwargs* which are inspected: *exc_info*
There are three keyword arguments in *kwargs* which are inspected: *exc_info*
which, if it does not evaluate as false, causes exception information to be
added to the logging message. If an exception tuple (in the format returned by
:func:`sys.exc_info`) is provided, it is used; otherwise, :func:`sys.exc_info`
is called to get the exception information.
The other optional keyword argument is *extra* which can be used to pass a
The second optional keyword argument is *stack_info*, which defaults to
False. If specified as True, stack information is added to the logging
message, including the actual logging call. Note that this is not the same
stack information as that displayed through specifying *exc_info*: The
former is stack frames from the bottom of the stack up to the logging call
in the current thread, whereas the latter is information about stack frames
which have been unwound, following an exception, while searching for
exception handlers.
You can specify *stack_info* independently of *exc_info*, e.g. to just show
how you got to a certain point in your code, even when no exceptions were
raised. The stack frames are printed following a header line which says::
Stack (most recent call last):
This mimics the `Traceback (most recent call last):` which is used when
displaying exception frames.
The third keyword argument is *extra* which can be used to pass a
dictionary which is used to populate the __dict__ of the LogRecord created for
the logging event with user-defined attributes. These custom attributes can then
be used as you like. For example, they could be incorporated into logged
@ -1078,6 +1116,9 @@ instantiated directly, but always through the module-level function
above example). In such circumstances, it is likely that specialized
:class:`Formatter`\ s would be used with particular :class:`Handler`\ s.
.. versionadded:: 3.2
The *stack_info* parameter was added.
.. method:: Logger.info(msg, *args, **kwargs)
@ -1142,10 +1183,11 @@ instantiated directly, but always through the module-level function
Removes the specified handler *hdlr* from this logger.
.. method:: Logger.findCaller()
.. method:: Logger.findCaller(stack_info=False)
Finds the caller's source filename and line number. Returns the filename, line
number and function name as a 3-element tuple.
number, function name and stack information as a 4-element tuple. The stack
information is returned as *None* unless *stack_info* is *True*.
.. method:: Logger.handle(record)
@ -1156,7 +1198,7 @@ instantiated directly, but always through the module-level function
Logger-level filtering is applied using :meth:`~Logger.filter`.
.. method:: Logger.makeRecord(name, lvl, fn, lno, msg, args, exc_info, func=None, extra=None)
.. method:: Logger.makeRecord(name, lvl, fn, lno, msg, args, exc_info, func=None, extra=None, sinfo=None)
This is a factory method which can be overridden in subclasses to create
specialized :class:`LogRecord` instances.
@ -3043,6 +3085,9 @@ Currently, the useful mapping keys in a :class:`LogRecord` are:
formatter to handle the event doesn't use the cached value but
recalculates it afresh.
If stack information is available, it's appended after the exception
information, using :meth:`formatStack` to transform it if necessary.
.. method:: formatTime(record, datefmt=None)
@ -3062,6 +3107,12 @@ Currently, the useful mapping keys in a :class:`LogRecord` are:
just uses :func:`traceback.print_exception`. The resulting string is
returned.
.. method:: formatStack(stack_info)
Formats the specified stack information (a string as returned by
:func:`traceback.print_stack`, but with the last newline removed) as a
string. This default implementation just returns the input value.
.. _filter:
Filter Objects
@ -3131,7 +3182,7 @@ every time something is logged, and can be created manually via
wire).
.. class:: LogRecord(name, lvl, pathname, lineno, msg, args, exc_info, func=None)
.. class:: LogRecord(name, lvl, pathname, lineno, msg, args, exc_info, func=None, sinfo=None)
Contains all the information pertinent to the event being logged.
@ -3178,6 +3229,12 @@ wire).
Absolute pathname of the source file of origin.
.. attribute:: stack_info
Stack frame information (where available) from the bottom of the stack
in the current thread, up to and including the stack frame of the
logging call which resulted in the creation of this record.
.. method:: getMessage()
Returns the message for this :class:`LogRecord` instance after merging any

View File

@ -238,7 +238,7 @@ class LogRecord(object):
information to be logged.
"""
def __init__(self, name, level, pathname, lineno,
msg, args, exc_info, func=None):
msg, args, exc_info, func=None, sinfo=None):
"""
Initialize a logging record with interesting information.
"""
@ -272,6 +272,7 @@ class LogRecord(object):
self.module = "Unknown module"
self.exc_info = exc_info
self.exc_text = None # used to cache the traceback text
self.stack_info = sinfo
self.lineno = lineno
self.funcName = func
self.created = ct
@ -515,6 +516,19 @@ class Formatter(object):
def formatMessage(self, record):
return self._style.format(record)
def formatStack(self, stack_info):
"""
This method is provided as an extension point for specialized
formatting of stack information.
The input data is a string as returned from a call to
:func:`traceback.print_stack`, but with the last trailing newline
removed.
The base implementation just returns the value passed in.
"""
return stack_info
def format(self, record):
"""
Format the specified record as text.
@ -541,6 +555,10 @@ class Formatter(object):
if s[-1:] != "\n":
s = s + "\n"
s = s + record.exc_text
if record.stack_info:
if s[-1:] != "\n":
s = s + "\n"
s = s + self.formatStack(record.stack_info)
return s
#
@ -1213,11 +1231,12 @@ class Logger(Filterer):
if self.isEnabledFor(ERROR):
self._log(ERROR, msg, args, **kwargs)
def exception(self, msg, *args):
def exception(self, msg, *args, **kwargs):
"""
Convenience method for logging an ERROR with exception information.
"""
self.error(msg, exc_info=1, *args)
kwargs['exc_info'] = True
self.error(msg, *args, **kwargs)
def critical(self, msg, *args, **kwargs):
"""
@ -1250,7 +1269,7 @@ class Logger(Filterer):
if self.isEnabledFor(level):
self._log(level, msg, args, **kwargs)
def findCaller(self):
def findCaller(self, stack_info=False):
"""
Find the stack frame of the caller so that we can note the source
file name, line number and function name.
@ -1260,23 +1279,34 @@ class Logger(Filterer):
#IronPython isn't run with -X:Frames.
if f is not None:
f = f.f_back
rv = "(unknown file)", 0, "(unknown function)"
rv = "(unknown file)", 0, "(unknown function)", None
while hasattr(f, "f_code"):
co = f.f_code
filename = os.path.normcase(co.co_filename)
if filename == _srcfile:
f = f.f_back
continue
rv = (co.co_filename, f.f_lineno, co.co_name)
sinfo = None
if stack_info:
sio = io.StringIO()
sio.write('Stack (most recent call last):\n')
traceback.print_stack(f, file=sio)
sinfo = sio.getvalue()
if sinfo[-1] == '\n':
sinfo = sinfo[:-1]
sio.close()
rv = (co.co_filename, f.f_lineno, co.co_name, sinfo)
break
return rv
def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):
def makeRecord(self, name, level, fn, lno, msg, args, exc_info,
func=None, extra=None, sinfo=None):
"""
A factory method which can be overridden in subclasses to create
specialized LogRecords.
"""
rv = _logRecordClass(name, level, fn, lno, msg, args, exc_info, func)
rv = _logRecordClass(name, level, fn, lno, msg, args, exc_info, func,
sinfo)
if extra is not None:
for key in extra:
if (key in ["message", "asctime"]) or (key in rv.__dict__):
@ -1284,17 +1314,18 @@ class Logger(Filterer):
rv.__dict__[key] = extra[key]
return rv
def _log(self, level, msg, args, exc_info=None, extra=None):
def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False):
"""
Low-level logging routine which creates a LogRecord and then calls
all the handlers of this logger to handle the record.
"""
sinfo = None
if _srcfile:
#IronPython doesn't track Python frames, so findCaller throws an
#exception on some versions of IronPython. We trap it here so that
#IronPython can use logging.
try:
fn, lno, func = self.findCaller()
fn, lno, func, sinfo = self.findCaller(stack_info)
except ValueError:
fn, lno, func = "(unknown file)", 0, "(unknown function)"
else:
@ -1302,7 +1333,8 @@ class Logger(Filterer):
if exc_info:
if not isinstance(exc_info, tuple):
exc_info = sys.exc_info()
record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
record = self.makeRecord(self.name, level, fn, lno, msg, args,
exc_info, func, extra, sinfo)
self.handle(record)
def handle(self, record):
@ -1657,12 +1689,13 @@ def error(msg, *args, **kwargs):
basicConfig()
root.error(msg, *args, **kwargs)
def exception(msg, *args):
def exception(msg, *args, **kwargs):
"""
Log a message with severity 'ERROR' on the root logger,
with exception information.
"""
error(msg, exc_info=1, *args)
kwargs['exc_info'] = True
error(msg, *args, **kwargs)
def warning(msg, *args, **kwargs):
"""

View File

@ -63,6 +63,8 @@ Core and Builtins
Library
-------
- Issue #1553375: logging: Added stack_info kwarg to display stack information.
- Issue #5111: IPv6 Host in the Header is wrapped inside [ ]. Patch by Chandru.
- Fix Fraction.__hash__ so that Fraction.__hash__(-1) is -2. (See also issue