diff --git a/vcsserver/base.py b/vcsserver/base.py --- a/vcsserver/base.py +++ b/vcsserver/base.py @@ -17,7 +17,6 @@ import os import sys import tempfile -import traceback import logging import urllib.parse @@ -27,7 +26,7 @@ from vcsserver import exceptions from vcsserver.exceptions import NoContentException from vcsserver.hgcompat import archival from vcsserver.str_utils import safe_bytes - +from vcsserver.lib.exc_tracking import format_exc log = logging.getLogger(__name__) @@ -72,12 +71,12 @@ def raise_from_original(new_type, org_ex """ Raise a new exception type with original args and traceback. """ - - exc_type, exc_value, exc_traceback = sys.exc_info() + exc_info = sys.exc_info() + exc_type, exc_value, exc_traceback = exc_info new_exc = new_type(*exc_value.args) # store the original traceback into the new exc - new_exc._org_exc_tb = traceback.format_tb(exc_traceback) + new_exc._org_exc_tb = format_exc(exc_info) try: raise new_exc.with_traceback(exc_traceback) diff --git a/vcsserver/http_main.py b/vcsserver/http_main.py --- a/vcsserver/http_main.py +++ b/vcsserver/http_main.py @@ -23,7 +23,6 @@ import logging import uuid import time import wsgiref.util -import traceback import tempfile import psutil @@ -62,7 +61,7 @@ from vcsserver.git_lfs.app import GIT_LF from vcsserver.echo_stub import remote_wsgi as remote_wsgi_stub from vcsserver.echo_stub.echo_app import EchoApp from vcsserver.exceptions import HTTPRepoLocked, HTTPRepoBranchProtected -from vcsserver.lib.exc_tracking import store_exception +from vcsserver.lib.exc_tracking import store_exception, format_exc from vcsserver.server import VcsServer strict_vcs = True @@ -410,8 +409,7 @@ class HTTPApplication(object): if should_store_exc: store_exception(id(exc_info), exc_info, request_path=request.path) - tb_info = ''.join( - traceback.format_exception(exc_type, exc_value, exc_traceback)) + tb_info = format_exc(exc_info) type_ = e.__class__.__name__ if type_ not in self.ALLOWED_EXCEPTIONS: @@ -669,11 +667,10 @@ class HTTPApplication(object): traceback_info = 'unavailable' if request.exc_info: - exc_type, exc_value, exc_tb = request.exc_info - traceback_info = ''.join(traceback.format_exception(exc_type, exc_value, exc_tb)) + traceback_info = format_exc(request.exc_info) log.error( - 'error occurred handling this request for path: %s, \n tb: %s', + 'error occurred handling this request for path: %s, \n%s', request.path, traceback_info) statsd = request.registry.statsd diff --git a/vcsserver/lib/exc_tracking.py b/vcsserver/lib/exc_tracking.py --- a/vcsserver/lib/exc_tracking.py +++ b/vcsserver/lib/exc_tracking.py @@ -18,11 +18,13 @@ import os import time +import sys import datetime import msgpack import logging import traceback import tempfile +import glob log = logging.getLogger(__name__) @@ -31,7 +33,7 @@ global_prefix = 'vcsserver' exc_store_dir_name = 'rc_exception_store_v1' -def exc_serialize(exc_id, tb, exc_type): +def exc_serialize(exc_id, tb, exc_type, extra_data=None): data = { 'version': 'v1', @@ -41,6 +43,8 @@ def exc_serialize(exc_id, tb, exc_type): 'exc_message': tb, 'exc_type': exc_type, } + if extra_data: + data.update(extra_data) return msgpack.packb(data), data @@ -48,10 +52,19 @@ def exc_unserialize(tb): return msgpack.unpackb(tb) +_exc_store = None + + def get_exc_store(): """ Get and create exception store if it's not existing """ + global _exc_store + + if _exc_store is not None: + # quick global cache + return _exc_store + import vcsserver as app exc_store_dir = app.CONFIG.get('exception_tracker.store_path', '') or tempfile.gettempdir() @@ -61,36 +74,114 @@ def get_exc_store(): if not os.path.isdir(_exc_store_path): os.makedirs(_exc_store_path) log.debug('Initializing exceptions store at %s', _exc_store_path) + _exc_store = _exc_store_path + return _exc_store_path -def _store_exception(exc_id, exc_info, prefix, request_path=''): - exc_type, exc_value, exc_traceback = exc_info +def get_detailed_tb(exc_info): + from io import StringIO + + try: + from pip._vendor.rich import traceback as rich_tb, scope as rich_scope, console as rich_console + except ImportError: + try: + from rich import traceback as rich_tb, scope as rich_scope, console as rich_console + except ImportError: + return None + + console = rich_console.Console( + width=160, + file=StringIO() + ) + + exc = rich_tb.Traceback.extract(*exc_info, show_locals=True) + + tb_rich = rich_tb.Traceback( + trace=exc, + width=160, + extra_lines=3, + theme=None, + word_wrap=False, + show_locals=False, + max_frames=100 + ) + + formatted_locals = "" - tb = ''.join(traceback.format_exception( - exc_type, exc_value, exc_traceback, None)) + # last_stack = exc.stacks[-1] + # last_frame = last_stack.frames[-1] + # if last_frame and last_frame.locals: + # console.print( + # rich_scope.render_scope( + # last_frame.locals, + # title=f'{last_frame.filename}:{last_frame.lineno}')) + + console.print(tb_rich) + formatted_locals = console.file.getvalue() + + return formatted_locals + - detailed_tb = getattr(exc_value, '_org_exc_tb', None) +def get_request_metadata(request=None) -> dict: + request_metadata = {} + if not request: + from pyramid.threadlocal import get_current_request + request = get_current_request() + # NOTE(marcink): store request information into exc_data + if request: + request_metadata['client_address'] = getattr(request, 'client_addr', '') + request_metadata['user_agent'] = getattr(request, 'user_agent', '') + request_metadata['method'] = getattr(request, 'method', '') + request_metadata['url'] = getattr(request, 'url', '') + return request_metadata + + +def format_exc(exc_info): + exc_type, exc_value, exc_traceback = exc_info + tb = "++ TRACEBACK ++\n\n" + tb += "".join(traceback.format_exception(exc_type, exc_value, exc_traceback, None)) + + detailed_tb = getattr(exc_value, "_org_exc_tb", None) + if detailed_tb: remote_tb = detailed_tb if isinstance(detailed_tb, str): remote_tb = [detailed_tb] - + tb += ( - '\n+++ BEG SOURCE EXCEPTION +++\n\n' - '{}\n' - '+++ END SOURCE EXCEPTION +++\n' - ''.format('\n'.join(remote_tb)) + "\n+++ BEG SOURCE EXCEPTION +++\n\n" + "{}\n" + "+++ END SOURCE EXCEPTION +++\n" + "".format("\n".join(remote_tb)) ) - + # Avoid that remote_tb also appears in the frame del remote_tb + + locals_tb = get_detailed_tb(exc_info) + if locals_tb: + tb += f"\n+++ DETAILS +++\n\n{locals_tb}\n" "" + return tb + + +def _store_exception(exc_id, exc_info, prefix, request_path=''): + """ + Low level function to store exception in the exception tracker + """ + + extra_data = {} + extra_data.update(get_request_metadata()) + + exc_type, exc_value, exc_traceback = exc_info + tb = format_exc(exc_info) exc_type_name = exc_type.__name__ + exc_data, org_data = exc_serialize(exc_id, tb, exc_type_name, extra_data=extra_data) + + exc_pref_id = '{}_{}_{}'.format(exc_id, prefix, org_data['exc_timestamp']) exc_store_path = get_exc_store() - exc_data, org_data = exc_serialize(exc_id, tb, exc_type_name) - exc_pref_id = '{}_{}_{}'.format(exc_id, prefix, org_data['exc_timestamp']) if not os.path.isdir(exc_store_path): os.makedirs(exc_store_path) stored_exc_path = os.path.join(exc_store_path, exc_pref_id) @@ -100,7 +191,7 @@ def _store_exception(exc_id, exc_info, p log.error( 'error occurred handling this request.\n' - 'Path: `%s`, tb: %s', + 'Path: `%s`, %s', request_path, tb) @@ -113,8 +204,12 @@ def store_exception(exc_id, exc_info, pr """ try: + exc_type = exc_info[0] + exc_type_name = exc_type.__name__ + _store_exception(exc_id=exc_id, exc_info=exc_info, prefix=prefix, request_path=request_path) + return exc_id, exc_type_name except Exception: log.exception('Failed to store exception `%s` information', exc_id) # there's no way this can fail, it will crash server badly if it does. @@ -129,16 +224,12 @@ def _find_exc_file(exc_id, prefix=global # search without a prefix exc_id = f'{exc_id}' - # we need to search the store for such start pattern as above - for fname in os.listdir(exc_store_path): - if fname.startswith(exc_id): - exc_id = os.path.join(exc_store_path, fname) - break - continue - else: - exc_id = None + found_exc_id = None + matches = glob.glob(os.path.join(exc_store_path, exc_id) + '*') + if matches: + found_exc_id = matches[0] - return exc_id + return found_exc_id def _read_exception(exc_id, prefix): @@ -170,3 +261,7 @@ def delete_exception(exc_id, prefix=glob log.exception('Failed to remove exception `%s` information', exc_id) # there's no way this can fail, it will crash server badly if it does. pass + + +def generate_id(): + return id(object()) diff --git a/vcsserver/remote/hg.py b/vcsserver/remote/hg.py --- a/vcsserver/remote/hg.py +++ b/vcsserver/remote/hg.py @@ -18,9 +18,9 @@ import binascii import io import logging import stat +import sys import urllib.request import urllib.parse -import traceback import hashlib from hgext import largefiles, rebase, purge @@ -33,19 +33,54 @@ from mercurial.error import AmbiguousPre import vcsserver from vcsserver import exceptions -from vcsserver.base import RepoFactory, obfuscate_qs, raise_from_original, store_archive_in_cache, ArchiveNode, BytesEnvelope, \ - BinaryEnvelope +from vcsserver.base import ( + RepoFactory, + obfuscate_qs, + raise_from_original, + store_archive_in_cache, + ArchiveNode, + BytesEnvelope, + BinaryEnvelope, +) from vcsserver.hgcompat import ( - archival, bin, clone, config as hgconfig, diffopts, hex, get_ctx, - hg_url as url_parser, httpbasicauthhandler, httpdigestauthhandler, - makepeer, instance, match, memctx, exchange, memfilectx, nullrev, hg_merge, - patch, peer, revrange, ui, hg_tag, Abort, LookupError, RepoError, - RepoLookupError, InterventionRequired, RequirementError, - alwaysmatcher, patternmatcher, hgutil, hgext_strip) + archival, + bin, + clone, + config as hgconfig, + diffopts, + hex, + get_ctx, + hg_url as url_parser, + httpbasicauthhandler, + httpdigestauthhandler, + makepeer, + instance, + match, + memctx, + exchange, + memfilectx, + nullrev, + hg_merge, + patch, + peer, + revrange, + ui, + hg_tag, + Abort, + LookupError, + RepoError, + RepoLookupError, + InterventionRequired, + RequirementError, + alwaysmatcher, + patternmatcher, + hgutil, + hgext_strip, +) from vcsserver.str_utils import ascii_bytes, ascii_str, safe_str, safe_bytes from vcsserver.vcs_base import RemoteBase from vcsserver.config import hooks as hooks_config - +from vcsserver.lib.exc_tracking import format_exc log = logging.getLogger(__name__) @@ -736,15 +771,15 @@ class HgRemote(RemoteBase): rev = rev + -1 try: ctx = self._get_ctx(repo, rev) - except (AmbiguousPrefixLookupError) as e: + except AmbiguousPrefixLookupError: e = RepoLookupError(rev) - e._org_exc_tb = traceback.format_exc() + e._org_exc_tb = format_exc(sys.exc_info()) raise exceptions.LookupException(e)(rev) except (TypeError, RepoLookupError, binascii.Error) as e: - e._org_exc_tb = traceback.format_exc() + e._org_exc_tb = format_exc(sys.exc_info()) raise exceptions.LookupException(e)(rev) except LookupError as e: - e._org_exc_tb = traceback.format_exc() + e._org_exc_tb = format_exc(sys.exc_info()) raise exceptions.LookupException(e)(e.name) if not both: