Merge pull request #22126 from ankush/trace_sql_queries

feat: basic tracing using monitor trace id

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",

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:

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)

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)

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):

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: