chore: improved logging for request processing

vcsserver/tweens/request_wrapper.py

@@ -1,123 +1,123 b''
 # RhodeCode VCSServer provides access to different vcs backends via network.
 # Copyright (C) 2014-2023 RhodeCode GmbH
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by
 # the Free Software Foundation; either version 3 of the License, or
 # (at your option) any later version.
 #
 # 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 General Public License
 # along with this program; if not, write to the Free Software Foundation,
 # Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301  USA
 import base64
 import logging
 import time
 
 import msgpack
 
 import vcsserver
 from vcsserver.lib.str_utils import safe_str
 
 log = logging.getLogger(__name__)
 
 
 def get_access_path(environ):
     path = environ.get('PATH_INFO')
     return path
 
 
 def get_user_agent(environ):
     return environ.get('HTTP_USER_AGENT')
 
 
 def get_call_context(request) -> dict:
     cc = {}
     registry = request.registry
     if hasattr(registry, 'vcs_call_context'):
         cc.update({
             'X-RC-Method': registry.vcs_call_context.get('method'),
             'X-RC-Repo-Name': registry.vcs_call_context.get('repo_name')
         })
 
     return cc
 
 
 def get_headers_call_context(environ, strict=True):
     if 'HTTP_X_RC_VCS_STREAM_CALL_CONTEXT' in environ:
         packed_cc = base64.b64decode(environ['HTTP_X_RC_VCS_STREAM_CALL_CONTEXT'])
         return msgpack.unpackb(packed_cc)
     elif strict:
         raise ValueError('Expected header HTTP_X_RC_VCS_STREAM_CALL_CONTEXT not found')
 
 
 class RequestWrapperTween:
     def __init__(self, handler, registry):
         self.handler = handler
         self.registry = registry
 
         # one-time configuration code goes here
 
     def __call__(self, request):
         start = time.time()
-        log.debug('Starting request time measurement')
+        log.debug('Starting request processing')
         response = None
 
         try:
             response = self.handler(request)
         finally:
             ua = get_user_agent(request.environ)
             call_context = get_call_context(request)
             vcs_method = call_context.get('X-RC-Method', '_NO_VCS_METHOD')
             repo_name = call_context.get('X-RC-Repo-Name', '')
 
             count = request.request_count()
             _ver_ = vcsserver.get_version()
             _path = safe_str(get_access_path(request.environ))
 
             ip = '127.0.0.1'
             match_route = request.matched_route.name if request.matched_route else "NOT_FOUND"
             resp_code = getattr(response, 'status_code', 'UNDEFINED')
 
             _view_path = f"{repo_name}@{_path}/{vcs_method}"
 
             total = time.time() - start
 
             log.info(
-                'Req[%4s] IP: %s %s Request to %s time: %.4fs [%s], VCSServer %s',
+                'Finished request processing: reqq[%4s] IP: %s %s Request to %s time: %.4fs [%s], VCSServer %s',
                 count, ip, request.environ.get('REQUEST_METHOD'),
                 _view_path, total, ua, _ver_,
                 extra={"time": total, "ver": _ver_, "code": resp_code,
                        "path": _path, "view_name": match_route, "user_agent": ua,
                        "vcs_method": vcs_method, "repo_name": repo_name}
             )
 
             statsd = request.registry.statsd
             if statsd:
                 match_route = request.matched_route.name if request.matched_route else _path
                 elapsed_time_ms = round(1000.0 * total)  # use ms only
                 statsd.timing(
                     "vcsserver_req_timing.histogram", elapsed_time_ms,
                     tags=[
                         f"view_name:{match_route}",
                         f"code:{resp_code}"
                     ],
                     use_decimals=False
                 )
                 statsd.incr(
                     "vcsserver_req_total", tags=[
                         f"view_name:{match_route}",
                         f"code:{resp_code}"
                     ])
 
         return response
 
 
 def includeme(config):
     config.add_tween(
         'vcsserver.tweens.request_wrapper.RequestWrapperTween',
     )