From b9f000e1f9f460e1e800a6bef381883c3694d9e4 Mon Sep 17 00:00:00 2001 From: Ankush Menat Date: Wed, 28 Jun 2023 10:07:14 +0530 Subject: [PATCH] refactor!: Log 5xx error to error log instead of error snapshot Also move log_error function to right location --- frappe/__init__.py | 37 +----- frappe/app.py | 4 +- frappe/hooks.py | 1 - frappe/utils/error.py | 275 ++++++------------------------------------ 4 files changed, 43 insertions(+), 274 deletions(-) diff --git a/frappe/__init__.py b/frappe/__init__.py index 998d881a13..13e9448109 100644 --- a/frappe/__init__.py +++ b/frappe/__init__.py @@ -2213,41 +2213,6 @@ def logger( ) -def log_error(title=None, message=None, reference_doctype=None, reference_name=None): - """Log error to Error Log""" - # Parameter ALERT: - # the title and message may be swapped - # the better API for this is log_error(title, message), and used in many cases this way - # this hack tries to be smart about whats a title (single line ;-)) and fixes it - - traceback = None - if message: - if "\n" in title: # traceback sent as title - traceback, title = title, message - else: - traceback = message - - title = title or "Error" - traceback = as_unicode(traceback or get_traceback(with_context=True)) - - if not db: - print(f"Failed to log error in db: {title}") - return - - error_log = get_doc( - doctype="Error Log", - error=traceback, - method=title, - reference_doctype=reference_doctype, - reference_name=reference_name, - ) - - if flags.read_only: - error_log.deferred_insert() - else: - return error_log.insert(ignore_permissions=True) - - def get_desk_link(doctype, name): html = ( '{doctype_local} {name}' @@ -2439,6 +2404,8 @@ def validate_and_sanitize_search_inputs(fn): return wrapper +from frappe.utils.error import log_error # noqa: backward compatibility + if _tune_gc: # generational GC gets triggered after certain allocs (g0) which is 700 by default. # This number is quite small for frappe where a single query can potentially create 700+ diff --git a/frappe/app.py b/frappe/app.py index 5113c858a5..1cbdca1361 100644 --- a/frappe/app.py +++ b/frappe/app.py @@ -22,7 +22,7 @@ from frappe import _ from frappe.auth import SAFE_HTTP_METHODS, UNSAFE_HTTP_METHODS, HTTPRequest from frappe.middlewares import StaticDataMiddleware from frappe.utils import cint, get_site_name, sanitize_html -from frappe.utils.error import make_error_snapshot +from frappe.utils.error import log_error_snapshot from frappe.website.serve import get_response local_manager = LocalManager(frappe.local) @@ -346,7 +346,7 @@ def handle_exception(e): frappe.local.login_manager.clear_cookies() if http_status_code >= 500: - make_error_snapshot(e) + log_error_snapshot(e) if return_as_message: response = get_response("message", http_status_code=http_status_code) diff --git a/frappe/hooks.py b/frappe/hooks.py index f160d93ecc..85a28feb39 100644 --- a/frappe/hooks.py +++ b/frappe/hooks.py @@ -214,7 +214,6 @@ scheduler_events = { "hourly": [ "frappe.model.utils.link_count.update_link_count", "frappe.model.utils.user_settings.sync_user_settings", - "frappe.utils.error.collect_error_snapshots", "frappe.desk.page.backups.backups.delete_downloadable_backups", "frappe.deferred_insert.save_to_db", "frappe.desk.form.document_follow.send_hourly_updates", diff --git a/frappe/utils/error.py b/frappe/utils/error.py index a9891cb532..d44bdef47f 100644 --- a/frappe/utils/error.py +++ b/frappe/utils/error.py @@ -1,17 +1,10 @@ # Copyright (c) 2015, Maxwell Morais and contributors # License: MIT. See LICENSE -import datetime import functools import inspect -import json -import linecache -import os -import sys -import traceback import frappe -from frappe.utils import cstr, encode EXCLUDE_EXCEPTIONS = ( frappe.AuthenticationError, @@ -37,194 +30,57 @@ def _is_ldap_exception(e): return False -def make_error_snapshot(exception): - if frappe.conf.disable_error_snapshot: +def log_error( + title=None, message=None, reference_doctype=None, reference_name=None, *, defer_insert=False +): + """Log error to Error Log""" + # Parameter ALERT: + # the title and message may be swapped + # the better API for this is log_error(title, message), and used in many cases this way + # this hack tries to be smart about whats a title (single line ;-)) and fixes it + + traceback = None + if message: + if "\n" in title: # traceback sent as title + traceback, title = title, message + else: + traceback = message + + title = title or "Error" + traceback = frappe.as_unicode(traceback or frappe.get_traceback(with_context=True)) + + if not frappe.db: + print(f"Failed to log error in db: {title}") return + error_log = frappe.get_doc( + doctype="Error Log", + error=traceback, + method=title, + reference_doctype=reference_doctype, + reference_name=reference_name, + ) + + if frappe.flags.read_only or defer_insert: + error_log.deferred_insert() + else: + return error_log.insert(ignore_permissions=True) + + +def log_error_snapshot(exception: Exception): + if isinstance(exception, EXCLUDE_EXCEPTIONS) or _is_ldap_exception(exception): return logger = frappe.logger(with_more_info=True) try: - error_id = "{timestamp:s}-{ip:s}-{hash:s}".format( - timestamp=cstr(datetime.datetime.now()), - ip=frappe.local.request_ip or "127.0.0.1", - hash=frappe.generate_hash(length=3), - ) - snapshot_folder = get_error_snapshot_path() - frappe.create_folder(snapshot_folder) - - snapshot_file_path = os.path.join(snapshot_folder, f"{error_id}.json") - snapshot = get_snapshot(exception) - - with open(encode(snapshot_file_path), "wb") as error_file: - error_file.write(encode(frappe.as_json(snapshot))) - - logger.error(f"New Exception collected with id: {error_id}") - + log_error(title=str(exception), defer_insert=True) + logger.error("New Exception collected in error log") except Exception as e: logger.error(f"Could not take error snapshot: {e}", exc_info=True) -def get_snapshot(exception, context=10): - import pydoc - - """ - Return a dict describing a given traceback (based on cgitb.text) - """ - - etype, evalue, etb = sys.exc_info() - if isinstance(etype, type): - etype = etype.__name__ - - # creates a snapshot dict with some basic information - - s = { - "pyver": "Python {version:s}: {executable:s} (prefix: {prefix:s})".format( - version=sys.version.split(maxsplit=1)[0], executable=sys.executable, prefix=sys.prefix - ), - "timestamp": cstr(datetime.datetime.now()), - "traceback": traceback.format_exc(), - "frames": [], - "etype": cstr(etype), - "evalue": cstr(repr(evalue)), - "exception": {}, - "locals": {}, - } - - # start to process frames - records = inspect.getinnerframes(etb, 5) - - for frame, file, lnum, func, lines, index in records: - file = file and os.path.abspath(file) or "?" - args, varargs, varkw, locals = inspect.getargvalues(frame) - call = "" - - if func != "?": - call = inspect.formatargvalues( - args, varargs, varkw, locals, formatvalue=lambda value: f"={pydoc.text.repr(value)}" - ) - - # basic frame information - f = {"file": file, "func": func, "call": call, "lines": {}, "lnum": lnum} - - def reader(lnum=[lnum]): # noqa - try: - # B023: function is evaluated immediately, binding not necessary - return linecache.getline(file, lnum[0]) # noqa: B023 - finally: - lnum[0] += 1 - - vars = _scanvars(reader, frame, locals) - - # if it is a view, replace with generated code - # if file.endswith('html'): - # lmin = lnum > context and (lnum - context) or 0 - # lmax = lnum + context - # lines = code.split("\n")[lmin:lmax] - # index = min(context, lnum) - 1 - - if index is not None: - i = lnum - index - for line in lines: - f["lines"][i] = line.rstrip() - i += 1 - - # dump local variable (referenced in current line only) - f["dump"] = {} - for name, where, value in vars: - if name in f["dump"]: - continue - if value is not __UNDEF__: - if where == "global": - name = f"global {name:s}" - elif where != "local": - name = where + " " + name.split(".")[-1] - f["dump"][name] = pydoc.text.repr(value) - else: - f["dump"][name] = "undefined" - - s["frames"].append(f) - - # add exception type, value and attributes - if isinstance(evalue, BaseException): - for name in dir(evalue): - if name != "messages" and not name.startswith("__"): - value = pydoc.text.repr(getattr(evalue, name)) - s["exception"][name] = encode(value) - - # add all local values (of last frame) to the snapshot - for name, value in locals.items(): - s["locals"][name] = value if isinstance(value, str) else pydoc.text.repr(value) - - return s - - -def collect_error_snapshots(): - """Scheduled task to collect error snapshots from files and push into Error Snapshot table""" - if frappe.conf.disable_error_snapshot: - return - - try: - path = get_error_snapshot_path() - if not os.path.exists(path): - return - - for fname in os.listdir(path): - fullpath = os.path.join(path, fname) - - try: - with open(fullpath) as filedata: - data = json.load(filedata) - - except ValueError: - # empty file - os.remove(fullpath) - continue - - for field in ["locals", "exception", "frames"]: - data[field] = frappe.as_json(data[field]) - - doc = frappe.new_doc("Error Snapshot") - doc.update(data) - doc.save() - - frappe.db.commit() - - os.remove(fullpath) - - clear_old_snapshots() - - except Exception as e: - make_error_snapshot(e) - - # prevent creation of unlimited error snapshots - raise - - -def clear_old_snapshots(): - """Clear snapshots that are older than a month""" - from frappe.query_builder import DocType, Interval - from frappe.query_builder.functions import Now - - ErrorSnapshot = DocType("Error Snapshot") - frappe.db.delete(ErrorSnapshot, filters=(ErrorSnapshot.creation < (Now() - Interval(months=1)))) - - path = get_error_snapshot_path() - today = datetime.datetime.now() - - for file in os.listdir(path): - p = os.path.join(path, file) - ctime = datetime.datetime.fromtimestamp(os.path.getctime(p)) - if (today - ctime).days > 31: - os.remove(os.path.join(path, p)) - - -def get_error_snapshot_path(): - return frappe.get_site_path("error-snapshots") - - def get_default_args(func): """Get default arguments of a function from its signature.""" signature = inspect.signature(func) @@ -270,56 +126,3 @@ def raise_error_on_no_output(error_message, error_type=None, keep_quiet=None): return wrapper_raise_error_on_no_output return decorator_raise_error_on_no_output - - -# Vendored from cgitb standard library reused under PSF License: -# https://github.com/python/cpython/blob/main/LICENSE - - -import keyword -import tokenize - -__UNDEF__ = [] # a special sentinel object - - -def _scanvars(reader, frame, locals): - """Scan one logical line of Python and look up values of variables used.""" - vars, lasttoken, parent, prefix, value = [], None, None, "", __UNDEF__ - for ttype, token, start, end, line in tokenize.generate_tokens(reader): - if ttype == tokenize.NEWLINE: - break - if ttype == tokenize.NAME and token not in keyword.kwlist: - if lasttoken == ".": - if parent is not __UNDEF__: - value = getattr(parent, token, __UNDEF__) - vars.append((prefix + token, prefix, value)) - else: - where, value = _lookup(token, frame, locals) - vars.append((token, where, value)) - elif token == ".": - prefix += lasttoken + "." - parent = value - else: - parent, prefix = None, "" - lasttoken = token - return vars - - -def _lookup(name, frame, locals): - """Find the value for a given name in the given environment.""" - if name in locals: - return "local", locals[name] - if name in frame.f_globals: - return "global", frame.f_globals[name] - if "__builtins__" in frame.f_globals: - builtins = frame.f_globals["__builtins__"] - if type(builtins) is type({}): # noqa - if name in builtins: - return "builtin", builtins[name] - else: - if hasattr(builtins, name): - return "builtin", getattr(builtins, name) - return None, __UNDEF__ - - -# end: vendored code