Merge pull request #198 from p-tombez/requests_log_imp

monitoring_log_requests: Improve data output

monitoring_log_requests/README.rst

@@ -6,7 +6,14 @@ Monitoring: Requests Logging
 
 This addon is used to output in the logs informations about the user's
 requests.  Data such as *what* is the request, *who* requested it and *how
-much* time did it took to complete could then be extracted from the logs and
+much* time did it took to complete.
+
+The requests logging is activated with the environment variable `ODOO_REQUESTS_LOGGING` set to `1`.
+
+Data output
+###########
+
+The data could then be extracted from the logs and
 loaded in an analysis tool such as ElasticSearch/Kibana.
 
 Each log line is a JSON with the monitored fields, so it is easier to parse.
@@ -15,3 +22,8 @@ The logs are prefixed with ``monitoring.http.requests`` so be sure to enable
 this path in the log handler::
 
     - LOG_HANDLER=":WARNING,monitoring.http.requests:INFO"
+
+It is also possible to send the data directly to an UDP listener without
+outputting anything to the logs to avoid flooding on busy instances.
+To do so, use the environment variable `ODOO_REQUESTS_LOGGING_UDP`
+set to a value like `<address>:<port>` (`address` can be an IP or a domain).

monitoring_log_requests/__init__.py

@@ -1,2 +1,3 @@
 
+from . import utils
 from . import models

monitoring_log_requests/models/__init__.py

@@ -1,2 +1,5 @@
 
-from . import ir_http
+from ..utils import is_enabled
+
+if is_enabled():
+    from . import ir_http

monitoring_log_requests/models/ir_http.py

@@ -2,35 +2,64 @@
 # License AGPL-3.0 or later (http://www.gnu.org/licenses/agpl.html)
 
 import json
-import logging
 import time
+from os import environ
+from collections import MutableMapping
+from contextlib import suppress
 
 from odoo import models
 from odoo.http import request as http_request
 from odoo.tools.config import config
 
 
-_logger = logging.getLogger('monitoring.http.requests')
+udp_dest = environ.get("ODOO_REQUESTS_LOGGING_UDP")
+if udp_dest:
+    import socket
+    import atexit
+
+    sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM, 0)
+    atexit.register(sock.close)
+    ip, port = udp_dest.split(":")
+    port = int(port)
+
+    def output_method(data):
+        data += "\n"
+        sock.sendto(data.encode("utf-8"), (ip, port))
+else:
+    import logging
+
+    _logger = logging.getLogger("monitoring.http.requests")
+    output_method = _logger.info
+
+
+def delete_from_dict(d, keys):
+    for key in keys:
+        with suppress(KeyError):
+            del d[key]
+    for value in d.values():
+        if isinstance(value, MutableMapping):
+            delete_from_dict(value, keys)
 
 
 class IrHttp(models.AbstractModel):
-    _inherit = 'ir.http'
+    _inherit = "ir.http"
 
     @classmethod
     def _dispatch(cls):
         begin = time.time()
         response = super()._dispatch()
         end = time.time()
-        if (not cls._monitoring_blacklist(http_request) and
+        if not cls._monitoring_blacklist(http_request) and cls._monitoring_filter(
-                cls._monitoring_filter(http_request)):
+            http_request
+        ):
             info = cls._monitoring_info(http_request, response, begin, end)
             cls._monitoring_log(info)
         return response
 
     @classmethod
     def _monitoring_blacklist(cls, request):
-        path_info = request.httprequest.environ.get('PATH_INFO')
+        path_info = request.httprequest.environ.get("PATH_INFO")
-        if path_info.startswith('/longpolling/'):
+        if path_info.startswith("/longpolling/"):
             return True
         return False
 
@@ -38,46 +67,39 @@ class IrHttp(models.AbstractModel):
     def _monitoring_filter(cls, _):
         return True
 
+    @classmethod
+    def _json_blacklist(cls):
+        return ["HTTP_COOKIE", "session_token"]
+
     @classmethod
     def _monitoring_info(cls, request, response, begin, end):
-        path = request.httprequest.environ.get('PATH_INFO')
         info = {
             # timing
-            'start_time': time.strftime("%Y-%m-%d %H:%M:%S",
+            "start_time": time.strftime("%Y-%m-%d %H:%M:%S", time.gmtime(begin)),
-                                        time.gmtime(begin)),
+            "duration": end - begin,
-            'duration': end - begin,
             # HTTP things
-            'method': request.httprequest.method,
+            "method": request.httprequest.method,
-            'url': request.httprequest.url,
+            "url": request.httprequest.url,
-            'path': path,
+            "status_code": response.status_code,
-            'content_type': request.httprequest.environ.get('CONTENT_TYPE'),
+            "headers": request.httprequest.environ.copy(),
-            'user_agent': request.httprequest.environ.get('HTTP_USER_AGENT'),
             # Odoo things
-            'db': None,
+            "uid": request.uid,
-            'uid': request.uid,
+            "server_environment": config.get("running_env"),
-            'login': None,
-            'server_environment': config.get('running_env'),
-            'model': None,
-            'model_method': None,
-            'workflow_signal': None,
-            # response things
-            'response_status_code': None,
         }
-        if hasattr(request, 'status_code'):
+        if hasattr(request, "session"):
-            info['status_code'] = response.status_code
+            info["session"] = dict(request.session)
-        if hasattr(request, 'session'):
+        if hasattr(request, "params"):
-            info.update({
+            info["params"] = dict(request.params)
-                'login': request.session.get('login'),
+
-                'db': request.session.get('db'),
-            })
-        if hasattr(request, 'params'):
-            info.update({
-                'model': request.params.get('model'),
-                'model_method': request.params.get('method'),
-                'workflow_signal': request.params.get('signal'),
-            })
         return info
 
     @classmethod
     def _monitoring_log(cls, info):
-        _logger.info(json.dumps(info))
+        delete_from_dict(info, cls._json_blacklist())
+        output_method(
+            json.dumps(
+                info,
+                ensure_ascii=True,
+                default=lambda o: f"<non-serializable: {type(o).__qualname__}>",
+            )
+        )

monitoring_log_requests/utils.py

@@ -0,0 +1,10 @@
+# Copyright 2020 Camptocamp SA
+# License AGPL-3.0 or later (http://www.gnu.org/licenses/agpl.html)
+
+from distutils.util import strtobool
+from os import environ
+
+
+def is_enabled():
+    env_val = environ.get('ODOO_REQUESTS_LOGGING')
+    return bool(strtobool(env_val or '0'.lower()))