chore(logging): optimize loggers for request wrapper to be easier to read

rhodecode/lib/middleware/request_wrapper.py

@@ -1,96 +1,96 b''
 
 
 # Copyright (C) 2016-2023 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/
 
 import time
 import logging
 
 import rhodecode
 from rhodecode.lib.auth import AuthUser
 from rhodecode.lib.base import get_ip_addr, get_user_agent
 from rhodecode.lib.middleware.utils import get_path_info
 from rhodecode.lib.utils2 import safe_str, get_current_rhodecode_user
 
 
 log = logging.getLogger(__name__)
 
 
 class RequestWrapperTween(object):
     def __init__(self, handler, registry):
         self.handler = handler
         self.registry = registry
 
         # one-time configuration code goes here
 
     def _get_user_info(self, request):
         user = get_current_rhodecode_user(request)
         if not user:
             user = AuthUser.repr_user(ip=get_ip_addr(request.environ))
         return user
 
     def __call__(self, request):
         start = time.time()
-        log.debug('Starting request time measurement')
+        log.debug('Starting request processing')
         response = None
         request.req_wrapper_start = start
 
         try:
             response = self.handler(request)
         finally:
             count = request.request_count()
             _ver_ = rhodecode.__version__
             _path = get_path_info(request.environ)
             _auth_user = self._get_user_info(request)
             ip = get_ip_addr(request.environ)
             match_route = request.matched_route.name if request.matched_route else "NOT_FOUND"
             resp_code = getattr(response, 'status_code', 'UNDEFINED')
 
             total = time.time() - start
             log.info(
-                'Req[%4s] %s %s Request to %s time: %.4fs [%s], RhodeCode %s',
+                'Finished request processing: req[%4s] %s %s Request to %s time: %.4fs [%s], RhodeCode %s',
                 count, _auth_user, request.environ.get('REQUEST_METHOD'),
                 _path, total, get_user_agent(request. environ), _ver_,
                 extra={"time": total, "ver": _ver_, "ip": ip,
                        "path": _path, "view_name": match_route, "code": resp_code}
             )
 
             statsd = request.registry.statsd
             if statsd:
                 elapsed_time_ms = round(1000.0 * total)  # use ms only
                 statsd.timing(
                     "rhodecode_req_timing.histogram", elapsed_time_ms,
                     tags=[
                         "view_name:{}".format(match_route),
                         "code:{}".format(resp_code)
                     ],
                     use_decimals=False
                 )
                 statsd.incr(
                     'rhodecode_req_total', tags=[
                         "view_name:{}".format(match_route),
                         "code:{}".format(resp_code)
                     ])
 
         return response
 
 
 def includeme(config):
     config.add_tween(
         'rhodecode.lib.middleware.request_wrapper.RequestWrapperTween',
     )