[IMP] rest_log: track exec_time

rest_log/components/service.py

@@ -5,6 +5,7 @@
 
 import json
 import logging
+import time
 import traceback
 
 from psycopg2.errors import OperationalError
@@ -44,6 +45,7 @@ def dispatch(self, method_name, *args, params=None):
         return self._dispatch_with_db_logging(method_name, *args, params=params)
 
     def _dispatch_with_db_logging(self, method_name, *args, params=None):
+        start_time = time.time()
         try:
             with self.env.cr.savepoint():
                 result = super().dispatch(method_name, *args, params=params)
@@ -54,6 +56,7 @@ def _dispatch_with_db_logging(self, method_name, *args, params=None):
                 orig_exception,
                 *args,
                 params=params,
+                exec_time=time.time() - start_time,
             )
         except exceptions.ValidationError as orig_exception:
             self._dispatch_exception(
@@ -62,6 +65,7 @@ def _dispatch_with_db_logging(self, method_name, *args, params=None):
                 orig_exception,
                 *args,
                 params=params,
+                exec_time=time.time() - start_time,
             )
         except exceptions.UserError as orig_exception:
             self._dispatch_exception(
@@ -70,6 +74,7 @@ def _dispatch_with_db_logging(self, method_name, *args, params=None):
                 orig_exception,
                 *args,
                 params=params,
+                exec_time=time.time() - start_time,
             )
         except Exception as orig_exception:
             self._dispatch_exception(
@@ -78,15 +83,26 @@ def _dispatch_with_db_logging(self, method_name, *args, params=None):
                 orig_exception,
                 *args,
                 params=params,
+                exec_time=time.time() - start_time,
             )
-        self._log_dispatch_success(method_name, result, *args, params)
+        self._log_dispatch_success(
+            method_name, result, *args, params, exec_time=time.time() - start_time
+        )
         return result
 
-    def _log_dispatch_success(self, method_name, result, *args, params=None):
+    def _log_dispatch_success(
+        self, method_name, result, *args, params=None, exec_time=None
+    ):
         try:
             with self.env.cr.savepoint():
                 log_entry = self._log_call_in_db(
-                    self.env, request, method_name, *args, params, result=result
+                    self.env,
+                    request,
+                    method_name,
+                    *args,
+                    params,
+                    result=result,
+                    exec_time=exec_time,
                 )
                 if log_entry and not isinstance(result, Response):
                     log_entry_url = self._get_log_entry_url(log_entry)
@@ -95,7 +111,13 @@ def _log_dispatch_success(self, method_name, result, *args, params=None):
             _logger.exception("Rest Log Error Creation: %s", e)
 
     def _dispatch_exception(
-        self, method_name, exception_klass, orig_exception, *args, params=None
+        self,
+        method_name,
+        exception_klass,
+        orig_exception,
+        *args,
+        params=None,
+        exec_time=None,
     ):
         exc_msg, log_entry_url = None, None  # in case it fails below
         try:
@@ -110,6 +132,7 @@ def _dispatch_exception(
                     params=params,
                     traceback=tb,
                     orig_exception=orig_exception,
+                    exec_time=exec_time,
                 )
                 log_entry_url = self._get_log_entry_url(log_entry)
         except Exception as e:
@@ -165,6 +188,7 @@ def _log_call_in_db_values(self, _request, *args, params=None, **kw):
             "exception_name": exception_name,
             "exception_message": exception_message,
             "state": state,
+            "exec_time": kw.get("exec_time"),
         }
 
     def _log_call_prepare_result(self, result):

rest_log/models/rest_log.py

@@ -39,6 +39,12 @@ class RESTLog(models.Model):
     state = fields.Selection(
         selection=[("success", "Success"), ("failed", "Failed")], readonly=True
     )
+    exec_time = fields.Float(
+        readonly=True,
+        string="Exec time (s)",
+        help="Time spent (in seconds) to dispatch the request.",
+        aggregator="avg",
+    )
     severity = fields.Selection(
         selection=[
             ("functional", "Functional"),

rest_log/tests/test_db_logging.py

@@ -2,6 +2,7 @@
 # License LGPL-3.0 or later (http://www.gnu.org/licenses/lgpl.html).
 # from urllib.parse import urlparse
 import json
+import time
 from unittest import mock
 
 from odoo import exceptions
@@ -88,6 +89,39 @@ def test_log_entry(self):
         self.assertIn("log_entry_url", resp)
         self.assertTrue(self.log_model.search_count([]) > log_entry_count)
 
+    def test_log_entry_exec_time_success(self):
+        delay = 0.2
+        original_get = self.service.get
+
+        def _delayed_get(*args, **kwargs):
+            time.sleep(delay)
+            return original_get(*args, **kwargs)
+
+        with (
+            self._get_mocked_request(),
+            mock.patch.object(self.service, "get", side_effect=_delayed_get),
+        ):
+            self.service.dispatch("get", 100)
+        entry = self.log_model.search([], order="id desc", limit=1)
+        self.assertGreaterEqual(entry.exec_time, delay)
+
+    def test_log_entry_exec_time_failed(self):
+        delay = 0.2
+        original_fail = self.service.fail
+
+        def _delayed_fail(*args, **kwargs):
+            time.sleep(delay)
+            return original_fail(*args, **kwargs)
+
+        with (
+            self._get_mocked_request(),
+            mock.patch.object(self.service, "fail", side_effect=_delayed_fail),
+            self.assertRaises(Exception),
+        ):
+            self.service.dispatch("fail", "value")
+        entry = self.log_model.search([], order="id desc", limit=1)
+        self.assertGreaterEqual(entry.exec_time, delay)
+
     def test_log_entry_values_success(self):
         params = {"some": "value"}
         kw = {"result": {"data": "worked!"}}

rest_log/views/rest_log_views.xml

@@ -12,6 +12,7 @@
                 <field name="request_method" />
                 <field name="request_url" />
                 <field name="state" />
+                <field name="exec_time" />
                 <field name="exception_name" />
                 <field name="exception_message" />
                 <field name="severity" />
@@ -50,6 +51,7 @@
                         <group>
                             <field name="create_uid" />
                             <field name="create_date" />
+                            <field name="exec_time" />
                         </group>
                     </group>
                     <group string="Parameters" name="parameters">