diff --git a/rest_log/README.rst b/rest_log/README.rst index 78fef2710..646ed95aa 100644 --- a/rest_log/README.rst +++ b/rest_log/README.rst @@ -1,7 +1,3 @@ -.. image:: https://odoo-community.org/readme-banner-image - :target: https://odoo-community.org/get-involved?utm_source=readme - :alt: Odoo Community Association - ======== REST Log ======== @@ -17,7 +13,7 @@ REST Log .. |badge1| image:: https://img.shields.io/badge/maturity-Beta-yellow.png :target: https://odoo-community.org/page/development-status :alt: Beta -.. |badge2| image:: https://img.shields.io/badge/license-LGPL--3-blue.png +.. |badge2| image:: https://img.shields.io/badge/licence-LGPL--3-blue.png :target: http://www.gnu.org/licenses/lgpl-3.0-standalone.html :alt: License: LGPL-3 .. |badge3| image:: https://img.shields.io/badge/github-OCA%2Frest--framework-lightgray.png?logo=github @@ -38,6 +34,10 @@ especially in case of errors. This module add DB logging for REST requests. It also inject in the response the URL of the log entry created. +It can also enable profiling for selected REST endpoints. When profiling +is active, the request execution is wrapped by Odoo's profiler and +results are stored in ``ir_profile``. + NOTE: this feature was implemented initially inside shopfloor app. Up to version 13.0.1.2.1 of this module, if shopfloor is installed, log records will be copied from its table. @@ -88,6 +88,22 @@ In the 2nd case you can set ``rest.log.active`` param as: `collection_name.usage.endpoint` # enable for specific endpoints `collection_name*:state` # enable only for specific state (success, failed) +Profiling +--------- + +Profiling is enabled per endpoint and per user via system parameters: + +- ``rest.log.profiling.conf``: same matching syntax as + ``rest.log.active`` +- ``rest.log.profiling.uid``: comma-separated list of user ids allowed + to profile + +When both parameters match, the request execution is wrapped in Odoo's +profiler and the results are stored in ``ir_profile``. + +``base.profiling_enabled_until`` is only needed to view speedscope +output in the UI. It is not required to record profiles. + Changelog ========= diff --git a/rest_log/components/service.py b/rest_log/components/service.py index 41065dd0b..ab07211a8 100644 --- a/rest_log/components/service.py +++ b/rest_log/components/service.py @@ -14,6 +14,7 @@ from odoo.http import Response, request from odoo.modules.registry import Registry from odoo.service.model import PG_CONCURRENCY_ERRORS_TO_RETRY +from odoo.tools.profiler import Profiler from odoo.addons.base_rest.http import JSONEncoder from odoo.addons.component.core import AbstractComponent @@ -41,6 +42,9 @@ class BaseRESTService(AbstractComponent): def dispatch(self, method_name, *args, params=None): if not self._db_logging_active(method_name): return super().dispatch(method_name, *args, params=params) + if self._start_profiling(method_name): + with self._profiling_get_profiler(method_name): + return self._dispatch_with_db_logging(method_name, *args, params=params) return self._dispatch_with_db_logging(method_name, *args, params=params) def _dispatch_with_db_logging(self, method_name, *args, params=None): @@ -224,3 +228,46 @@ def _get_matching_active_conf(self, method_name): return self.env["rest.log"]._get_matching_active_conf( self._collection, self._usage, method_name ) + + def _start_profiling(self, method_name): + if request.session.profile_session and request.db: + return None + profiling_uids = self._profiling_get_uids() + profiling_conf_match = self._profiling_get_matching_conf(method_name) + res = profiling_conf_match and self.env.uid in profiling_uids + if res: + _logger.info( + "Profiling enabled for uids=%s %s", + str(profiling_uids), + f"{self._collection}.{self._usage}.{method_name}", + ) + return res + + def _profiling_get_uids(self): + try: + param = ( + self.env["ir.config_parameter"] + .sudo() + .get_param("rest.log.profiling.uids", "") + ) + if not param.strip(): + return [] + return [int(x.strip()) for x in param.strip().split(",") if x.strip()] + except ValueError as err: + _logger.warning( + "Cannot get uid from system parameter rest.log.profiling.uid: %s", + str(err), + ) + return [] + + def _profiling_get_matching_conf(self, method_name): + return self.env["rest.log"]._get_matching_conf_from_param( + "rest.log.profiling.conf", self._collection, self._usage, method_name + ) + + def _profiling_get_profiler(self, method_name): + call_name = f"{self._collection}.{self._usage}.{method_name}" + return Profiler( + description=f"REST LOG {call_name}", + profile_session=f"{self.env.user.name} (uid={self.env.uid})", + ) diff --git a/rest_log/models/rest_log.py b/rest_log/models/rest_log.py index 50665c521..e42c0da3f 100644 --- a/rest_log/models/rest_log.py +++ b/rest_log/models/rest_log.py @@ -132,7 +132,10 @@ def autovacuum(self): return True def _get_log_active_param(self): - param = self.env["ir.config_parameter"].sudo().get_param("rest.log.active") + return self._get_log_param("rest.log.active") + + def _get_log_param(self, config_parameter): + param = self.env["ir.config_parameter"].sudo().get_param(config_parameter) return param.strip() if param else "" @tools.ormcache("self._get_log_active_param()") @@ -150,7 +153,11 @@ def _get_log_active_conf(self): :return: mapping by matching key / enabled states """ - param = self._get_log_active_param() + # TODO: Deprecate in favour of _get_log_param + config_param = self._get_log_active_param() + return self._get_conf_from_param_value(config_param) + + def _get_conf_from_param_value(self, param): conf = {} lines = [x.strip() for x in param.split(",") if x.strip()] for line in lines: @@ -169,7 +176,16 @@ def _get_log_active_conf(self): @api.model def _get_matching_active_conf(self, collection, usage, method_name): """Retrieve conf matching current service and method.""" + # TODO: Deprecate in favour of _get_matching_conf_from_param conf = self._get_log_active_conf() + return self._get_matching_conf(conf, collection, usage, method_name) + + def _get_matching_conf_from_param(self, param, collection, usage, method_name): + config_param = self._get_log_param(param) + conf = self._get_conf_from_param_value(config_param) + return self._get_matching_conf(conf, collection, usage, method_name) + + def _get_matching_conf(self, conf, collection, usage, method_name): candidates = ( collection + "." + usage + "." + method_name, collection + "." + usage, diff --git a/rest_log/readme/CONFIGURE.md b/rest_log/readme/CONFIGURE.md index f6d55151a..a78433576 100644 --- a/rest_log/readme/CONFIGURE.md +++ b/rest_log/readme/CONFIGURE.md @@ -30,3 +30,16 @@ In the 2nd case you can set `rest.log.active` param as: `collection_name.usage` # enable for specific endpoints `collection_name.usage.endpoint` # enable for specific endpoints `collection_name*:state` # enable only for specific state (success, failed) + +## Profiling + +Profiling is enabled per endpoint and per user via system parameters: + +- `rest.log.profiling.conf`: same matching syntax as `rest.log.active` +- `rest.log.profiling.uid`: comma-separated list of user ids allowed to profile + +When both parameters match, the request execution is wrapped in Odoo's +profiler and the results are stored in `ir_profile`. + +`base.profiling_enabled_until` is only needed to view speedscope output +in the UI. It is not required to record profiles. diff --git a/rest_log/readme/DESCRIPTION.md b/rest_log/readme/DESCRIPTION.md index 8300876f7..58d6f7c83 100644 --- a/rest_log/readme/DESCRIPTION.md +++ b/rest_log/readme/DESCRIPTION.md @@ -4,6 +4,10 @@ especially in case of errors. This module add DB logging for REST requests. It also inject in the response the URL of the log entry created. +It can also enable profiling for selected REST endpoints. When profiling is +active, the request execution is wrapped by Odoo's profiler and results are +stored in `ir_profile`. + NOTE: this feature was implemented initially inside shopfloor app. Up to version 13.0.1.2.1 of this module, if shopfloor is installed, log records will be copied from its table. diff --git a/rest_log/static/description/index.html b/rest_log/static/description/index.html index 9ce26f3ad..7c32b66c4 100644 --- a/rest_log/static/description/index.html +++ b/rest_log/static/description/index.html @@ -3,7 +3,7 @@ -README.rst +REST Log -
+
+

REST Log

- - -Odoo Community Association - -
-

REST Log

-

Beta License: LGPL-3 OCA/rest-framework Translate me on Weblate Try me on Runboat

+

Beta License: LGPL-3 OCA/rest-framework Translate me on Weblate Try me on Runboat

When exposing REST services is often useful to see what’s happening especially in case of errors.

This module add DB logging for REST requests. It also inject in the response the URL of the log entry created.

+

It can also enable profiling for selected REST endpoints. When profiling +is active, the request execution is wrapped by Odoo’s profiler and +results are stored in ir_profile.

NOTE: this feature was implemented initially inside shopfloor app. Up to version 13.0.1.2.1 of this module, if shopfloor is installed, log records will be copied from its table.

@@ -388,26 +386,27 @@

REST Log

  • Configuration
    • -
  • Changelog
    • -

    Configuration

    +

    Configuration

    -

    Logs retention

    +

    Logs retention

    Logs are kept in database for every REST requests made by a client application. They can be used for debugging and monitoring of the activity.

    @@ -421,7 +420,7 @@

    Logs retention

    error.

    -

    Logs activation

    +

    Logs activation

    You have 2 ways to activate logging:

    • on the service component set _log_calls_in_db = True
      • @@ -436,16 +435,30 @@

      Logs activation

      `collection_name*:state` # enable only for specific state (success, failed)
    +
    +

    Profiling

    +

    Profiling is enabled per endpoint and per user via system parameters:

    +
      +
    • rest.log.profiling.conf: same matching syntax as +rest.log.active
      • +
    • rest.log.profiling.uid: comma-separated list of user ids allowed +to profile
      • +
    +

    When both parameters match, the request execution is wrapped in Odoo’s +profiler and the results are stored in ir_profile.

    +

    base.profiling_enabled_until is only needed to view speedscope +output in the UI. It is not required to record profiles.

    +
    -

    Changelog

    +

    Changelog

    -

    13.0.1.0.0

    +

    13.0.1.0.0

    First official version.

    -

    Bug Tracker

    +

    Bug Tracker

    Bugs are tracked on GitHub Issues. In case of trouble, please check there if your issue has already been reported. If you spotted it first, help us to smash it by providing a detailed and welcomed @@ -453,23 +466,23 @@

    Bug Tracker

    Do not contact contributors directly about support or help with technical issues.

    -

    Credits

    +

    Credits

    -

    Authors

    +

    Authors

    • Camptocamp
    • ACSONE
    -

    Other credits

    +

    Other credits

    Financial support

    -

    Maintainers

    +

    Maintainers

    This module is maintained by the OCA.

    Odoo Community Association @@ -493,6 +506,5 @@

    Maintainers

    -
    diff --git a/rest_log/tests/__init__.py b/rest_log/tests/__init__.py index 40042ac51..6fa21787c 100644 --- a/rest_log/tests/__init__.py +++ b/rest_log/tests/__init__.py @@ -1 +1,2 @@ from . import test_db_logging +from . import test_db_logging_exception diff --git a/rest_log/tests/test_db_logging.py b/rest_log/tests/test_db_logging.py index b7b3ebf85..0d28ddc8d 100644 --- a/rest_log/tests/test_db_logging.py +++ b/rest_log/tests/test_db_logging.py @@ -8,12 +8,9 @@ from odoo.http import Response from odoo.tools import mute_logger -from odoo.addons.base_rest.controllers.main import _PseudoCollection from odoo.addons.base_rest.tests.common import TransactionRestServiceRegistryCase -from odoo.addons.component.tests.common import new_rollbacked_env -from odoo.addons.rest_log import exceptions as log_exceptions # pylint: disable=W7950 -from .common import FakeConcurrentUpdateError, TestDBLoggingMixin +from .common import TestDBLoggingMixin class TestDBLogging(TransactionRestServiceRegistryCase, TestDBLoggingMixin): @@ -278,162 +275,44 @@ def test_log_entry_values_failure_with_response(self): }, ) + def test_start_profiling(self): + with self._get_mocked_request() as mocked_request: + config_param = self.env["ir.config_parameter"].sudo() + config_param.set_param( + "rest.log.profiling.conf", + f"{self.service._collection}.{self.service._usage}.avg_endpoint", + ) + config_param.set_param("rest.log.profiling.uids", str(self.env.uid)) + with self.assertLogs("odoo.addons.rest_log.components.service") as logs: + self.assertTrue(self.service._start_profiling("avg_endpoint")) + self.assertEqual( + logs.output[0], + f"INFO:odoo.addons.rest_log.components.service:" + f"Profiling enabled for uids=[{self.env.uid}] " + "base.rest.test.logmycalls.avg_endpoint", + ) + + config_param.set_param("rest.log.profiling.uids", "99999") + self.assertFalse(self.service._start_profiling("avg_endpoint")) + + mocked_request.session.profile_session = "rest-log-test" + self.assertIsNone(self.service._start_profiling("avg_endpoint")) + + def test_get_profiling_uids(self): + config_param = self.env["ir.config_parameter"].sudo() + with self._get_mocked_request(): + self.assertEqual(self.service._profiling_get_uids(), []) + config_param.set_param("rest.log.profiling.uids", f"{self.env.uid}, 99999") + self.assertEqual(self.service._profiling_get_uids(), [self.env.uid, 99999]) -class TestDBLoggingExceptionBase( - TransactionRestServiceRegistryCase, TestDBLoggingMixin -): - @classmethod - def setUpClass(cls): - super().setUpClass() - cls._setup_registry(cls) - - @classmethod - def tearDownClass(cls): - # pylint: disable=W8110 - cls._teardown_registry(cls) - super().tearDownClass() - - def _test_exception(self, test_type, wrapping_exc, exc_name, severity): - log_model = self.env["rest.log"].sudo() - initial_entries = log_model.search([]) - entry_url_from_exc = None - # Context: we are running in a transaction case which uses savepoints. - # The log machinery is going to rollback the transation when catching errors. - # Hence we need a completely separated env for the service. - with new_rollbacked_env() as new_env: - # Init fake collection w/ new env - collection = _PseudoCollection(self._collection_name, new_env) - service = self._get_service(self, collection=collection) - with self._get_mocked_request(env=new_env): - try: - service.dispatch("fail", test_type) - except Exception as err: - # Not using `assertRaises` to inspect the exception directly - self.assertTrue(isinstance(err, wrapping_exc)) - self.assertEqual( - service._get_exception_message(err), "Failed as you wanted!" - ) - entry_url_from_exc = err.rest_json_info["log_entry_url"] - - with new_rollbacked_env() as new_env: - log_model = new_env["rest.log"].sudo() - entry = log_model.search([]) - initial_entries - expected = { - "collection": service._collection, - "state": "failed", - "result": "null", - "exception_name": exc_name, - "exception_message": "Failed as you wanted!", - "severity": severity, - } - self.assertRecordValues(entry, [expected]) - self.assertEqual(entry_url_from_exc, service._get_log_entry_url(entry)) - - -class TestDBLoggingExceptionUserError(TestDBLoggingExceptionBase): - @staticmethod - def _get_test_controller(class_or_instance, root_path=None): - # Override to avoid registering twice the same controller route. - return super()._get_test_controller( - class_or_instance, root_path="/test_log_exception_user/" - ) - - def test_log_exception_user(self): - self._test_exception( - "user", - log_exceptions.RESTServiceUserErrorException, - "odoo.exceptions.UserError", - "functional", - ) - - -class TestDBLoggingExceptionValidationError(TestDBLoggingExceptionBase): - @staticmethod - def _get_test_controller(class_or_instance, root_path=None): - return super()._get_test_controller( - class_or_instance, root_path="/test_log_exception_validation/" - ) - - def test_log_exception_validation(self): - self._test_exception( - "validation", - log_exceptions.RESTServiceValidationErrorException, - "odoo.exceptions.ValidationError", - "functional", - ) - - -class TestDBLoggingExceptionValueError(TestDBLoggingExceptionBase): - @staticmethod - def _get_test_controller(class_or_instance, root_path=None): - return super()._get_test_controller( - class_or_instance, root_path="/test_log_exception_value/" - ) - - def test_log_exception_value(self): - self._test_exception( - "value", log_exceptions.RESTServiceDispatchException, "ValueError", "severe" - ) - - -class TestDBLoggingRetryableError( - TransactionRestServiceRegistryCase, TestDBLoggingMixin -): - @classmethod - def setUpClass(cls): - super().setUpClass() - cls._setup_registry(cls) - - @classmethod - def tearDownClass(cls): - # pylint: disable=W8110 - cls._teardown_registry(cls) - super().tearDownClass() - - def _test_exception(self, test_type, wrapping_exc, exc_name, severity): - log_model = self.env["rest.log"].sudo() - initial_entries = log_model.search([]) - # Context: we are running in a transaction case which uses savepoints. - # The log machinery is going to rollback the transation when catching errors. - # Hence we need a completely separated env for the service. - with new_rollbacked_env() as new_env: - # Init fake collection w/ new env - collection = _PseudoCollection(self._collection_name, new_env) - service = self._get_service(self, collection=collection) - with self._get_mocked_request(env=new_env): - try: - service.dispatch("fail", test_type) - except Exception as err: - # Not using `assertRaises` to inspect the exception directly - self.assertTrue(isinstance(err, wrapping_exc)) - self.assertEqual( - service._get_exception_message(err), "Failed as you wanted!" - ) - - with new_rollbacked_env() as new_env: - log_model = new_env["rest.log"].sudo() - entry = log_model.search([]) - initial_entries - expected = { - "collection": service._collection, - "state": "failed", - "result": "null", - "exception_name": exc_name, - "exception_message": "Failed as you wanted!", - "severity": severity, - } - self.assertRecordValues(entry, [expected]) - - @staticmethod - def _get_test_controller(class_or_instance, root_path=None): - return super()._get_test_controller( - class_or_instance, root_path="/test_log_exception_retryable/" - ) - - def test_log_exception_retryable(self): - # retryable error must bubble up to the retrying mechanism - self._test_exception( - "retryable", - FakeConcurrentUpdateError, - "odoo.addons.rest_log.tests.common.FakeConcurrentUpdateError", - "warning", - ) + def test_get_profiler(self): + with self._get_mocked_request(): + profiler = self.service._profiling_get_profiler("avg_endpoint") + self.assertEqual( + profiler.description, + f"REST LOG {self.service._collection}" + f".{self.service._usage}.avg_endpoint", + ) + self.assertEqual( + profiler.profile_session, f"{self.env.user.name} (uid={self.env.uid})" + ) diff --git a/rest_log/tests/test_db_logging_exception.py b/rest_log/tests/test_db_logging_exception.py new file mode 100644 index 000000000..79fc71373 --- /dev/null +++ b/rest_log/tests/test_db_logging_exception.py @@ -0,0 +1,171 @@ +# Copyright 2020 Camptocamp SA (http://www.camptocamp.com) +# License LGPL-3.0 or later (http://www.gnu.org/licenses/lgpl.html). +# from urllib.parse import urlparse + + +from odoo.addons.base_rest.controllers.main import _PseudoCollection +from odoo.addons.base_rest.tests.common import TransactionRestServiceRegistryCase +from odoo.addons.component.tests.common import new_rollbacked_env +from odoo.addons.rest_log import exceptions as log_exceptions # pylint: disable=W7950 + +from .common import FakeConcurrentUpdateError, TestDBLoggingMixin + + +class TestDBLoggingExceptionBase( + TransactionRestServiceRegistryCase, TestDBLoggingMixin +): + @classmethod + def setUpClass(cls): + super().setUpClass() + cls._setup_registry(cls) + + @classmethod + def tearDownClass(cls): + # pylint: disable=W8110 + cls._teardown_registry(cls) + super().tearDownClass() + + def _test_exception(self, test_type, wrapping_exc, exc_name, severity): + log_model = self.env["rest.log"].sudo() + initial_entries = log_model.search([]) + entry_url_from_exc = None + # Context: we are running in a transaction case which uses savepoints. + # The log machinery is going to rollback the transation when catching errors. + # Hence we need a completely separated env for the service. + with new_rollbacked_env() as new_env: + # Init fake collection w/ new env + collection = _PseudoCollection(self._collection_name, new_env) + service = self._get_service(self, collection=collection) + with self._get_mocked_request(env=new_env): + try: + service.dispatch("fail", test_type) + except Exception as err: + # Not using `assertRaises` to inspect the exception directly + self.assertTrue(isinstance(err, wrapping_exc)) + self.assertEqual( + service._get_exception_message(err), "Failed as you wanted!" + ) + entry_url_from_exc = err.rest_json_info["log_entry_url"] + + with new_rollbacked_env() as new_env: + log_model = new_env["rest.log"].sudo() + entry = log_model.search([]) - initial_entries + expected = { + "collection": service._collection, + "state": "failed", + "result": "null", + "exception_name": exc_name, + "exception_message": "Failed as you wanted!", + "severity": severity, + } + self.assertRecordValues(entry, [expected]) + self.assertEqual(entry_url_from_exc, service._get_log_entry_url(entry)) + + +class TestDBLoggingExceptionUserError(TestDBLoggingExceptionBase): + @staticmethod + def _get_test_controller(class_or_instance, root_path=None): + # Override to avoid registering twice the same controller route. + return super()._get_test_controller( + class_or_instance, root_path="/test_log_exception_user/" + ) + + def test_log_exception_user(self): + self._test_exception( + "user", + log_exceptions.RESTServiceUserErrorException, + "odoo.exceptions.UserError", + "functional", + ) + + +class TestDBLoggingExceptionValidationError(TestDBLoggingExceptionBase): + @staticmethod + def _get_test_controller(class_or_instance, root_path=None): + return super()._get_test_controller( + class_or_instance, root_path="/test_log_exception_validation/" + ) + + def test_log_exception_validation(self): + self._test_exception( + "validation", + log_exceptions.RESTServiceValidationErrorException, + "odoo.exceptions.ValidationError", + "functional", + ) + + +class TestDBLoggingExceptionValueError(TestDBLoggingExceptionBase): + @staticmethod + def _get_test_controller(class_or_instance, root_path=None): + return super()._get_test_controller( + class_or_instance, root_path="/test_log_exception_value/" + ) + + def test_log_exception_value(self): + self._test_exception( + "value", log_exceptions.RESTServiceDispatchException, "ValueError", "severe" + ) + + +class TestDBLoggingRetryableError( + TransactionRestServiceRegistryCase, TestDBLoggingMixin +): + @classmethod + def setUpClass(cls): + super().setUpClass() + cls._setup_registry(cls) + + @classmethod + def tearDownClass(cls): + # pylint: disable=W8110 + cls._teardown_registry(cls) + super().tearDownClass() + + def _test_exception(self, test_type, wrapping_exc, exc_name, severity): + log_model = self.env["rest.log"].sudo() + initial_entries = log_model.search([]) + # Context: we are running in a transaction case which uses savepoints. + # The log machinery is going to rollback the transation when catching errors. + # Hence we need a completely separated env for the service. + with new_rollbacked_env() as new_env: + # Init fake collection w/ new env + collection = _PseudoCollection(self._collection_name, new_env) + service = self._get_service(self, collection=collection) + with self._get_mocked_request(env=new_env): + try: + service.dispatch("fail", test_type) + except Exception as err: + # Not using `assertRaises` to inspect the exception directly + self.assertTrue(isinstance(err, wrapping_exc)) + self.assertEqual( + service._get_exception_message(err), "Failed as you wanted!" + ) + + with new_rollbacked_env() as new_env: + log_model = new_env["rest.log"].sudo() + entry = log_model.search([]) - initial_entries + expected = { + "collection": service._collection, + "state": "failed", + "result": "null", + "exception_name": exc_name, + "exception_message": "Failed as you wanted!", + "severity": severity, + } + self.assertRecordValues(entry, [expected]) + + @staticmethod + def _get_test_controller(class_or_instance, root_path=None): + return super()._get_test_controller( + class_or_instance, root_path="/test_log_exception_retryable/" + ) + + def test_log_exception_retryable(self): + # retryable error must bubble up to the retrying mechanism + self._test_exception( + "retryable", + FakeConcurrentUpdateError, + "odoo.addons.rest_log.tests.common.FakeConcurrentUpdateError", + "warning", + )