def formatError(self, test, exc_info):
t, v, tb = exc_info
from zope.exceptions.exceptionformatter import format_exception
# Omitting filenames makes things shorter
# and generally more readable, but when the last part of the traceback
# is in initializing a module, then the filename is the only discriminator
lines = format_exception(t, v, tb, with_filenames=self.with_filenames)
if not self.with_filenames and any([str('Module None') in line for line in lines]):
lines = format_exception(t, v, tb, with_filenames=True )
# Note that we are joining with a native string, not a unicode
# string (under py2). Under python2, tracebacks are byte
# strings and mixing unicode at this level may result in
# UnicodeDecodeError, but under python3 tracebacks are unicode
if isinstance(str(''), bytes):
# Python 2. Preemptively get everything to bytes.
# Most terminals and files can handle UTF-8
lines = [l.encode('utf-8','replace') if isinstance(l,unicode) else l for l in lines]
else:
# Python 3. Get everything native
lines = [l.decode('utf-8','replace') if isinstance(l,bytes) else l for l in lines]
formatted_tb = str('').join( lines )
# Returning none for the traceback is what lets us trump
# the earlier plugins. Otherwise we end up with
# multiple copies
return (t, formatted_tb, None)
def test_format_exception_as_html(self):
# Test for format_exception (as_html=True)
from zope.exceptions.exceptionformatter import format_exception
from textwrap import dedent
import re
try:
exec('import')
except SyntaxError:
result = ''.join(format_exception(*sys.exc_info(), as_html=True))
expected = dedent("""\
<p>Traceback (most recent call last):</p>
<ul>
<li> Module {module}, line ABC, in {fn}<br />
exec('import')</li>
</ul><p> File "<string>", line 1<br />
import<br />
^<br />
SyntaxError: invalid syntax<br />
</p>""").format(
module='zope.exceptions.tests.test_exceptionformatter',
fn='test_format_exception_as_html',
)
if IS_PY39_OR_GREATER: # pragma: no cover
# Python 3.9 moves the pointer after the statement instead to the
# last character of it:
expected = expected.replace('^<br />', ' ^<br />')
# HTML formatter uses Windows line endings for some reason.
result = result.replace('\r\n', '\n')
result = re.sub(r'line \d\d\d,', 'line ABC,', result)
self.maxDiff = None
self.assertEqual(expected, result)
def _callFUT(self, as_html=False):
from zope.exceptions.exceptionformatter import format_exception
t, v, b = sys.exc_info()
try:
return ''.join(format_exception(t, v, b, as_html=as_html))
finally:
del b
def _callFUT(self, as_html=False):
from zope.exceptions.exceptionformatter import format_exception
t, v, b = sys.exc_info()
try:
return ''.join(format_exception(t, v, b, as_html=as_html))
finally:
del b
def handleException(self, exc_info):
# only legacy Exception where we didn't define a view for get handled
# by this method. All exceptions where we have a view registered for
# get handled by the setResult method based on the given
# IJSONRPCErrorView
logger.log(logging.ERROR, "".join(format_exception(
exc_info[0], exc_info[1], exc_info[2], with_filenames=True)))
t, value = exc_info[:2]
s = '%s: %s' % (getattr(t, '__name__', t), value)
if self._request.jsonVersion == "1.0":
wrapper = {'result': None,
'error': s,
'id': self._request.jsonId}
elif self._request.jsonVersion == "1.1":
wrapper = {'version': self._request.jsonVersion,
'error': s,
'id': self._request.jsonId}
else:
# this only happens if error handling was running into en error or
# if we didn't define an IJSONRPCErrorView for a given error
wrapper = {'jsonrpc': self._request.jsonVersion,
'error': {'code': -32603,
'message': 'Internal error',
'data': s},
'id': self._request.jsonId}
json = zope.component.getUtility(IJSONWriter)
result = json.write(wrapper)
body = self._prepareResult(result)
super(JSONRPCResponse, self).setResult(DirectResult((body,)))
logger.log(DEBUG, "Exception: %s" % result)
self.setStatus(200)
def test_ErrorLog_unicode(self):
# Emulate a unicode url, it gets encoded to utf-8 before it's passed
# to the request. Also add some unicode field to the request's
# environment and make the principal's title unicode.
request = TestRequest(environ={'PATH_INFO': '/\xd1\x82',
'SOME_UNICODE': u'\u0441'})
class PrincipalStub(object):
id = u'\u0441'
title = u'\u0441'
description = u'\u0441'
request.setPrincipal(PrincipalStub())
errUtility = ErrorReportingUtility()
exc_info = getAnErrorInfo(u"Error (\u0441)")
errUtility.raising(exc_info, request=request)
getErrLog = errUtility.getLogEntries()
self.assertEquals(1, len(getErrLog))
tb_text = ''.join(format_exception(as_html=0, *exc_info))
err_id = getErrLog[0]['id']
self.assertEquals(tb_text,
errUtility.getLogEntryById(err_id)['tb_text'])
username = getErrLog[0]['username']
self.assertEquals(username, u'unauthenticated, \u0441, \u0441, \u0441')
def getFormattedException(info, as_html=False):
lines = []
for line in format_exception(as_html=as_html, *info):
line = getPrintable(line, as_html=as_html)
if not line.endswith("\n"):
line += "<br />\n" if as_html else "\n"
lines.append(line)
return u"".join(lines)
def getFormattedException(info, as_html=False):
lines = []
for line in format_exception(as_html=as_html, *info):
line = getPrintable(line)
if not line.endswith("\n"):
if not as_html:
line += "\n"
else:
line += "<br />\n"
lines.append(line)
return u"".join(lines)
def test_ErrorLog(self):
# Test for Logging Error. Create one error and check whether its
# logged or not.
errUtility = ErrorReportingUtility()
exc_info = getAnErrorInfo()
errUtility.raising(exc_info)
getErrLog = errUtility.getLogEntries()
self.assertEquals(1, len(getErrLog))
tb_text = ''.join(format_exception(as_html=0, *exc_info))
err_id = getErrLog[0]['id']
self.assertEquals(tb_text,
errUtility.getLogEntryById(err_id)['tb_text'])
def test_ErrorLog(self):
# Test for Logging Error. Create one error and check whether its
# logged or not.
errUtility = ErrorReportingUtility()
exc_info = getAnErrorInfo()
errUtility.raising(exc_info)
getErrLog = errUtility.getLogEntries()
self.assertEquals(1, len(getErrLog))
tb_text = ''.join(format_exception(as_html=0, *exc_info))
err_id = getErrLog[0]['id']
self.assertEquals(tb_text,
errUtility.getLogEntryById(err_id)['tb_text'])
def __init__(self, context, request):
self.context = context
self.request = request
self.error_type, self.error_object, tb = info = sys.exc_info()
try:
strtype = str(getattr(info[0], '__name__', info[0]))
if not isinstance(info[2], StringTypes):
self.tb_text = ''.join(
format_exception(*info, **{'as_html': 0}))
self.tb_html = ''.join(
format_exception(*info, **{'as_html': 1}))
else:
self.tb_text = info[2]
except:
try:
self.tb_lines = traceback.format_tb(tb)
finally:
del tb
info = None
def computeDebugOutput(self):
"""Inspect the exception, and set up instance attributes.
self.error_type
self.error_object
self.traceback_lines
self.htmltext
"""
self.error_type, self.error_object, tb = sys.exc_info()
try:
self.traceback_lines = traceback.format_tb(tb)
self.htmltext = '\n'.join(
format_exception(self.error_type, self.error_object,
tb, as_html=True)
)
finally:
del tb
def computeDebugOutput(self):
"""Inspect the exception, and set up instance attributes.
self.error_type
self.error_object
self.traceback_lines
self.htmltext
"""
self.error_type, self.error_object, tb = sys.exc_info()
try:
self.traceback_lines = traceback.format_tb(tb)
self.htmltext = '\n'.join(
format_exception(self.error_type, self.error_object,
tb, as_html=True)
)
finally:
del tb
def renderSETUP(self):
data = {}
fixtures = self.get_fixtures()
try:
for fixture_name in self.fixtures:
__traceback_info__ = (fixture_name, data)
fixtures[fixture_name](self.request, data)
except EXPLOSIVE_ERRORS:
raise
except:
self.request.response.setStatus(500)
result = ''.join(format_exception(*sys.exc_info()))
else:
self.request.response.setHeader('Content-Type', 'application/json')
# We use the ProxyFactory so that the restful
# redaction code is always used.
result = simplejson.dumps(ProxyFactory(data),
cls=ResourceJSONEncoder)
return result
def _abort_on_exception(self, exc_info, retryable, number, tx):
e = exc_info[0]
try:
_timing(transaction.abort, 'transaction.abort') # note: NOT our tx variable, whatever is current
logger.debug("Transaction aborted; retrying %s/%s; '%s'/%r",
retryable, number, e, e)
except (AttributeError, ValueError):
try:
logger.exception("Failed to abort transaction following exception "
"(retrying %s/%s; '%s'/%r). New exception:",
retryable, number, e, e)
except: # pylint:disable=I0011,W0702
pass
# We've seen RelStorage do this:
# relstorage.cache:427 in after_poll: AttributeError: 'int' object has no attribute 'split' which looks like
# an issue with how it stores checkpoints in memcache.
# We have no idea what state it's in after that, so we should
# abort.
# We've seen repoze.sendmail do this:
# repoze.sendmail.delivery:119 in abort: ValueError "TPC in progress"
# This appears to happen due to some other component raising an exception
# after the call to commit has begun, and some exception slips through
# such that, instead of calling `tpc_abort`, the stack unwinds.
# The sendmail object appears to have been `tpc_begin`, but not
# `tpc_vote`. (This may happen if the original exception was a ReadConflictError?)
# https://github.com/repoze/repoze.sendmail/issues/31 (introduced in 4.2)
# Again, no idea what state things are in, so abort with prejudice.
try:
if format_exception:
fmt = format_exception(*exc_info)
logger.warning("Failed to abort transaction following exception. Original exception:\n%s",
'\n'.join(fmt))
except: # pylint:disable=I0011,W0702
exc_info = sys.exc_info()
self.__free(tx); del tx
try:
six.reraise(AbortFailedError, None, exc_info[2])
finally:
del exc_info
del e
def _abort_on_exception(self, exc_info, retryable, number, tx):
e = exc_info[0]
try:
_timing(transaction.abort, 'transaction.abort') # note: NOT our tx variable, whatever is current
logger.debug("Transaction aborted; retrying %s/%s; '%s'/%r",
retryable, number, e, e)
except (AttributeError, ValueError):
try:
logger.exception("Failed to abort transaction following exception "
"(retrying %s/%s; '%s'/%r). New exception:",
retryable, number, e, e)
except: # pylint:disable=I0011,W0702
pass
# We've seen RelStorage do this:
# relstorage.cache:427 in after_poll: AttributeError: 'int' object has no attribute 'split' which looks like
# an issue with how it stores checkpoints in memcache.
# We have no idea what state it's in after that, so we should
# abort.
# We've seen repoze.sendmail do this:
# repoze.sendmail.delivery:119 in abort: ValueError "TPC in progress"
# This appears to happen due to some other component raising an exception
# after the call to commit has begun, and some exception slips through
# such that, instead of calling `tpc_abort`, the stack unwinds.
# The sendmail object appears to have been `tpc_begin`, but not
# `tpc_vote`. (This may happen if the original exception was a ReadConflictError?)
# https://github.com/repoze/repoze.sendmail/issues/31 (introduced in 4.2)
# Again, no idea what state things are in, so abort with prejudice.
try:
if format_exception is not None:
fmt = format_exception(*exc_info)
logger.warning("Failed to abort transaction following exception. Original exception:\n%s",
'\n'.join(fmt))
except: # pylint:disable=I0011,W0702
exc_info = sys.exc_info()
self.__free(tx); del tx
six.reraise(AbortFailedError, AbortFailedError(repr(exc_info)), exc_info[2])
finally:
del exc_info
del e
def attach_exc_info(report, context):
"""Attach exception info to the report.
This reads the 'exc_info' key from the context and sets the:
* type
* value
* tb_text
keys in the report.
"""
info = context.get('exc_info')
if info is None:
return
report['type'] = getattr(info[0], '__name__', info[0])
report['value'] = oops.createhooks.safe_unicode(info[1])
if not isinstance(info[2], basestring):
tb_text = ''.join(format_exception(*info, **{'as_html': False}))
else:
tb_text = info[2]
report['tb_text'] = tb_text
def attach_exc_info(report, context):
"""Attach exception info to the report.
This reads the 'exc_info' key from the context and sets the:
* type
* value
* tb_text
keys in the report.
"""
info = context.get('exc_info')
if info is None:
return
report['type'] = getattr(info[0], '__name__', info[0])
report['value'] = oops.createhooks.safe_unicode(info[1])
if not isinstance(info[2], basestring):
tb_text = ''.join(format_exception(*info,
**{'as_html': False}))
else:
tb_text = info[2]
report['tb_text'] = tb_text
def renderTEARDOWN(self):
data = simplejson.loads(self.request.form['data'])
fixtures = self.get_fixtures()
try:
for fixture_name in reversed(self.fixtures):
__traceback_info__ = (fixture_name, data)
fixtures[fixture_name].teardown(self.request, data)
except EXPLOSIVE_ERRORS:
raise
except:
self.request.response.setStatus(500)
result = ''.join(format_exception(*sys.exc_info()))
else:
# Remove the session cookie, in case we have one.
self.request.response.expireCookie(
getUtility(IClientIdManager).namespace)
# Blow up the database once we are out of this transaction
# by passing a result that will do so when it is iterated
# through in asyncore.
self.request.response.setHeader('Content-Length', 1)
result = CloseDbResult()
return result
def test_format_exception_as_html(self):
# Test for format_exception (as_html=True)
from zope.exceptions.exceptionformatter import format_exception
from textwrap import dedent
import re
try:
exec('import')
except SyntaxError:
result = ''.join(format_exception(*sys.exc_info(), as_html=True))
expected = dedent("""\
<p>Traceback (most recent call last):</p>
<ul>
<li> Module zope.exceptions.tests.test_exceptionformatter, line ABC, in test_format_exception_as_html<br />
exec('import')</li>
</ul><p> File "<string>", line 1<br />
import<br />
^<br />
SyntaxError: invalid syntax<br />
</p>""")
# HTML formatter uses Windows line endings for some reason.
result = result.replace('\r\n', '\n')
result = re.sub(r'line \d\d\d,', 'line ABC,', result)
self.maxDiff = None
self.assertEqual(expected, result)
def test_format_exception_as_html(self):
# Test for format_exception (as_html=True)
from zope.exceptions.exceptionformatter import format_exception
from textwrap import dedent
import re
try:
exec('import')
except SyntaxError:
result = ''.join(format_exception(*sys.exc_info(), as_html=True))
expected = dedent("""\
<p>Traceback (most recent call last):</p>
<ul>
<li> Module zope.exceptions.tests.test_exceptionformatter, line ABC, in test_format_exception_as_html<br />
exec('import')</li>
</ul><p> File "<string>", line 1<br />
import<br />
^<br />
SyntaxError: invalid syntax<br />
</p>""")
# HTML formatter uses Windows line endings for some reason.
result = result.replace('\r\n', '\n')
result = re.sub(r'line \d\d\d,', 'line ABC,', result)
self.maxDiff = None
self.assertEqual(expected, result)
def log_exception(msg, exc, tb):
exc_str = '\n'.join(format_exception(exc.__class__, str(exc), tb))
logger.error('%s\n\n%s' % (msg, exc_str))
def tb(as_html=0):
t, v, b = sys.exc_info()
try:
return ''.join(format_exception(t, v, b, as_html=as_html))
finally:
del b
def end_request(event):
"""If profiling is turned on, save profile data for the request."""
try:
if not _profilers.profiling:
return
_profilers.profiling = False
except AttributeError:
# Some tests don't go through all the proper motions, like firing off
# a start request event. Just be quiet about it.
return
actions = _profilers.actions
_profilers.actions = None
request = event.request
# Create a timestamp including milliseconds.
now = datetime.fromtimestamp(da.get_request_start_time())
timestamp = "%s.%d" % (
now.strftime('%Y-%m-%d_%H:%M:%S'), int(now.microsecond / 1000.0))
pageid = request._orig_env.get('launchpad.pageid', 'Unknown')
oopsid = getattr(request, 'oopsid', None)
content_type = request.response.getHeader('content-type')
if content_type is None:
content_type_params = {}
is_html = False
else:
_major, _minor, content_type_params = parse(content_type)
is_html = _major == 'text' and _minor == 'html'
template_context = {
'actions': dict((key, True) for key in actions),
'always_log': config.profiling.profile_all_requests}
dump_path = config.profiling.profile_dir
if _profilers.profiler is not None:
prof_stats = _profilers.profiler.stop()
# Free some memory (at least for the BzrProfiler).
_profilers.profiler = None
if oopsid is None:
# Log an OOPS to get a log of the SQL queries, and other
# useful information, together with the profiling
# information.
info = (ProfilingOops, None, None)
error_utility = getUtility(IErrorReportingUtility)
oops_report = error_utility.raising(info, request)
oopsid = oops_report['id']
else:
oops_report = request.oops
filename = '%s-%s-%s-%s' % (
timestamp, pageid, oopsid,
threading.currentThread().getName())
if 'callgrind' in actions:
# The stats class looks at the filename to know to use
# callgrind syntax.
callgrind_path = os.path.join(
dump_path, 'callgrind.out.' + filename)
prof_stats.save(callgrind_path, callgrind=True)
template_context['callgrind_path'] = os.path.abspath(
callgrind_path)
if 'pstats' in actions:
pstats_path = os.path.join(
dump_path, filename + '.prof')
prof_stats.save(pstats_path)
template_context['pstats_path'] = os.path.abspath(
pstats_path)
if is_html and 'show' in actions:
# Generate rfc822 OOPS result (might be nice to have an html
# serializer..).
template_context['oops'] = ''.join(
oops_datedir_repo.serializer_rfc822.to_chunks(oops_report))
# Generate profile summaries.
prof_stats.strip_dirs()
for name in ('time', 'cumulative', 'calls'):
prof_stats.sort(name)
f = StringIO.StringIO()
prof_stats.pprint(file=f)
template_context[name] = f.getvalue()
template_context['profile_count'] = prof_stats.count
template_context['multiple_profiles'] = prof_stats.count > 1
# Try to free some more memory.
del prof_stats
# Dump memory profiling info.
if 'memory_profile_start' in actions:
log = file(config.profiling.memory_profile_log, 'a')
vss_start, rss_start = actions.pop('memory_profile_start')
vss_end, rss_end = memory(), resident()
if oopsid is None:
oopsid = '-'
log.write('%s %s %s %f %d %d %d %d\n' % (
timestamp, pageid, oopsid, da.get_request_duration(),
vss_start, rss_start, vss_end, rss_end))
log.close()
trace = None
if 'sql' in actions:
trace = da.stop_sql_logging() or ()
# The trace is a list of dicts, each with the keys "sql" and "stack".
# "sql" is a tuple of start time, stop time, database name (with a
# "SQL-" prefix), sql statement and possibly a backtrace (backtraces
# are included when the timeline storm trace is installed). "stack" is
# None or a tuple of filename, line number, function name, text, module
# name, optional supplement dict, and optional info string. The
# supplement dict has keys 'source_url', 'line', 'column',
# 'expression', 'warnings' (an iterable), and 'extra', any of which may
# be None.
top_sql = []
top_python = []
triggers = {}
ix = 1 # We display these, so start at 1, not 0.
last_stop_time = 0
_heappushpop = heapq.heappushpop # This is an optimization.
for step in trace:
# Set up an identifier for each trace step.
step['id'] = ix
step['sql'] = dict(zip(
('start', 'stop', 'name', 'statement', 'backtrace'),
step['sql']))
# NB: step['sql']['backtrace'] is a string backtrace, not a live
# stack: less flexible than what the profiler gathers, but cheaper
# to keep alive as it holds no references. For now, its not usable
# here.
if step['stack'] is not None:
# Divide up the stack into the more unique (app) and less
# unique (db) bits.
app_stack = step['app_stack'] = []
db_stack = step['db_stack'] = []
storm_found = False
for f in step['stack']:
f_data = dict(zip(
('filename', 'lineno', 'name', 'line', 'module',
'supplement', 'info'), f))
storm_found = storm_found or (
f_data['module'] and
f_data['module'].startswith('storm.'))
if storm_found:
db_stack.append(f_data)
else:
app_stack.append(f_data)
# Begin to gather what app code is triggering the most SQL
# calls.
trigger_key = tuple(
(f['filename'], f['lineno']) for f in app_stack)
if trigger_key not in triggers:
triggers[trigger_key] = []
triggers[trigger_key].append(ix)
# Get the nbest (n=10) sql and python times
step['python_time'] = step['sql']['start'] - last_stop_time
step['sql_time'] = step['sql']['stop'] - step['sql']['start']
python_data = (step['python_time'], ix, step)
sql_data = (step['sql_time'], ix, step)
if ix < 10:
top_sql.append(sql_data)
top_python.append(python_data)
else:
if ix == 10:
heapq.heapify(top_sql)
heapq.heapify(top_python)
_heappushpop(top_sql, sql_data)
_heappushpop(top_python, python_data)
# Reset for next loop.
last_stop_time = step['sql']['stop']
ix += 1
# Finish setting up top sql and python times.
top_sql.sort(reverse=True)
top_python.sort(reverse=True)
top_sql_ids = []
for rank, (key, ix, step) in enumerate(top_sql):
step['sql_rank'] = rank + 1
step['sql_class'] = (
'sql_danger' if key > 500 else
'sql_warning' if key > 100 else None)
top_sql_ids.append(dict(
value=key,
ix=ix,
rank=step['sql_rank'],
cls=step['sql_class']))
top_python_ids = []
for rank, (key, ix, step) in enumerate(top_python):
step['python_rank'] = rank + 1
step['python_class'] = (
'python_danger' if key > 500 else
'python_warning' if key > 100 else None)
top_python_ids.append(dict(
value=key,
ix=ix,
rank=step['python_rank'],
cls=step['python_class']))
# Identify the repeated Python calls that generated SQL.
triggers = triggers.items()
triggers.sort(key=lambda x: len(x[1]))
triggers.reverse()
top_triggers = []
for (key, ixs) in triggers:
if len(ixs) == 1:
break
info = trace[ixs[0] - 1]['app_stack'][-1].copy()
info['indexes'] = ixs
info['count'] = len(ixs)
top_triggers.append(info)
template_context.update(dict(
sqltrace=trace,
top_sql=top_sql_ids,
top_python=top_python_ids,
top_triggers=top_triggers,
sql_count=len(trace)))
if actions['sql'] is True:
template_context['sql_traceback_all'] = True
elif actions['sql'] is False:
template_context['sql_traceback_none'] = True
else:
conditions = actions['sql'].copy()
del conditions['condition']
template_context['sql_traceback_conditions'] = conditions
template_context['dump_path'] = os.path.abspath(dump_path)
if actions and is_html:
# Hack the new HTML in at the end of the page.
encoding = content_type_params.get('charset', 'utf-8')
try:
added_html = template(**template_context).encode(encoding)
except (SystemExit, KeyboardInterrupt):
raise
except:
error = ''.join(format_exception(*sys.exc_info(), as_html=True))
added_html = (
'<div class="profiling_info">' + error + '</div>')
existing_html = request.response.consumeBody()
e_start, e_close_body, e_end = existing_html.rpartition(
'</body>')
new_html = ''.join(
(e_start, added_html, e_close_body, e_end))
request.response.setResult(new_html)
