debug: add new custom logging to track unique requests across systems.

rhodecode/config/middleware.py

@@ -38,6 +38,7 @@ from rhodecode.config import utils as config_utils
 from rhodecode.config.environment import load_pyramid_environment
 
 from rhodecode.lib.middleware.vcs import VCSMiddleware
+from rhodecode.lib.request import Request
 from rhodecode.lib.vcs import VCSCommunicationError
 from rhodecode.lib.exceptions import VCSServerUnavailable
 from rhodecode.lib.middleware.appenlight import wrap_in_appenlight_if_enabled
@@ -192,6 +193,7 @@ def includeme_first(config):
 
 def includeme(config):
     settings = config.registry.settings
+    config.set_request_factory(Request)
 
     # plugin information
     config.registry.rhodecode_plugins = collections.OrderedDict()

rhodecode/lib/logging_formatter.py

@@ -123,6 +123,35 @@ class ColorFormatter(ExceptionAwareFormatter):
         return colored_record
 
 
+def _inject_req_id(record):
+    from pyramid.threadlocal import get_current_request
+    req = get_current_request()
+    req_id = 'req_id:%-36s ' % (getattr(req, 'req_id', None))
+    record.req_id = req_id
+
+
+class RequestTrackingFormatter(ExceptionAwareFormatter):
+    def format(self, record):
+        _inject_req_id(record)
+        def_record = logging.Formatter.format(self, record)
+        return def_record
+
+
+class ColorRequestTrackingFormatter(ColorFormatter):
+    def format(self, record):
+        """
+        Changes record's levelname to use with COLORS enum
+        """
+        _inject_req_id(record)
+        levelname = record.levelname
+        start = COLOR_SEQ % (COLORS[levelname])
+        def_record = logging.Formatter.format(self, record)
+        end = RESET_SEQ
+
+        colored_record = ''.join([start, def_record, end])
+        return colored_record
+
+
 class ColorFormatterSql(logging.Formatter):
 
     def format(self, record):

rhodecode/lib/middleware/vcs.py

@@ -158,7 +158,7 @@ def detect_vcs_request(environ, backends):
             log.debug('got handler:%s from environ', handler)
 
     if not handler:
-        log.debug('checking if request is of VCS type in order: %s', backends)
+        log.debug('request start: checking if request is of VCS type in order: %s', backends)
         for vcs_type in backends:
             vcs_check, _handler = checks[vcs_type]
             if vcs_check(environ):

rhodecode/lib/pyramid_utils.py

@@ -21,9 +21,10 @@
 import os
 from pyramid.compat import configparser
 from pyramid.paster import bootstrap as pyramid_bootstrap, setup_logging  # noqa
-from pyramid.request import Request
 from pyramid.scripting import prepare
 
+from rhodecode.lib.request import Request
+
 
 def get_config(ini_path, **kwargs):
     parser = configparser.ConfigParser(**kwargs)

rhodecode/lib/request.py

@@ -0,0 +1,29 @@
+# -*- coding: utf-8 -*-
+
+# Copyright (C) 2017-2018 RhodeCode GmbH
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License, version 3
+# (only), as published by the Free Software Foundation.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+#
+# This program is dual-licensed. If you wish to learn more about the
+# RhodeCode Enterprise Edition, including its added features, Support services,
+# and proprietary license terms, please see https://rhodecode.com/licenses/
+
+from uuid import uuid4
+from pyramid.decorator import reify
+from pyramid.request import Request as _Request
+
+
+class Request(_Request):
+    @reify
+    def req_id(self):
+        return str(uuid4())

rhodecode/lib/utils.py

@@ -41,7 +41,7 @@ import pkg_resources
 from webhelpers.text import collapse, remove_formatting, strip_tags
 from mako import exceptions
 from pyramid.threadlocal import get_current_registry
-from pyramid.request import Request
+from rhodecode.lib.request import Request
 
 from rhodecode.lib.fakemod import create_module
 from rhodecode.lib.vcs.backends.base import Config

rhodecode/subscribers.py

@@ -86,6 +86,8 @@ def add_request_user_context(event):
     Adds auth user into request context
     """
     request = event.request
+    # access req_id as soon as possible
+    req_id = request.req_id
 
     if hasattr(request, 'vcs_call'):
         # skip vcs calls
@@ -98,7 +100,7 @@ def add_request_user_context(event):
     auth_user = get_auth_user(request)
     request.user = auth_user
     request.environ['rc_auth_user'] = auth_user
-
+    request.environ['rc_req_id'] = req_id
 
 def inject_app_settings(event):
     settings = event.app.registry.settings