vcsserver: logging improvements

vcsserver/lib/rc_cache/utils.py

@@ -1,263 +1,263 b''
 # 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 os
 import time
 import logging
 import functools
 
 from dogpile.cache import CacheRegion
 from dogpile.cache.util import compat
 
 from vcsserver.utils import safe_str, sha1
 
 from vcsserver.lib.rc_cache import region_meta
 
 log = logging.getLogger(__name__)
 
 
 class RhodeCodeCacheRegion(CacheRegion):
 
     def conditional_cache_on_arguments(
             self, namespace=None,
             expiration_time=None,
             should_cache_fn=None,
             to_str=compat.string_type,
             function_key_generator=None,
             condition=True):
         """
         Custom conditional decorator, that will not touch any dogpile internals if
         condition isn't meet. This works a bit different than should_cache_fn
         And it's faster in cases we don't ever want to compute cached values
         """
         expiration_time_is_callable = compat.callable(expiration_time)
 
         if function_key_generator is None:
             function_key_generator = self.function_key_generator
 
         # workaround for py2 and cython problems, this block should be removed
         # once we've migrated to py3
         if 'cython' == 'cython':
             def decorator(fn):
                 if to_str is compat.string_type:
                     # backwards compatible
                     key_generator = function_key_generator(namespace, fn)
                 else:
                     key_generator = function_key_generator(namespace, fn, to_str=to_str)
 
                 @functools.wraps(fn)
                 def decorate(*arg, **kw):
                     key = key_generator(*arg, **kw)
 
                     @functools.wraps(fn)
                     def creator():
                         return fn(*arg, **kw)
 
                     if not condition:
                         return creator()
 
                     timeout = expiration_time() if expiration_time_is_callable \
                         else expiration_time
 
                     return self.get_or_create(key, creator, timeout, should_cache_fn)
 
                 def invalidate(*arg, **kw):
                     key = key_generator(*arg, **kw)
                     self.delete(key)
 
                 def set_(value, *arg, **kw):
                     key = key_generator(*arg, **kw)
                     self.set(key, value)
 
                 def get(*arg, **kw):
                     key = key_generator(*arg, **kw)
                     return self.get(key)
 
                 def refresh(*arg, **kw):
                     key = key_generator(*arg, **kw)
                     value = fn(*arg, **kw)
                     self.set(key, value)
                     return value
 
                 decorate.set = set_
                 decorate.invalidate = invalidate
                 decorate.refresh = refresh
                 decorate.get = get
                 decorate.original = fn
                 decorate.key_generator = key_generator
                 decorate.__wrapped__ = fn
 
                 return decorate
             return decorator
 
         def get_or_create_for_user_func(key_generator, user_func, *arg, **kw):
 
             if not condition:
-                log.debug('Calling un-cached func:%s', user_func.func_name)
+                log.debug('Calling un-cached method:%s', user_func.func_name)
                 start = time.time()
                 result = user_func(*arg, **kw)
                 total = time.time() - start
-                log.debug('un-cached func:%s took %.4fs', user_func.func_name, total)
+                log.debug('un-cached method:%s took %.4fs', user_func.func_name, total)
                 return result
 
             key = key_generator(*arg, **kw)
 
             timeout = expiration_time() if expiration_time_is_callable \
                 else expiration_time
 
-            log.debug('Calling cached fn:%s', user_func.func_name)
+            log.debug('Calling cached method:`%s`', user_func.func_name)
             return self.get_or_create(key, user_func, timeout, should_cache_fn, (arg, kw))
 
         def cache_decorator(user_func):
             if to_str is compat.string_type:
                 # backwards compatible
                 key_generator = function_key_generator(namespace, user_func)
             else:
                 key_generator = function_key_generator(namespace, user_func, to_str=to_str)
 
             def refresh(*arg, **kw):
                 """
                 Like invalidate, but regenerates the value instead
                 """
                 key = key_generator(*arg, **kw)
                 value = user_func(*arg, **kw)
                 self.set(key, value)
                 return value
 
             def invalidate(*arg, **kw):
                 key = key_generator(*arg, **kw)
                 self.delete(key)
 
             def set_(value, *arg, **kw):
                 key = key_generator(*arg, **kw)
                 self.set(key, value)
 
             def get(*arg, **kw):
                 key = key_generator(*arg, **kw)
                 return self.get(key)
 
             user_func.set = set_
             user_func.invalidate = invalidate
             user_func.get = get
             user_func.refresh = refresh
             user_func.key_generator = key_generator
             user_func.original = user_func
 
             # Use `decorate` to preserve the signature of :param:`user_func`.
             return decorator.decorate(user_func, functools.partial(
                 get_or_create_for_user_func, key_generator))
 
         return cache_decorator
 
 
 def make_region(*arg, **kw):
     return RhodeCodeCacheRegion(*arg, **kw)
 
 
 def get_default_cache_settings(settings, prefixes=None):
     prefixes = prefixes or []
     cache_settings = {}
     for key in settings.keys():
         for prefix in prefixes:
             if key.startswith(prefix):
                 name = key.split(prefix)[1].strip()
                 val = settings[key]
                 if isinstance(val, compat.string_types):
                     val = val.strip()
                 cache_settings[name] = val
     return cache_settings
 
 
 def compute_key_from_params(*args):
     """
     Helper to compute key from given params to be used in cache manager
     """
     return sha1("_".join(map(safe_str, args)))
 
 
 def backend_key_generator(backend):
     """
     Special wrapper that also sends over the backend to the key generator
     """
     def wrapper(namespace, fn):
         return key_generator(backend, namespace, fn)
     return wrapper
 
 
 def key_generator(backend, namespace, fn):
     fname = fn.__name__
 
     def generate_key(*args):
         backend_prefix = getattr(backend, 'key_prefix', None) or 'backend_prefix'
         namespace_pref = namespace or 'default_namespace'
         arg_key = compute_key_from_params(*args)
         final_key = "{}:{}:{}_{}".format(backend_prefix, namespace_pref, fname, arg_key)
 
         return final_key
 
     return generate_key
 
 
 def get_or_create_region(region_name, region_namespace=None):
     from vcsserver.lib.rc_cache.backends import FileNamespaceBackend
     region_obj = region_meta.dogpile_cache_regions.get(region_name)
     if not region_obj:
         raise EnvironmentError(
             'Region `{}` not in configured: {}.'.format(
                 region_name, region_meta.dogpile_cache_regions.keys()))
 
     region_uid_name = '{}:{}'.format(region_name, region_namespace)
     if isinstance(region_obj.actual_backend, FileNamespaceBackend):
         region_exist = region_meta.dogpile_cache_regions.get(region_namespace)
         if region_exist:
             log.debug('Using already configured region: %s', region_namespace)
             return region_exist
         cache_dir = region_meta.dogpile_config_defaults['cache_dir']
         expiration_time = region_obj.expiration_time
 
         if not os.path.isdir(cache_dir):
             os.makedirs(cache_dir)
         new_region = make_region(
             name=region_uid_name,
             function_key_generator=backend_key_generator(region_obj.actual_backend)
         )
         namespace_filename = os.path.join(
             cache_dir, "{}.cache.dbm".format(region_namespace))
         # special type that allows 1db per namespace
         new_region.configure(
             backend='dogpile.cache.rc.file_namespace',
             expiration_time=expiration_time,
             arguments={"filename": namespace_filename}
         )
 
         # create and save in region caches
         log.debug('configuring new region: %s', region_uid_name)
         region_obj = region_meta.dogpile_cache_regions[region_namespace] = new_region
 
     return region_obj
 
 
 def clear_cache_namespace(cache_region, cache_namespace_uid, invalidate=False):
     region = get_or_create_region(cache_region, cache_namespace_uid)
     cache_keys = region.backend.list_keys(prefix=cache_namespace_uid)
     num_delete_keys = len(cache_keys)
     if invalidate:
         region.invalidate(hard=False)
     else:
         if num_delete_keys:
             region.delete_multi(cache_keys)
     return num_delete_keys