diff --git a/frappe/core/doctype/error_log/error_log.json b/frappe/core/doctype/error_log/error_log.json index 2ee86bd118..a8bb7a57d0 100644 --- a/frappe/core/doctype/error_log/error_log.json +++ b/frappe/core/doctype/error_log/error_log.json @@ -11,7 +11,8 @@ "reference_name", "section_break_5", "method", - "error" + "error", + "trace_id" ], "fields": [ { @@ -57,13 +58,19 @@ { "fieldname": "section_break_5", "fieldtype": "Section Break" + }, + { + "fieldname": "trace_id", + "fieldtype": "Data", + "label": "Trace ID", + "read_only": 1 } ], "icon": "fa fa-warning-sign", "idx": 1, "in_create": 1, "links": [], - "modified": "2022-06-13 06:34:05.158606", + "modified": "2023-08-23 14:20:15.343339", "modified_by": "Administrator", "module": "Core", "name": "Error Log", diff --git a/frappe/core/doctype/error_log/error_log.py b/frappe/core/doctype/error_log/error_log.py index 90f00a1531..09a671638c 100644 --- a/frappe/core/doctype/error_log/error_log.py +++ b/frappe/core/doctype/error_log/error_log.py @@ -21,6 +21,7 @@ class ErrorLog(Document): reference_doctype: DF.Link | None reference_name: DF.Data | None seen: DF.Check + trace_id: DF.Data | None # end: auto-generated types def onload(self): if not self.seen and not frappe.flags.read_only: diff --git a/frappe/database/database.py b/frappe/database/database.py index 61cabc0478..3c42b65e9b 100644 --- a/frappe/database/database.py +++ b/frappe/database/database.py @@ -29,6 +29,7 @@ from frappe.database.utils import ( is_query_type, ) from frappe.exceptions import DoesNotExistError, ImplicitCommitError +from frappe.monitor import get_trace_id from frappe.query_builder.functions import Count from frappe.utils import CallbackManager from frappe.utils import cast as cast_fieldtype @@ -113,6 +114,10 @@ class Database: self.before_rollback = CallbackManager() self.after_rollback = CallbackManager() + self._trace_comment = "" + if trace_id := get_trace_id(): + self._trace_comment = f" /* FRAPPE_TRACE_ID: {trace_id} */" + # self.db_type: str # self.last_query (lazy) attribute of last sql query executed @@ -223,7 +228,9 @@ class Database: values = None elif not isinstance(values, (tuple, dict, list)): values = (values,) + query, values = self._transform_query(query, values) + query += self._trace_comment try: self._cursor.execute(query, values) diff --git a/frappe/monitor.py b/frappe/monitor.py index da2deb859e..9b8f500358 100644 --- a/frappe/monitor.py +++ b/frappe/monitor.py @@ -32,6 +32,12 @@ def add_data_to_monitor(**kwargs) -> None: frappe.local.monitor.add_custom_data(**kwargs) +def get_trace_id() -> str | None: + """Get unique ID for current transaction.""" + if monitor := getattr(frappe.local, "monitor", None): + return monitor.data.uuid + + def log_file(): return os.path.join(frappe.utils.get_bench_path(), "logs", "monitor.json.log") @@ -66,14 +72,16 @@ class Monitor: } ) + if request_id := frappe.request.headers.get("X-Frappe-Request-Id"): + self.data.uuid = request_id + def collect_job_meta(self, method, kwargs): self.data.job = frappe._dict({"method": method, "scheduled": False, "wait": 0}) if "run_scheduled_job" in method: self.data.job.method = kwargs["job_type"] self.data.job.scheduled = True - job = rq.get_current_job() - if job: + if job := rq.get_current_job(): self.data.uuid = job.id waitdiff = self.data.timestamp - job.enqueued_at self.data.job.wait = int(waitdiff.total_seconds() * 1000000) diff --git a/frappe/tests/test_recorder.py b/frappe/tests/test_recorder.py index 71d9b3add5..5349f15dbf 100644 --- a/frappe/tests/test_recorder.py +++ b/frappe/tests/test_recorder.py @@ -100,7 +100,10 @@ class TestRecorder(FrappeTestCase): for query, call in zip(queries, request["calls"]): self.assertEqual( - call["query"], sqlparse.format(query[sql_dialect].strip(), keyword_case="upper", reindent=True) + call["query"], + sqlparse.format( + query[sql_dialect].strip(), keyword_case="upper", reindent=True, strip_comments=True + ), ) def test_duplicate_queries(self): diff --git a/frappe/utils/error.py b/frappe/utils/error.py index a3d39bbe7d..7d4e5c7c16 100644 --- a/frappe/utils/error.py +++ b/frappe/utils/error.py @@ -37,6 +37,8 @@ def log_error( title=None, message=None, reference_doctype=None, reference_name=None, *, defer_insert=False ): """Log error to Error Log""" + from frappe.monitor import get_trace_id + # 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 @@ -62,6 +64,7 @@ def log_error( method=title, reference_doctype=reference_doctype, reference_name=reference_name, + trace_id=get_trace_id(), ) if frappe.flags.read_only or defer_insert: