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)