vcsserver/tweens/request_wrapper.py

# RhodeCode VCSServer provides access to different vcs backends via network.
# Copyright (C) 2014-2020 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 time
import logging

import msgpack

import vcsserver
from vcsserver.str_utils import safe_str, ascii_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(registry) -> dict:
    cc = {}
    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


class RequestWrapperTween(object):
    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')
        response = None

        try:
            response = self.handler(request)
        finally:
            ua = get_user_agent(request.environ)
            call_context = get_call_context(request.registry)
            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_ = ascii_str(vcsserver.__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',
                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=[
                        "view_name:{}".format(match_route),
                        "code:{}".format(resp_code)
                    ],
                    use_decimals=False
                )
                statsd.incr(
                    "vcsserver_req_total", tags=[
                        "view_name:{}".format(match_route),
                        "code:{}".format(resp_code)
                    ])

        return response


def includeme(config):
    config.add_tween(
        'vcsserver.tweens.request_wrapper.RequestWrapperTween',
    )