logging: expose extra metadata to various important logs for loki

rhodecode/authentication/base.py

@@ -1,816 +1,822 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2010-2020 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/
 
 """
 Authentication modules
 """
 import socket
 import string
 import colander
 import copy
 import logging
 import time
 import traceback
 import warnings
 import functools
 
 from pyramid.threadlocal import get_current_registry
 
 from rhodecode.authentication.interface import IAuthnPluginRegistry
 from rhodecode.authentication.schema import AuthnPluginSettingsSchemaBase
 from rhodecode.lib import rc_cache
 from rhodecode.lib.statsd_client import StatsdClient
 from rhodecode.lib.auth import PasswordGenerator, _RhodeCodeCryptoBCrypt
 from rhodecode.lib.utils2 import safe_int, safe_str
 from rhodecode.lib.exceptions import (LdapConnectionError, LdapUsernameError, LdapPasswordError)
 from rhodecode.model.db import User
 from rhodecode.model.meta import Session
 from rhodecode.model.settings import SettingsModel
 from rhodecode.model.user import UserModel
 from rhodecode.model.user_group import UserGroupModel
 
 
 log = logging.getLogger(__name__)
 
 # auth types that authenticate() function can receive
 VCS_TYPE = 'vcs'
 HTTP_TYPE = 'http'
 
 external_auth_session_key = 'rhodecode.external_auth'
 
 
 class hybrid_property(object):
     """
     a property decorator that works both for instance and class
     """
     def __init__(self, fget, fset=None, fdel=None, expr=None):
         self.fget = fget
         self.fset = fset
         self.fdel = fdel
         self.expr = expr or fget
         functools.update_wrapper(self, fget)
 
     def __get__(self, instance, owner):
         if instance is None:
             return self.expr(owner)
         else:
             return self.fget(instance)
 
     def __set__(self, instance, value):
         self.fset(instance, value)
 
     def __delete__(self, instance):
         self.fdel(instance)
 
 
 class LazyFormencode(object):
     def __init__(self, formencode_obj, *args, **kwargs):
         self.formencode_obj = formencode_obj
         self.args = args
         self.kwargs = kwargs
 
     def __call__(self, *args, **kwargs):
         from inspect import isfunction
         formencode_obj = self.formencode_obj
         if isfunction(formencode_obj):
             # case we wrap validators into functions
             formencode_obj = self.formencode_obj(*args, **kwargs)
         return formencode_obj(*self.args, **self.kwargs)
 
 
 class RhodeCodeAuthPluginBase(object):
     # UID is used to register plugin to the registry
     uid = None
 
     # cache the authentication request for N amount of seconds. Some kind
     # of authentication methods are very heavy and it's very efficient to cache
     # the result of a call. If it's set to None (default) cache is off
     AUTH_CACHE_TTL = None
     AUTH_CACHE = {}
 
     auth_func_attrs = {
         "username": "unique username",
         "firstname": "first name",
         "lastname": "last name",
         "email": "email address",
         "groups": '["list", "of", "groups"]',
         "user_group_sync":
             'True|False defines if returned user groups should be synced',
         "extern_name": "name in external source of record",
         "extern_type": "type of external source of record",
         "admin": 'True|False defines if user should be RhodeCode super admin',
         "active":
             'True|False defines active state of user internally for RhodeCode',
         "active_from_extern":
             "True|False|None, active state from the external auth, "
             "None means use definition from RhodeCode extern_type active value"
 
     }
     # set on authenticate() method and via set_auth_type func.
     auth_type = None
 
     # set on authenticate() method and via set_calling_scope_repo, this is a
     # calling scope repository when doing authentication most likely on VCS
     # operations
     acl_repo_name = None
 
     # List of setting names to store encrypted. Plugins may override this list
     # to store settings encrypted.
     _settings_encrypted = []
 
     # Mapping of python to DB settings model types. Plugins may override or
     # extend this mapping.
     _settings_type_map = {
         colander.String: 'unicode',
         colander.Integer: 'int',
         colander.Boolean: 'bool',
         colander.List: 'list',
     }
 
     # list of keys in settings that are unsafe to be logged, should be passwords
     # or other crucial credentials
     _settings_unsafe_keys = []
 
     def __init__(self, plugin_id):
         self._plugin_id = plugin_id
         self._settings = {}
 
     def __str__(self):
         return self.get_id()
 
     def _get_setting_full_name(self, name):
         """
         Return the full setting name used for storing values in the database.
         """
         # TODO: johbo: Using the name here is problematic. It would be good to
         # introduce either new models in the database to hold Plugin and
         # PluginSetting or to use the plugin id here.
         return 'auth_{}_{}'.format(self.name, name)
 
     def _get_setting_type(self, name):
         """
         Return the type of a setting. This type is defined by the SettingsModel
         and determines how the setting is stored in DB. Optionally the suffix
         `.encrypted` is appended to instruct SettingsModel to store it
         encrypted.
         """
         schema_node = self.get_settings_schema().get(name)
         db_type = self._settings_type_map.get(
             type(schema_node.typ), 'unicode')
         if name in self._settings_encrypted:
             db_type = '{}.encrypted'.format(db_type)
         return db_type
 
     @classmethod
     def docs(cls):
         """
         Defines documentation url which helps with plugin setup
         """
         return ''
 
     @classmethod
     def icon(cls):
         """
         Defines ICON in SVG format for authentication method
         """
         return ''
 
     def is_enabled(self):
         """
         Returns true if this plugin is enabled. An enabled plugin can be
         configured in the admin interface but it is not consulted during
         authentication.
         """
         auth_plugins = SettingsModel().get_auth_plugins()
         return self.get_id() in auth_plugins
 
     def is_active(self, plugin_cached_settings=None):
         """
         Returns true if the plugin is activated. An activated plugin is
         consulted during authentication, assumed it is also enabled.
         """
         return self.get_setting_by_name(
             'enabled', plugin_cached_settings=plugin_cached_settings)
 
     def get_id(self):
         """
         Returns the plugin id.
         """
         return self._plugin_id
 
     def get_display_name(self, load_from_settings=False):
         """
         Returns a translation string for displaying purposes.
         if load_from_settings is set, plugin settings can override the display name
         """
         raise NotImplementedError('Not implemented in base class')
 
     def get_settings_schema(self):
         """
         Returns a colander schema, representing the plugin settings.
         """
         return AuthnPluginSettingsSchemaBase()
 
     def _propagate_settings(self, raw_settings):
         settings = {}
         for node in self.get_settings_schema():
             settings[node.name] = self.get_setting_by_name(
                 node.name, plugin_cached_settings=raw_settings)
         return settings
 
     def get_settings(self, use_cache=True):
         """
         Returns the plugin settings as dictionary.
         """
         if self._settings != {} and use_cache:
             return self._settings
 
         raw_settings = SettingsModel().get_all_settings()
         settings = self._propagate_settings(raw_settings)
 
         self._settings = settings
         return self._settings
 
     def get_setting_by_name(self, name, default=None, plugin_cached_settings=None):
         """
         Returns a plugin setting by name.
         """
         full_name = 'rhodecode_{}'.format(self._get_setting_full_name(name))
         if plugin_cached_settings:
             plugin_settings = plugin_cached_settings
         else:
             plugin_settings = SettingsModel().get_all_settings()
 
         if full_name in plugin_settings:
             return plugin_settings[full_name]
         else:
             return default
 
     def create_or_update_setting(self, name, value):
         """
         Create or update a setting for this plugin in the persistent storage.
         """
         full_name = self._get_setting_full_name(name)
         type_ = self._get_setting_type(name)
         db_setting = SettingsModel().create_or_update_setting(
             full_name, value, type_)
         return db_setting.app_settings_value
 
     def log_safe_settings(self, settings):
         """
         returns a log safe representation of settings, without any secrets
         """
         settings_copy = copy.deepcopy(settings)
         for k in self._settings_unsafe_keys:
             if k in settings_copy:
                 del settings_copy[k]
         return settings_copy
 
     @hybrid_property
     def name(self):
         """
         Returns the name of this authentication plugin.
 
         :returns: string
         """
         raise NotImplementedError("Not implemented in base class")
 
     def get_url_slug(self):
         """
         Returns a slug which should be used when constructing URLs which refer
         to this plugin. By default it returns the plugin name. If the name is
         not suitable for using it in an URL the plugin should override this
         method.
         """
         return self.name
 
     @property
     def is_headers_auth(self):
         """
         Returns True if this authentication plugin uses HTTP headers as
         authentication method.
         """
         return False
 
     @hybrid_property
     def is_container_auth(self):
         """
         Deprecated method that indicates if this authentication plugin uses
         HTTP headers as authentication method.
         """
         warnings.warn(
             'Use is_headers_auth instead.', category=DeprecationWarning)
         return self.is_headers_auth
 
     @hybrid_property
     def allows_creating_users(self):
         """
         Defines if Plugin allows users to be created on-the-fly when
         authentication is called. Controls how external plugins should behave
         in terms if they are allowed to create new users, or not. Base plugins
         should not be allowed to, but External ones should be !
 
         :return: bool
         """
         return False
 
     def set_auth_type(self, auth_type):
         self.auth_type = auth_type
 
     def set_calling_scope_repo(self, acl_repo_name):
         self.acl_repo_name = acl_repo_name
 
     def allows_authentication_from(
             self, user, allows_non_existing_user=True,
             allowed_auth_plugins=None, allowed_auth_sources=None):
         """
         Checks if this authentication module should accept a request for
         the current user.
 
         :param user: user object fetched using plugin's get_user() method.
         :param allows_non_existing_user: if True, don't allow the
             user to be empty, meaning not existing in our database
         :param allowed_auth_plugins: if provided, users extern_type will be
             checked against a list of provided extern types, which are plugin
             auth_names in the end
         :param allowed_auth_sources: authentication type allowed,
             `http` or `vcs` default is both.
             defines if plugin will accept only http authentication vcs
             authentication(git/hg) or both
         :returns: boolean
         """
         if not user and not allows_non_existing_user:
             log.debug('User is empty but plugin does not allow empty users,'
                       'not allowed to authenticate')
             return False
 
         expected_auth_plugins = allowed_auth_plugins or [self.name]
         if user and (user.extern_type and
                      user.extern_type not in expected_auth_plugins):
             log.debug(
                 'User `%s` is bound to `%s` auth type. Plugin allows only '
                 '%s, skipping', user, user.extern_type, expected_auth_plugins)
 
             return False
 
         # by default accept both
         expected_auth_from = allowed_auth_sources or [HTTP_TYPE, VCS_TYPE]
         if self.auth_type not in expected_auth_from:
             log.debug('Current auth source is %s but plugin only allows %s',
                       self.auth_type, expected_auth_from)
             return False
 
         return True
 
     def get_user(self, username=None, **kwargs):
         """
         Helper method for user fetching in plugins, by default it's using
         simple fetch by username, but this method can be custimized in plugins
         eg. headers auth plugin to fetch user by environ params
 
         :param username: username if given to fetch from database
         :param kwargs: extra arguments needed for user fetching.
         """
         user = None
         log.debug(
             'Trying to fetch user `%s` from RhodeCode database', username)
         if username:
             user = User.get_by_username(username)
             if not user:
                 log.debug('User not found, fallback to fetch user in '
                           'case insensitive mode')
                 user = User.get_by_username(username, case_insensitive=True)
         else:
             log.debug('provided username:`%s` is empty skipping...', username)
         if not user:
             log.debug('User `%s` not found in database', username)
         else:
             log.debug('Got DB user:%s', user)
         return user
 
     def user_activation_state(self):
         """
         Defines user activation state when creating new users
 
         :returns: boolean
         """
         raise NotImplementedError("Not implemented in base class")
 
     def auth(self, userobj, username, passwd, settings, **kwargs):
         """
         Given a user object (which may be null), username, a plaintext
         password, and a settings object (containing all the keys needed as
         listed in settings()), authenticate this user's login attempt.
 
         Return None on failure. On success, return a dictionary of the form:
 
             see: RhodeCodeAuthPluginBase.auth_func_attrs
         This is later validated for correctness
         """
         raise NotImplementedError("not implemented in base class")
 
     def _authenticate(self, userobj, username, passwd, settings, **kwargs):
         """
         Wrapper to call self.auth() that validates call on it
 
         :param userobj: userobj
         :param username: username
         :param passwd: plaintext password
         :param settings: plugin settings
         """
         auth = self.auth(userobj, username, passwd, settings, **kwargs)
         if auth:
             auth['_plugin'] = self.name
             auth['_ttl_cache'] = self.get_ttl_cache(settings)
             # check if hash should be migrated ?
             new_hash = auth.get('_hash_migrate')
             if new_hash:
                 self._migrate_hash_to_bcrypt(username, passwd, new_hash)
             if 'user_group_sync' not in auth:
                 auth['user_group_sync'] = False
             return self._validate_auth_return(auth)
         return auth
 
     def _migrate_hash_to_bcrypt(self, username, password, new_hash):
         new_hash_cypher = _RhodeCodeCryptoBCrypt()
         # extra checks, so make sure new hash is correct.
         password_encoded = safe_str(password)
         if new_hash and new_hash_cypher.hash_check(
                 password_encoded, new_hash):
             cur_user = User.get_by_username(username)
             cur_user.password = new_hash
             Session().add(cur_user)
             Session().flush()
             log.info('Migrated user %s hash to bcrypt', cur_user)
 
     def _validate_auth_return(self, ret):
         if not isinstance(ret, dict):
             raise Exception('returned value from auth must be a dict')
         for k in self.auth_func_attrs:
             if k not in ret:
                 raise Exception('Missing %s attribute from returned data' % k)
         return ret
 
     def get_ttl_cache(self, settings=None):
         plugin_settings = settings or self.get_settings()
         # we set default to 30, we make a compromise here,
         # performance > security, mostly due to LDAP/SVN, majority
         # of users pick cache_ttl to be enabled
         from rhodecode.authentication import plugin_default_auth_ttl
         cache_ttl = plugin_default_auth_ttl
 
         if isinstance(self.AUTH_CACHE_TTL, (int, long)):
             # plugin cache set inside is more important than the settings value
             cache_ttl = self.AUTH_CACHE_TTL
         elif plugin_settings.get('cache_ttl'):
             cache_ttl = safe_int(plugin_settings.get('cache_ttl'), 0)
 
         plugin_cache_active = bool(cache_ttl and cache_ttl > 0)
         return plugin_cache_active, cache_ttl
 
 
 class RhodeCodeExternalAuthPlugin(RhodeCodeAuthPluginBase):
 
     @hybrid_property
     def allows_creating_users(self):
         return True
 
     def use_fake_password(self):
         """
         Return a boolean that indicates whether or not we should set the user's
         password to a random value when it is authenticated by this plugin.
         If your plugin provides authentication, then you will generally
         want this.
 
         :returns: boolean
         """
         raise NotImplementedError("Not implemented in base class")
 
     def _authenticate(self, userobj, username, passwd, settings, **kwargs):
         # at this point _authenticate calls plugin's `auth()` function
         auth = super(RhodeCodeExternalAuthPlugin, self)._authenticate(
             userobj, username, passwd, settings, **kwargs)
 
         if auth:
             # maybe plugin will clean the username ?
             # we should use the return value
             username = auth['username']
 
             # if external source tells us that user is not active, we should
             # skip rest of the process. This can prevent from creating users in
             # RhodeCode when using external authentication, but if it's
             # inactive user we shouldn't create that user anyway
             if auth['active_from_extern'] is False:
                 log.warning(
                     "User %s authenticated against %s, but is inactive",
                     username, self.__module__)
                 return None
 
             cur_user = User.get_by_username(username, case_insensitive=True)
             is_user_existing = cur_user is not None
 
             if is_user_existing:
                 log.debug('Syncing user `%s` from '
                           '`%s` plugin', username, self.name)
             else:
                 log.debug('Creating non existing user `%s` from '
                           '`%s` plugin', username, self.name)
 
             if self.allows_creating_users:
                 log.debug('Plugin `%s` allows to '
                           'create new users', self.name)
             else:
                 log.debug('Plugin `%s` does not allow to '
                           'create new users', self.name)
 
             user_parameters = {
                 'username': username,
                 'email': auth["email"],
                 'firstname': auth["firstname"],
                 'lastname': auth["lastname"],
                 'active': auth["active"],
                 'admin': auth["admin"],
                 'extern_name': auth["extern_name"],
                 'extern_type': self.name,
                 'plugin': self,
                 'allow_to_create_user': self.allows_creating_users,
             }
 
             if not is_user_existing:
                 if self.use_fake_password():
                     # Randomize the PW because we don't need it, but don't want
                     # them blank either
                     passwd = PasswordGenerator().gen_password(length=16)
                 user_parameters['password'] = passwd
             else:
                 # Since the password is required by create_or_update method of
                 # UserModel, we need to set it explicitly.
                 # The create_or_update method is smart and recognises the
                 # password hashes as well.
                 user_parameters['password'] = cur_user.password
 
             # we either create or update users, we also pass the flag
             # that controls if this method can actually do that.
             # raises NotAllowedToCreateUserError if it cannot, and we try to.
             user = UserModel().create_or_update(**user_parameters)
             Session().flush()
             # enforce user is just in given groups, all of them has to be ones
             # created from plugins. We store this info in _group_data JSON
             # field
 
             if auth['user_group_sync']:
                 try:
                     groups = auth['groups'] or []
                     log.debug(
                         'Performing user_group sync based on set `%s` '
                         'returned by `%s` plugin', groups, self.name)
                     UserGroupModel().enforce_groups(user, groups, self.name)
                 except Exception:
                     # for any reason group syncing fails, we should
                     # proceed with login
                     log.error(traceback.format_exc())
 
             Session().commit()
         return auth
 
 
 class AuthLdapBase(object):
 
     @classmethod
     def _build_servers(cls, ldap_server_type, ldap_server, port, use_resolver=True):
 
         def host_resolver(host, port, full_resolve=True):
             """
             Main work for this function is to prevent ldap connection issues,
             and detect them early using a "greenified" sockets
             """
             host = host.strip()
             if not full_resolve:
                 return '{}:{}'.format(host, port)
 
             log.debug('LDAP: Resolving IP for LDAP host `%s`', host)
             try:
                 ip = socket.gethostbyname(host)
                 log.debug('LDAP: Got LDAP host `%s` ip %s', host, ip)
             except Exception:
                 raise LdapConnectionError('Failed to resolve host: `{}`'.format(host))
 
             log.debug('LDAP: Checking if IP %s is accessible', ip)
             s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
             try:
                 s.connect((ip, int(port)))
                 s.shutdown(socket.SHUT_RD)
                 log.debug('LDAP: connection to %s successful', ip)
             except Exception:
                 raise LdapConnectionError(
                     'Failed to connect to host: `{}:{}`'.format(host, port))
 
             return '{}:{}'.format(host, port)
 
         if len(ldap_server) == 1:
             # in case of single server use resolver to detect potential
             # connection issues
             full_resolve = True
         else:
             full_resolve = False
 
         return ', '.join(
             ["{}://{}".format(
                 ldap_server_type,
                 host_resolver(host, port, full_resolve=use_resolver and full_resolve))
              for host in ldap_server])
 
     @classmethod
     def _get_server_list(cls, servers):
         return map(string.strip, servers.split(','))
 
     @classmethod
     def get_uid(cls, username, server_addresses):
         uid = username
         for server_addr in server_addresses:
             uid = chop_at(username, "@%s" % server_addr)
         return uid
 
     @classmethod
     def validate_username(cls, username):
         if "," in username:
             raise LdapUsernameError(
                 "invalid character `,` in username: `{}`".format(username))
 
     @classmethod
     def validate_password(cls, username, password):
         if not password:
             msg = "Authenticating user %s with blank password not allowed"
             log.warning(msg, username)
             raise LdapPasswordError(msg)
 
 
 def loadplugin(plugin_id):
     """
     Loads and returns an instantiated authentication plugin.
     Returns the RhodeCodeAuthPluginBase subclass on success,
     or None on failure.
     """
     # TODO: Disusing pyramids thread locals to retrieve the registry.
     authn_registry = get_authn_registry()
     plugin = authn_registry.get_plugin(plugin_id)
     if plugin is None:
         log.error('Authentication plugin not found: "%s"', plugin_id)
     return plugin
 
 
 def get_authn_registry(registry=None):
     registry = registry or get_current_registry()
     authn_registry = registry.queryUtility(IAuthnPluginRegistry)
     return authn_registry
 
 
 def authenticate(username, password, environ=None, auth_type=None,
                  skip_missing=False, registry=None, acl_repo_name=None):
     """
     Authentication function used for access control,
     It tries to authenticate based on enabled authentication modules.
 
     :param username: username can be empty for headers auth
     :param password: password can be empty for headers auth
     :param environ: environ headers passed for headers auth
     :param auth_type: type of authentication, either `HTTP_TYPE` or `VCS_TYPE`
     :param skip_missing: ignores plugins that are in db but not in environment
     :returns: None if auth failed, plugin_user dict if auth is correct
     """
     if not auth_type or auth_type not in [HTTP_TYPE, VCS_TYPE]:
         raise ValueError('auth type must be on of http, vcs got "%s" instead'
                          % auth_type)
     headers_only = environ and not (username and password)
 
     authn_registry = get_authn_registry(registry)
 
     plugins_to_check = authn_registry.get_plugins_for_authentication()
     log.debug('Starting ordered authentication chain using %s plugins',
               [x.name for x in plugins_to_check])
     for plugin in plugins_to_check:
         plugin.set_auth_type(auth_type)
         plugin.set_calling_scope_repo(acl_repo_name)
 
         if headers_only and not plugin.is_headers_auth:
             log.debug('Auth type is for headers only and plugin `%s` is not '
                       'headers plugin, skipping...', plugin.get_id())
             continue
 
         log.debug('Trying authentication using ** %s **', plugin.get_id())
 
         # load plugin settings from RhodeCode database
         plugin_settings = plugin.get_settings()
         plugin_sanitized_settings = plugin.log_safe_settings(plugin_settings)
         log.debug('Plugin `%s` settings:%s', plugin.get_id(), plugin_sanitized_settings)
 
         # use plugin's method of user extraction.
         user = plugin.get_user(username, environ=environ,
                                settings=plugin_settings)
         display_user = user.username if user else username
         log.debug(
             'Plugin %s extracted user is `%s`', plugin.get_id(), display_user)
 
         if not plugin.allows_authentication_from(user):
             log.debug('Plugin %s does not accept user `%s` for authentication',
                       plugin.get_id(), display_user)
             continue
         else:
             log.debug('Plugin %s accepted user `%s` for authentication',
                       plugin.get_id(), display_user)
 
         log.info('Authenticating user `%s` using %s plugin',
                  display_user, plugin.get_id())
 
         plugin_cache_active, cache_ttl = plugin.get_ttl_cache(plugin_settings)
 
         log.debug('AUTH_CACHE_TTL for plugin `%s` active: %s (TTL: %s)',
                   plugin.get_id(), plugin_cache_active, cache_ttl)
 
         user_id = user.user_id if user else 'no-user'
         # don't cache for empty users
         plugin_cache_active = plugin_cache_active and user_id
         cache_namespace_uid = 'cache_user_auth.{}'.format(user_id)
         region = rc_cache.get_or_create_region('cache_perms', cache_namespace_uid)
 
         @region.conditional_cache_on_arguments(namespace=cache_namespace_uid,
                                                expiration_time=cache_ttl,
                                                condition=plugin_cache_active)
         def compute_auth(
                 cache_name, plugin_name, username, password):
 
             # _authenticate is a wrapper for .auth() method of plugin.
             # it checks if .auth() sends proper data.
             # For RhodeCodeExternalAuthPlugin it also maps users to
             # Database and maps the attributes returned from .auth()
             # to RhodeCode database. If this function returns data
             # then auth is correct.
             log.debug('Running plugin `%s` _authenticate method '
                       'using username and password', plugin.get_id())
             return plugin._authenticate(
                 user, username, password, plugin_settings,
                 environ=environ or {})
 
         start = time.time()
         # for environ based auth, password can be empty, but then the validation is
         # on the server that fills in the env data needed for authentication
         plugin_user = compute_auth('auth', plugin.name, username, (password or ''))
 
         auth_time = time.time() - start
         log.debug('Authentication for plugin `%s` completed in %.4fs, '
                   'expiration time of fetched cache %.1fs.',
-                  plugin.get_id(), auth_time, cache_ttl)
+                  plugin.get_id(), auth_time, cache_ttl,
+                  extra={"plugin": plugin.get_id(), "time": auth_time})
 
         log.debug('PLUGIN USER DATA: %s', plugin_user)
 
         statsd = StatsdClient.statsd
 
         if plugin_user:
             log.debug('Plugin returned proper authentication data')
             if statsd:
+                elapsed_time_ms = round(1000.0 * auth_time)  # use ms only
                 statsd.incr('rhodecode_login_success_total')
+                statsd.timing("rhodecode_login_timing.histogram", elapsed_time_ms,
+                              tags=["plugin:{}".format(plugin.get_id())],
+                              use_decimals=False
+                )
             return plugin_user
 
         # we failed to Auth because .auth() method didn't return proper user
         log.debug("User `%s` failed to authenticate against %s",
                   display_user, plugin.get_id())
         if statsd:
             statsd.incr('rhodecode_login_fail_total')
 
     # case when we failed to authenticate against all defined plugins
     return None
 
 
 def chop_at(s, sub, inclusive=False):
     """Truncate string ``s`` at the first occurrence of ``sub``.
 
     If ``inclusive`` is true, truncate just after ``sub`` rather than at it.
 
     >>> chop_at("plutocratic brats", "rat")
     'plutoc'
     >>> chop_at("plutocratic brats", "rat", True)
     'plutocrat'
     """
     pos = s.find(sub)
     if pos == -1:
         return s
     if inclusive:
         return s[:pos+len(sub)]
     return s[:pos]

rhodecode/authentication/plugins/auth_headers.py

@@ -1,231 +1,232 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2012-2020 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 colander
 import logging
 
 from rhodecode.translation import _
 from rhodecode.authentication.base import (
     RhodeCodeExternalAuthPlugin, hybrid_property)
 from rhodecode.authentication.schema import AuthnPluginSettingsSchemaBase
 from rhodecode.authentication.routes import AuthnPluginResourceBase
 from rhodecode.lib.colander_utils import strip_whitespace
 from rhodecode.lib.utils2 import str2bool, safe_unicode
 from rhodecode.model.db import User
 
 
 log = logging.getLogger(__name__)
 
 
 def plugin_factory(plugin_id, *args, **kwargs):
     """
     Factory function that is called during plugin discovery.
     It returns the plugin instance.
     """
     plugin = RhodeCodeAuthPlugin(plugin_id)
     return plugin
 
 
 class HeadersAuthnResource(AuthnPluginResourceBase):
     pass
 
 
 class HeadersSettingsSchema(AuthnPluginSettingsSchemaBase):
     header = colander.SchemaNode(
         colander.String(),
         default='REMOTE_USER',
         description=_('Header to extract the user from'),
         preparer=strip_whitespace,
         title=_('Header'),
         widget='string')
     fallback_header = colander.SchemaNode(
         colander.String(),
         default='HTTP_X_FORWARDED_USER',
         description=_('Header to extract the user from when main one fails'),
         preparer=strip_whitespace,
         title=_('Fallback header'),
         widget='string')
     clean_username = colander.SchemaNode(
         colander.Boolean(),
         default=True,
         description=_('Perform cleaning of user, if passed user has @ in '
                       'username then first part before @ is taken. '
                       'If there\'s \\ in the username only the part after '
                       ' \\ is taken'),
         missing=False,
         title=_('Clean username'),
         widget='bool')
 
 
 class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
     uid = 'headers'
 
     def includeme(self, config):
         config.add_authn_plugin(self)
         config.add_authn_resource(self.get_id(), HeadersAuthnResource(self))
         config.add_view(
             'rhodecode.authentication.views.AuthnPluginViewBase',
             attr='settings_get',
             renderer='rhodecode:templates/admin/auth/plugin_settings.mako',
             request_method='GET',
             route_name='auth_home',
             context=HeadersAuthnResource)
         config.add_view(
             'rhodecode.authentication.views.AuthnPluginViewBase',
             attr='settings_post',
             renderer='rhodecode:templates/admin/auth/plugin_settings.mako',
             request_method='POST',
             route_name='auth_home',
             context=HeadersAuthnResource)
 
     def get_display_name(self, load_from_settings=False):
         return _('Headers')
 
     def get_settings_schema(self):
         return HeadersSettingsSchema()
 
     @hybrid_property
     def name(self):
         return u"headers"
 
     @property
     def is_headers_auth(self):
         return True
 
     def use_fake_password(self):
         return True
 
     def user_activation_state(self):
         def_user_perms = User.get_default_user().AuthUser().permissions['global']
         return 'hg.extern_activate.auto' in def_user_perms
 
     def _clean_username(self, username):
         # Removing realm and domain from username
         username = username.split('@')[0]
         username = username.rsplit('\\')[-1]
         return username
 
     def _get_username(self, environ, settings):
         username = None
         environ = environ or {}
         if not environ:
             log.debug('got empty environ: %s', environ)
 
         settings = settings or {}
         if settings.get('header'):
             header = settings.get('header')
             username = environ.get(header)
             log.debug('extracted %s:%s', header, username)
 
         # fallback mode
         if not username and settings.get('fallback_header'):
             header = settings.get('fallback_header')
             username = environ.get(header)
             log.debug('extracted %s:%s', header, username)
 
         if username and str2bool(settings.get('clean_username')):
             log.debug('Received username `%s` from headers', username)
             username = self._clean_username(username)
             log.debug('New cleanup user is:%s', username)
         return username
 
     def get_user(self, username=None, **kwargs):
         """
         Helper method for user fetching in plugins, by default it's using
         simple fetch by username, but this method can be custimized in plugins
         eg. headers auth plugin to fetch user by environ params
         :param username: username if given to fetch
         :param kwargs: extra arguments needed for user fetching.
         """
         environ = kwargs.get('environ') or {}
         settings = kwargs.get('settings') or {}
         username = self._get_username(environ, settings)
         # we got the username, so use default method now
         return super(RhodeCodeAuthPlugin, self).get_user(username)
 
     def auth(self, userobj, username, password, settings, **kwargs):
         """
         Get's the headers_auth username (or email). It tries to get username
         from REMOTE_USER if this plugin is enabled, if that fails
         it tries to get username from HTTP_X_FORWARDED_USER if fallback header
         is set. clean_username extracts the username from this data if it's
         having @ in it.
         Return None on failure. On success, return a dictionary of the form:
 
             see: RhodeCodeAuthPluginBase.auth_func_attrs
 
         :param userobj:
         :param username:
         :param password:
         :param settings:
         :param kwargs:
         """
         environ = kwargs.get('environ')
         if not environ:
             log.debug('Empty environ data skipping...')
             return None
 
         if not userobj:
             userobj = self.get_user('', environ=environ, settings=settings)
 
         # we don't care passed username/password for headers auth plugins.
         # only way to log in is using environ
         username = None
         if userobj:
             username = getattr(userobj, 'username')
 
         if not username:
             # we don't have any objects in DB user doesn't exist extract
             # username from environ based on the settings
             username = self._get_username(environ, settings)
 
         # if cannot fetch username, it's a no-go for this plugin to proceed
         if not username:
             return None
 
         # old attrs fetched from RhodeCode database
         admin = getattr(userobj, 'admin', False)
         active = getattr(userobj, 'active', True)
         email = getattr(userobj, 'email', '')
         firstname = getattr(userobj, 'firstname', '')
         lastname = getattr(userobj, 'lastname', '')
         extern_type = getattr(userobj, 'extern_type', '')
 
         user_attrs = {
             'username': username,
             'firstname': safe_unicode(firstname or username),
             'lastname': safe_unicode(lastname or ''),
             'groups': [],
             'user_group_sync': False,
             'email': email or '',
             'admin': admin or False,
             'active': active,
             'active_from_extern': True,
             'extern_name': username,
             'extern_type': extern_type,
         }
 
-        log.info('user `%s` authenticated correctly', user_attrs['username'])
+        log.info('user `%s` authenticated correctly', user_attrs['username'],
+                 extra={"action": "user_auth_ok", "module": "auth_headers", "username": user_attrs["username"]})
         return user_attrs
 
 
 def includeme(config):
     plugin_id = 'egg:rhodecode-enterprise-ce#{}'.format(RhodeCodeAuthPlugin.uid)
     plugin_factory(plugin_id).includeme(config)

rhodecode/authentication/plugins/auth_ldap.py

@@ -1,551 +1,552 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2010-2020 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/
 
 """
 RhodeCode authentication plugin for LDAP
 """
 
 import logging
 import traceback
 
 import colander
 from rhodecode.translation import _
 from rhodecode.authentication.base import (
     RhodeCodeExternalAuthPlugin, AuthLdapBase, hybrid_property)
 from rhodecode.authentication.schema import AuthnPluginSettingsSchemaBase
 from rhodecode.authentication.routes import AuthnPluginResourceBase
 from rhodecode.lib.colander_utils import strip_whitespace
 from rhodecode.lib.exceptions import (
     LdapConnectionError, LdapUsernameError, LdapPasswordError, LdapImportError
 )
 from rhodecode.lib.utils2 import safe_unicode, safe_str
 from rhodecode.model.db import User
 from rhodecode.model.validators import Missing
 
 log = logging.getLogger(__name__)
 
 try:
     import ldap
 except ImportError:
     # means that python-ldap is not installed, we use Missing object to mark
     # ldap lib is Missing
     ldap = Missing
 
 
 class LdapError(Exception):
     pass
 
 
 def plugin_factory(plugin_id, *args, **kwargs):
     """
     Factory function that is called during plugin discovery.
     It returns the plugin instance.
     """
     plugin = RhodeCodeAuthPlugin(plugin_id)
     return plugin
 
 
 class LdapAuthnResource(AuthnPluginResourceBase):
     pass
 
 
 class AuthLdap(AuthLdapBase):
     default_tls_cert_dir = '/etc/openldap/cacerts'
 
     scope_labels = {
         ldap.SCOPE_BASE: 'SCOPE_BASE',
         ldap.SCOPE_ONELEVEL: 'SCOPE_ONELEVEL',
         ldap.SCOPE_SUBTREE: 'SCOPE_SUBTREE',
     }
 
     def __init__(self, server, base_dn, port=389, bind_dn='', bind_pass='',
                  tls_kind='PLAIN', tls_reqcert='DEMAND', tls_cert_file=None,
                  tls_cert_dir=None, ldap_version=3,
                  search_scope='SUBTREE', attr_login='uid',
                  ldap_filter='', timeout=None):
         if ldap == Missing:
             raise LdapImportError("Missing or incompatible ldap library")
 
         self.debug = False
         self.timeout = timeout or 60 * 5
         self.ldap_version = ldap_version
         self.ldap_server_type = 'ldap'
 
         self.TLS_KIND = tls_kind
 
         if self.TLS_KIND == 'LDAPS':
             port = port or 636
             self.ldap_server_type += 's'
 
         OPT_X_TLS_DEMAND = 2
         self.TLS_REQCERT = getattr(ldap, 'OPT_X_TLS_%s' % tls_reqcert, OPT_X_TLS_DEMAND)
         self.TLS_CERT_FILE = tls_cert_file or ''
         self.TLS_CERT_DIR = tls_cert_dir or self.default_tls_cert_dir
 
         # split server into list
         self.SERVER_ADDRESSES = self._get_server_list(server)
         self.LDAP_SERVER_PORT = port
 
         # USE FOR READ ONLY BIND TO LDAP SERVER
         self.attr_login = attr_login
 
         self.LDAP_BIND_DN = safe_str(bind_dn)
         self.LDAP_BIND_PASS = safe_str(bind_pass)
 
         self.SEARCH_SCOPE = getattr(ldap, 'SCOPE_%s' % search_scope)
         self.BASE_DN = safe_str(base_dn)
         self.LDAP_FILTER = safe_str(ldap_filter)
 
     def _get_ldap_conn(self):
 
         if self.debug:
             ldap.set_option(ldap.OPT_DEBUG_LEVEL, 255)
 
         if self.TLS_CERT_FILE and hasattr(ldap, 'OPT_X_TLS_CACERTFILE'):
             ldap.set_option(ldap.OPT_X_TLS_CACERTFILE, self.TLS_CERT_FILE)
 
         elif hasattr(ldap, 'OPT_X_TLS_CACERTDIR'):
             ldap.set_option(ldap.OPT_X_TLS_CACERTDIR, self.TLS_CERT_DIR)
 
         if self.TLS_KIND != 'PLAIN':
             ldap.set_option(ldap.OPT_X_TLS_REQUIRE_CERT, self.TLS_REQCERT)
 
         ldap.set_option(ldap.OPT_REFERRALS, ldap.OPT_OFF)
         ldap.set_option(ldap.OPT_RESTART, ldap.OPT_ON)
 
         # init connection now
         ldap_servers = self._build_servers(
             self.ldap_server_type,  self.SERVER_ADDRESSES, self.LDAP_SERVER_PORT)
         log.debug('initializing LDAP connection to:%s', ldap_servers)
         ldap_conn = ldap.initialize(ldap_servers)
         ldap_conn.set_option(ldap.OPT_NETWORK_TIMEOUT, self.timeout)
         ldap_conn.set_option(ldap.OPT_TIMEOUT, self.timeout)
         ldap_conn.timeout = self.timeout
 
         if self.ldap_version == 2:
             ldap_conn.protocol = ldap.VERSION2
         else:
             ldap_conn.protocol = ldap.VERSION3
 
         if self.TLS_KIND == 'START_TLS':
             ldap_conn.start_tls_s()
 
         if self.LDAP_BIND_DN and self.LDAP_BIND_PASS:
             log.debug('Trying simple_bind with password and given login DN: %r',
                       self.LDAP_BIND_DN)
             ldap_conn.simple_bind_s(self.LDAP_BIND_DN, self.LDAP_BIND_PASS)
         log.debug('simple_bind successful')
         return ldap_conn
 
     def fetch_attrs_from_simple_bind(self, ldap_conn, dn, username, password):
         scope = ldap.SCOPE_BASE
         scope_label = self.scope_labels.get(scope)
         ldap_filter = '(objectClass=*)'
 
         try:
             log.debug('Trying authenticated search bind with dn: %r SCOPE: %s (and filter: %s)',
                       dn, scope_label, ldap_filter)
             ldap_conn.simple_bind_s(dn, safe_str(password))
             response = ldap_conn.search_ext_s(dn, scope, ldap_filter, attrlist=['*', '+'])
 
             if not response:
                 log.error('search bind returned empty results: %r', response)
                 return {}
             else:
                 _dn, attrs = response[0]
                 return attrs
 
         except ldap.INVALID_CREDENTIALS:
             log.debug("LDAP rejected password for user '%s': %s, org_exc:",
                       username, dn, exc_info=True)
 
     def authenticate_ldap(self, username, password):
         """
         Authenticate a user via LDAP and return his/her LDAP properties.
 
         Raises AuthenticationError if the credentials are rejected, or
         EnvironmentError if the LDAP server can't be reached.
 
         :param username: username
         :param password: password
         """
 
         uid = self.get_uid(username, self.SERVER_ADDRESSES)
         user_attrs = {}
         dn = ''
 
         self.validate_password(username, password)
         self.validate_username(username)
         scope_label = self.scope_labels.get(self.SEARCH_SCOPE)
 
         ldap_conn = None
         try:
             ldap_conn = self._get_ldap_conn()
             filter_ = '(&%s(%s=%s))' % (
                 self.LDAP_FILTER, self.attr_login, username)
             log.debug("Authenticating %r filter %s and scope: %s",
                       self.BASE_DN, filter_, scope_label)
 
             ldap_objects = ldap_conn.search_ext_s(
                 self.BASE_DN, self.SEARCH_SCOPE, filter_, attrlist=['*', '+'])
 
             if not ldap_objects:
                 log.debug("No matching LDAP objects for authentication "
                           "of UID:'%s' username:(%s)", uid, username)
                 raise ldap.NO_SUCH_OBJECT()
 
             log.debug('Found %s matching ldap object[s], trying to authenticate on each one now...', len(ldap_objects))
             for (dn, _attrs) in ldap_objects:
                 if dn is None:
                     continue
 
                 user_attrs = self.fetch_attrs_from_simple_bind(
                     ldap_conn, dn, username, password)
 
                 if user_attrs:
                     log.debug('Got authenticated user attributes from DN:%s', dn)
                     break
             else:
                 raise LdapPasswordError(
                     'Failed to authenticate user `{}` with given password'.format(username))
 
         except ldap.NO_SUCH_OBJECT:
             log.debug("LDAP says no such user '%s' (%s), org_exc:",
                       uid, username, exc_info=True)
             raise LdapUsernameError('Unable to find user')
         except ldap.SERVER_DOWN:
             org_exc = traceback.format_exc()
             raise LdapConnectionError(
                 "LDAP can't access authentication server, org_exc:%s" % org_exc)
         finally:
             if ldap_conn:
                 log.debug('ldap: connection release')
                 try:
                     ldap_conn.unbind_s()
                 except Exception:
                     # for any reason this can raise exception we must catch it
                     # to not crush the server
                     pass
 
         return dn, user_attrs
 
 
 class LdapSettingsSchema(AuthnPluginSettingsSchemaBase):
     tls_kind_choices = ['PLAIN', 'LDAPS', 'START_TLS']
     tls_reqcert_choices = ['NEVER', 'ALLOW', 'TRY', 'DEMAND', 'HARD']
     search_scope_choices = ['BASE', 'ONELEVEL', 'SUBTREE']
 
     host = colander.SchemaNode(
         colander.String(),
         default='',
         description=_('Host[s] of the LDAP Server \n'
                       '(e.g., 192.168.2.154, or ldap-server.domain.com.\n '
                       'Multiple servers can be specified using commas'),
         preparer=strip_whitespace,
         title=_('LDAP Host'),
         widget='string')
     port = colander.SchemaNode(
         colander.Int(),
         default=389,
         description=_('Custom port that the LDAP server is listening on. '
                       'Default value is: 389, use 636 for LDAPS (SSL)'),
         preparer=strip_whitespace,
         title=_('Port'),
         validator=colander.Range(min=0, max=65536),
         widget='int')
 
     timeout = colander.SchemaNode(
         colander.Int(),
         default=60 * 5,
         description=_('Timeout for LDAP connection'),
         preparer=strip_whitespace,
         title=_('Connection timeout'),
         validator=colander.Range(min=1),
         widget='int')
 
     dn_user = colander.SchemaNode(
         colander.String(),
         default='',
         description=_('Optional user DN/account to connect to LDAP if authentication is required. \n'
                       'e.g., cn=admin,dc=mydomain,dc=com, or '
                       'uid=root,cn=users,dc=mydomain,dc=com, or [e-mail]'),
         missing='',
         preparer=strip_whitespace,
         title=_('Bind account'),
         widget='string')
     dn_pass = colander.SchemaNode(
         colander.String(),
         default='',
         description=_('Password to authenticate for given user DN.'),
         missing='',
         preparer=strip_whitespace,
         title=_('Bind account password'),
         widget='password')
     tls_kind = colander.SchemaNode(
         colander.String(),
         default=tls_kind_choices[0],
         description=_('TLS Type'),
         title=_('Connection Security'),
         validator=colander.OneOf(tls_kind_choices),
         widget='select')
     tls_reqcert = colander.SchemaNode(
         colander.String(),
         default=tls_reqcert_choices[0],
         description=_('Require Cert over TLS?. Self-signed and custom '
                       'certificates can be used when\n `RhodeCode Certificate` '
                       'found in admin > settings > system info page is extended.'),
         title=_('Certificate Checks'),
         validator=colander.OneOf(tls_reqcert_choices),
         widget='select')
     tls_cert_file = colander.SchemaNode(
         colander.String(),
         default='',
         description=_('This specifies the PEM-format file path containing '
                       'certificates for use in TLS connection.\n'
                       'If not specified `TLS Cert dir` will be used'),
         title=_('TLS Cert file'),
         missing='',
         widget='string')
     tls_cert_dir = colander.SchemaNode(
         colander.String(),
         default=AuthLdap.default_tls_cert_dir,
         description=_('This specifies the path of a directory that contains individual '
                       'CA certificates in separate files.'),
         title=_('TLS Cert dir'),
         widget='string')
     base_dn = colander.SchemaNode(
         colander.String(),
         default='',
         description=_('Base DN to search. Dynamic bind is supported. Add `$login` marker '
                       'in it to be replaced with current user username \n'
                       '(e.g., dc=mydomain,dc=com, or ou=Users,dc=mydomain,dc=com)'),
         missing='',
         preparer=strip_whitespace,
         title=_('Base DN'),
         widget='string')
     filter = colander.SchemaNode(
         colander.String(),
         default='',
         description=_('Filter to narrow results \n'
                       '(e.g., (&(objectCategory=Person)(objectClass=user)), or \n'
                       '(memberof=cn=rc-login,ou=groups,ou=company,dc=mydomain,dc=com)))'),
         missing='',
         preparer=strip_whitespace,
         title=_('LDAP Search Filter'),
         widget='string')
 
     search_scope = colander.SchemaNode(
         colander.String(),
         default=search_scope_choices[2],
         description=_('How deep to search LDAP. If unsure set to SUBTREE'),
         title=_('LDAP Search Scope'),
         validator=colander.OneOf(search_scope_choices),
         widget='select')
     attr_login = colander.SchemaNode(
         colander.String(),
         default='uid',
         description=_('LDAP Attribute to map to user name (e.g., uid, or sAMAccountName)'),
         preparer=strip_whitespace,
         title=_('Login Attribute'),
         missing_msg=_('The LDAP Login attribute of the CN must be specified'),
         widget='string')
     attr_email = colander.SchemaNode(
         colander.String(),
         default='',
         description=_('LDAP Attribute to map to email address (e.g., mail).\n'
                       'Emails are a crucial part of RhodeCode. \n'
                       'If possible add a valid email attribute to ldap users.'),
         missing='',
         preparer=strip_whitespace,
         title=_('Email Attribute'),
         widget='string')
     attr_firstname = colander.SchemaNode(
         colander.String(),
         default='',
         description=_('LDAP Attribute to map to first name (e.g., givenName)'),
         missing='',
         preparer=strip_whitespace,
         title=_('First Name Attribute'),
         widget='string')
     attr_lastname = colander.SchemaNode(
         colander.String(),
         default='',
         description=_('LDAP Attribute to map to last name (e.g., sn)'),
         missing='',
         preparer=strip_whitespace,
         title=_('Last Name Attribute'),
         widget='string')
 
 
 class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
     uid = 'ldap'
     # used to define dynamic binding in the
     DYNAMIC_BIND_VAR = '$login'
     _settings_unsafe_keys = ['dn_pass']
 
     def includeme(self, config):
         config.add_authn_plugin(self)
         config.add_authn_resource(self.get_id(), LdapAuthnResource(self))
         config.add_view(
             'rhodecode.authentication.views.AuthnPluginViewBase',
             attr='settings_get',
             renderer='rhodecode:templates/admin/auth/plugin_settings.mako',
             request_method='GET',
             route_name='auth_home',
             context=LdapAuthnResource)
         config.add_view(
             'rhodecode.authentication.views.AuthnPluginViewBase',
             attr='settings_post',
             renderer='rhodecode:templates/admin/auth/plugin_settings.mako',
             request_method='POST',
             route_name='auth_home',
             context=LdapAuthnResource)
 
     def get_settings_schema(self):
         return LdapSettingsSchema()
 
     def get_display_name(self, load_from_settings=False):
         return _('LDAP')
 
     @classmethod
     def docs(cls):
         return "https://docs.rhodecode.com/RhodeCode-Enterprise/auth/auth-ldap.html"
 
     @hybrid_property
     def name(self):
         return u"ldap"
 
     def use_fake_password(self):
         return True
 
     def user_activation_state(self):
         def_user_perms = User.get_default_user().AuthUser().permissions['global']
         return 'hg.extern_activate.auto' in def_user_perms
 
     def try_dynamic_binding(self, username, password, current_args):
         """
         Detects marker inside our original bind, and uses dynamic auth if
         present
         """
 
         org_bind = current_args['bind_dn']
         passwd = current_args['bind_pass']
 
         def has_bind_marker(username):
             if self.DYNAMIC_BIND_VAR in username:
                 return True
 
         # we only passed in user with "special" variable
         if org_bind and has_bind_marker(org_bind) and not passwd:
             log.debug('Using dynamic user/password binding for ldap '
                       'authentication. Replacing `%s` with username',
                       self.DYNAMIC_BIND_VAR)
             current_args['bind_dn'] = org_bind.replace(
                 self.DYNAMIC_BIND_VAR, username)
             current_args['bind_pass'] = password
 
         return current_args
 
     def auth(self, userobj, username, password, settings, **kwargs):
         """
         Given a user object (which may be null), username, a plaintext password,
         and a settings object (containing all the keys needed as listed in
         settings()), authenticate this user's login attempt.
 
         Return None on failure. On success, return a dictionary of the form:
 
             see: RhodeCodeAuthPluginBase.auth_func_attrs
         This is later validated for correctness
         """
 
         if not username or not password:
             log.debug('Empty username or password skipping...')
             return None
 
         ldap_args = {
             'server': settings.get('host', ''),
             'base_dn': settings.get('base_dn', ''),
             'port': settings.get('port'),
             'bind_dn': settings.get('dn_user'),
             'bind_pass': settings.get('dn_pass'),
             'tls_kind': settings.get('tls_kind'),
             'tls_reqcert': settings.get('tls_reqcert'),
             'tls_cert_file': settings.get('tls_cert_file'),
             'tls_cert_dir': settings.get('tls_cert_dir'),
             'search_scope': settings.get('search_scope'),
             'attr_login': settings.get('attr_login'),
             'ldap_version': 3,
             'ldap_filter': settings.get('filter'),
             'timeout': settings.get('timeout')
         }
 
         ldap_attrs = self.try_dynamic_binding(username, password, ldap_args)
 
         log.debug('Checking for ldap authentication.')
 
         try:
             aldap = AuthLdap(**ldap_args)
             (user_dn, ldap_attrs) = aldap.authenticate_ldap(username, password)
             log.debug('Got ldap DN response %s', user_dn)
 
             def get_ldap_attr(k):
                 return ldap_attrs.get(settings.get(k), [''])[0]
 
             # old attrs fetched from RhodeCode database
             admin = getattr(userobj, 'admin', False)
             active = getattr(userobj, 'active', True)
             email = getattr(userobj, 'email', '')
             username = getattr(userobj, 'username', username)
             firstname = getattr(userobj, 'firstname', '')
             lastname = getattr(userobj, 'lastname', '')
             extern_type = getattr(userobj, 'extern_type', '')
 
             groups = []
 
             user_attrs = {
                 'username': username,
                 'firstname': safe_unicode(get_ldap_attr('attr_firstname') or firstname),
                 'lastname': safe_unicode(get_ldap_attr('attr_lastname') or lastname),
                 'groups': groups,
                 'user_group_sync': False,
                 'email': get_ldap_attr('attr_email') or email,
                 'admin': admin,
                 'active': active,
                 'active_from_extern': None,
                 'extern_name': user_dn,
                 'extern_type': extern_type,
             }
 
             log.debug('ldap user: %s', user_attrs)
-            log.info('user `%s` authenticated correctly', user_attrs['username'])
+            log.info('user `%s` authenticated correctly', user_attrs['username'],
+                     extra={"action": "user_auth_ok", "module": "auth_ldap", "username": user_attrs["username"]})
 
             return user_attrs
 
         except (LdapUsernameError, LdapPasswordError, LdapImportError):
             log.exception("LDAP related exception")
             return None
         except (Exception,):
             log.exception("Other exception")
             return None
 
 
 def includeme(config):
     plugin_id = 'egg:rhodecode-enterprise-ce#{}'.format(RhodeCodeAuthPlugin.uid)
     plugin_factory(plugin_id).includeme(config)

rhodecode/authentication/plugins/auth_pam.py

@@ -1,171 +1,172 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2012-2020 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/
 
 """
 RhodeCode authentication library for PAM
 """
 
 import colander
 import grp
 import logging
 import pam
 import pwd
 import re
 import socket
 
 from rhodecode.translation import _
 from rhodecode.authentication.base import (
     RhodeCodeExternalAuthPlugin, hybrid_property)
 from rhodecode.authentication.schema import AuthnPluginSettingsSchemaBase
 from rhodecode.authentication.routes import AuthnPluginResourceBase
 from rhodecode.lib.colander_utils import strip_whitespace
 
 log = logging.getLogger(__name__)
 
 
 def plugin_factory(plugin_id, *args, **kwargs):
     """
     Factory function that is called during plugin discovery.
     It returns the plugin instance.
     """
     plugin = RhodeCodeAuthPlugin(plugin_id)
     return plugin
 
 
 class PamAuthnResource(AuthnPluginResourceBase):
     pass
 
 
 class PamSettingsSchema(AuthnPluginSettingsSchemaBase):
     service = colander.SchemaNode(
         colander.String(),
         default='login',
         description=_('PAM service name to use for authentication.'),
         preparer=strip_whitespace,
         title=_('PAM service name'),
         widget='string')
     gecos = colander.SchemaNode(
         colander.String(),
         default='(?P<last_name>.+),\s*(?P<first_name>\w+)',
         description=_('Regular expression for extracting user name/email etc. '
                       'from Unix userinfo.'),
         preparer=strip_whitespace,
         title=_('Gecos Regex'),
         widget='string')
 
 
 class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
     uid = 'pam'
     # PAM authentication can be slow. Repository operations involve a lot of
     # auth calls. Little caching helps speedup push/pull operations significantly
     AUTH_CACHE_TTL = 4
 
     def includeme(self, config):
         config.add_authn_plugin(self)
         config.add_authn_resource(self.get_id(), PamAuthnResource(self))
         config.add_view(
             'rhodecode.authentication.views.AuthnPluginViewBase',
             attr='settings_get',
             renderer='rhodecode:templates/admin/auth/plugin_settings.mako',
             request_method='GET',
             route_name='auth_home',
             context=PamAuthnResource)
         config.add_view(
             'rhodecode.authentication.views.AuthnPluginViewBase',
             attr='settings_post',
             renderer='rhodecode:templates/admin/auth/plugin_settings.mako',
             request_method='POST',
             route_name='auth_home',
             context=PamAuthnResource)
 
     def get_display_name(self, load_from_settings=False):
         return _('PAM')
 
     @classmethod
     def docs(cls):
         return "https://docs.rhodecode.com/RhodeCode-Enterprise/auth/auth-pam.html"
 
     @hybrid_property
     def name(self):
         return u"pam"
 
     def get_settings_schema(self):
         return PamSettingsSchema()
 
     def use_fake_password(self):
         return True
 
     def auth(self, userobj, username, password, settings, **kwargs):
         if not username or not password:
             log.debug('Empty username or password skipping...')
             return None
         _pam = pam.pam()
         auth_result = _pam.authenticate(username, password, settings["service"])
 
         if not auth_result:
             log.error("PAM was unable to authenticate user: %s", username)
             return None
 
         log.debug('Got PAM response %s', auth_result)
 
         # old attrs fetched from RhodeCode database
         default_email = "%s@%s" % (username, socket.gethostname())
         admin = getattr(userobj, 'admin', False)
         active = getattr(userobj, 'active', True)
         email = getattr(userobj, 'email', '') or default_email
         username = getattr(userobj, 'username', username)
         firstname = getattr(userobj, 'firstname', '')
         lastname = getattr(userobj, 'lastname', '')
         extern_type = getattr(userobj, 'extern_type', '')
 
         user_attrs = {
             'username': username,
             'firstname': firstname,
             'lastname': lastname,
             'groups': [g.gr_name for g in grp.getgrall()
                        if username in g.gr_mem],
             'user_group_sync': True,
             'email': email,
             'admin': admin,
             'active': active,
             'active_from_extern': None,
             'extern_name': username,
             'extern_type': extern_type,
         }
 
         try:
             user_data = pwd.getpwnam(username)
             regex = settings["gecos"]
             match = re.search(regex, user_data.pw_gecos)
             if match:
                 user_attrs["firstname"] = match.group('first_name')
                 user_attrs["lastname"] = match.group('last_name')
         except Exception:
             log.warning("Cannot extract additional info for PAM user")
             pass
 
         log.debug("pamuser: %s", user_attrs)
-        log.info('user `%s` authenticated correctly', user_attrs['username'])
+        log.info('user `%s` authenticated correctly', user_attrs['username'],
+                 extra={"action": "user_auth_ok", "module": "auth_pam", "username": user_attrs["username"]})
         return user_attrs
 
 
 def includeme(config):
     plugin_id = 'egg:rhodecode-enterprise-ce#{}'.format(RhodeCodeAuthPlugin.uid)
     plugin_factory(plugin_id).includeme(config)

rhodecode/authentication/plugins/auth_rhodecode.py

@@ -1,220 +1,222 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2012-2020 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/
 
 """
 RhodeCode authentication plugin for built in internal auth
 """
 
 import logging
 
 import colander
 
 from rhodecode.translation import _
 from rhodecode.lib.utils2 import safe_str
 from rhodecode.model.db import User
 from rhodecode.authentication.schema import AuthnPluginSettingsSchemaBase
 from rhodecode.authentication.base import (
     RhodeCodeAuthPluginBase, hybrid_property, HTTP_TYPE, VCS_TYPE)
 from rhodecode.authentication.routes import AuthnPluginResourceBase
 
 log = logging.getLogger(__name__)
 
 
 def plugin_factory(plugin_id, *args, **kwargs):
     plugin = RhodeCodeAuthPlugin(plugin_id)
     return plugin
 
 
 class RhodecodeAuthnResource(AuthnPluginResourceBase):
     pass
 
 
 class RhodeCodeAuthPlugin(RhodeCodeAuthPluginBase):
     uid = 'rhodecode'
     AUTH_RESTRICTION_NONE = 'user_all'
     AUTH_RESTRICTION_SUPER_ADMIN = 'user_super_admin'
     AUTH_RESTRICTION_SCOPE_ALL = 'scope_all'
     AUTH_RESTRICTION_SCOPE_HTTP = 'scope_http'
     AUTH_RESTRICTION_SCOPE_VCS = 'scope_vcs'
 
     def includeme(self, config):
         config.add_authn_plugin(self)
         config.add_authn_resource(self.get_id(), RhodecodeAuthnResource(self))
         config.add_view(
             'rhodecode.authentication.views.AuthnPluginViewBase',
             attr='settings_get',
             renderer='rhodecode:templates/admin/auth/plugin_settings.mako',
             request_method='GET',
             route_name='auth_home',
             context=RhodecodeAuthnResource)
         config.add_view(
             'rhodecode.authentication.views.AuthnPluginViewBase',
             attr='settings_post',
             renderer='rhodecode:templates/admin/auth/plugin_settings.mako',
             request_method='POST',
             route_name='auth_home',
             context=RhodecodeAuthnResource)
 
     def get_settings_schema(self):
         return RhodeCodeSettingsSchema()
 
     def get_display_name(self, load_from_settings=False):
         return _('RhodeCode Internal')
 
     @classmethod
     def docs(cls):
         return "https://docs.rhodecode.com/RhodeCode-Enterprise/auth/auth.html"
 
     @hybrid_property
     def name(self):
         return u"rhodecode"
 
     def user_activation_state(self):
         def_user_perms = User.get_default_user().AuthUser().permissions['global']
         return 'hg.register.auto_activate' in def_user_perms
 
     def allows_authentication_from(
             self, user, allows_non_existing_user=True,
             allowed_auth_plugins=None, allowed_auth_sources=None):
         """
         Custom method for this auth that doesn't accept non existing users.
         We know that user exists in our database.
         """
         allows_non_existing_user = False
         return super(RhodeCodeAuthPlugin, self).allows_authentication_from(
             user, allows_non_existing_user=allows_non_existing_user)
 
     def auth(self, userobj, username, password, settings, **kwargs):
         if not userobj:
             log.debug('userobj was:%s skipping', userobj)
             return None
 
         if userobj.extern_type != self.name:
             log.warning("userobj:%s extern_type mismatch got:`%s` expected:`%s`",
                         userobj, userobj.extern_type, self.name)
             return None
 
         # check scope of auth
         scope_restriction = settings.get('scope_restriction', '')
 
         if scope_restriction == self.AUTH_RESTRICTION_SCOPE_HTTP \
                 and self.auth_type != HTTP_TYPE:
             log.warning("userobj:%s tried scope type %s and scope restriction is set to %s",
                         userobj, self.auth_type, scope_restriction)
             return None
 
         if scope_restriction == self.AUTH_RESTRICTION_SCOPE_VCS \
                 and self.auth_type != VCS_TYPE:
             log.warning("userobj:%s tried scope type %s and scope restriction is set to %s",
                         userobj, self.auth_type, scope_restriction)
             return None
 
         # check super-admin restriction
         auth_restriction = settings.get('auth_restriction', '')
 
         if auth_restriction == self.AUTH_RESTRICTION_SUPER_ADMIN \
                 and userobj.admin is False:
             log.warning("userobj:%s is not super-admin and auth restriction is set to %s",
                         userobj, auth_restriction)
             return None
 
         user_attrs = {
             "username": userobj.username,
             "firstname": userobj.firstname,
             "lastname": userobj.lastname,
             "groups": [],
             'user_group_sync': False,
             "email": userobj.email,
             "admin": userobj.admin,
             "active": userobj.active,
             "active_from_extern": userobj.active,
             "extern_name": userobj.user_id,
             "extern_type": userobj.extern_type,
         }
 
         log.debug("User attributes:%s", user_attrs)
         if userobj.active:
             from rhodecode.lib import auth
             crypto_backend = auth.crypto_backend()
             password_encoded = safe_str(password)
             password_match, new_hash = crypto_backend.hash_check_with_upgrade(
                 password_encoded, userobj.password or '')
 
             if password_match and new_hash:
                 log.debug('user %s properly authenticated, but '
                           'requires hash change to bcrypt', userobj)
                 # if password match, and we use OLD deprecated hash,
                 # we should migrate this user hash password to the new hash
                 # we store the new returned by hash_check_with_upgrade function
                 user_attrs['_hash_migrate'] = new_hash
 
             if userobj.username == User.DEFAULT_USER and userobj.active:
                 log.info('user `%s` authenticated correctly as anonymous user',
-                         userobj.username)
+                         userobj.username,
+                         extra={"action": "user_auth_ok", "module": "auth_rhodecode_anon", "username": userobj.username})
                 return user_attrs
 
             elif userobj.username == username and password_match:
-                log.info('user `%s` authenticated correctly', userobj.username)
+                log.info('user `%s` authenticated correctly', userobj.username,
+                         extra={"action": "user_auth_ok", "module": "auth_rhodecode", "username": userobj.username})
                 return user_attrs
             log.warning("user `%s` used a wrong password when "
                         "authenticating on this plugin", userobj.username)
             return None
         else:
             log.warning('user `%s` failed to authenticate via %s, reason: account not '
                         'active.', username, self.name)
             return None
 
 
 class RhodeCodeSettingsSchema(AuthnPluginSettingsSchemaBase):
 
     auth_restriction_choices = [
         (RhodeCodeAuthPlugin.AUTH_RESTRICTION_NONE, 'All users'),
         (RhodeCodeAuthPlugin.AUTH_RESTRICTION_SUPER_ADMIN, 'Super admins only'),
     ]
 
     auth_scope_choices = [
         (RhodeCodeAuthPlugin.AUTH_RESTRICTION_SCOPE_ALL, 'HTTP and VCS'),
         (RhodeCodeAuthPlugin.AUTH_RESTRICTION_SCOPE_HTTP, 'HTTP only'),
     ]
 
     auth_restriction = colander.SchemaNode(
         colander.String(),
         default=auth_restriction_choices[0],
         description=_('Allowed user types for authentication using this plugin.'),
         title=_('User restriction'),
         validator=colander.OneOf([x[0] for x in auth_restriction_choices]),
         widget='select_with_labels',
         choices=auth_restriction_choices
     )
     scope_restriction = colander.SchemaNode(
         colander.String(),
         default=auth_scope_choices[0],
         description=_('Allowed protocols for authentication using this plugin. '
                       'VCS means GIT/HG/SVN. HTTP is web based login.'),
         title=_('Scope restriction'),
         validator=colander.OneOf([x[0] for x in auth_scope_choices]),
         widget='select_with_labels',
         choices=auth_scope_choices
     )
 
 
 def includeme(config):
     plugin_id = 'egg:rhodecode-enterprise-ce#{}'.format(RhodeCodeAuthPlugin.uid)
     plugin_factory(plugin_id).includeme(config)

rhodecode/lib/_vendor/redis_lock/__init__.py

@@ -1,390 +1,390 b''
 import sys
 import threading
 import weakref
 from base64 import b64encode
 from logging import getLogger
 from os import urandom
 
 from redis import StrictRedis
 
 __version__ = '3.7.0'
 
 loggers = {
     k: getLogger("rhodecode." + ".".join((__name__, k)))
     for k in [
         "acquire",
         "refresh.thread.start",
         "refresh.thread.stop",
         "refresh.thread.exit",
         "refresh.start",
         "refresh.shutdown",
         "refresh.exit",
         "release",
     ]
 }
 
 PY3 = sys.version_info[0] == 3
 
 if PY3:
     text_type = str
     binary_type = bytes
 else:
     text_type = unicode  # noqa
     binary_type = str
 
 
 # Check if the id match. If not, return an error code.
 UNLOCK_SCRIPT = b"""
     if redis.call("get", KEYS[1]) ~= ARGV[1] then
         return 1
     else
         redis.call("del", KEYS[2])
         redis.call("lpush", KEYS[2], 1)
         redis.call("pexpire", KEYS[2], ARGV[2])
         redis.call("del", KEYS[1])
         return 0
     end
 """
 
 # Covers both cases when key doesn't exist and doesn't equal to lock's id
 EXTEND_SCRIPT = b"""
     if redis.call("get", KEYS[1]) ~= ARGV[1] then
         return 1
     elseif redis.call("ttl", KEYS[1]) < 0 then
         return 2
     else
         redis.call("expire", KEYS[1], ARGV[2])
         return 0
     end
 """
 
 RESET_SCRIPT = b"""
     redis.call('del', KEYS[2])
     redis.call('lpush', KEYS[2], 1)
     redis.call('pexpire', KEYS[2], ARGV[2])
     return redis.call('del', KEYS[1])
 """
 
 RESET_ALL_SCRIPT = b"""
     local locks = redis.call('keys', 'lock:*')
     local signal
     for _, lock in pairs(locks) do
         signal = 'lock-signal:' .. string.sub(lock, 6)
         redis.call('del', signal)
         redis.call('lpush', signal, 1)
         redis.call('expire', signal, 1)
         redis.call('del', lock)
     end
     return #locks
 """
 
 
 class AlreadyAcquired(RuntimeError):
     pass
 
 
 class NotAcquired(RuntimeError):
     pass
 
 
 class AlreadyStarted(RuntimeError):
     pass
 
 
 class TimeoutNotUsable(RuntimeError):
     pass
 
 
 class InvalidTimeout(RuntimeError):
     pass
 
 
 class TimeoutTooLarge(RuntimeError):
     pass
 
 
 class NotExpirable(RuntimeError):
     pass
 
 
 class Lock(object):
     """
     A Lock context manager implemented via redis SETNX/BLPOP.
     """
     unlock_script = None
     extend_script = None
     reset_script = None
     reset_all_script = None
 
     def __init__(self, redis_client, name, expire=None, id=None, auto_renewal=False, strict=True, signal_expire=1000):
         """
         :param redis_client:
             An instance of :class:`~StrictRedis`.
         :param name:
             The name (redis key) the lock should have.
         :param expire:
             The lock expiry time in seconds. If left at the default (None)
             the lock will not expire.
         :param id:
             The ID (redis value) the lock should have. A random value is
             generated when left at the default.
 
             Note that if you specify this then the lock is marked as "held". Acquires
             won't be possible.
         :param auto_renewal:
             If set to ``True``, Lock will automatically renew the lock so that it
             doesn't expire for as long as the lock is held (acquire() called
             or running in a context manager).
 
             Implementation note: Renewal will happen using a daemon thread with
             an interval of ``expire*2/3``. If wishing to use a different renewal
             time, subclass Lock, call ``super().__init__()`` then set
             ``self._lock_renewal_interval`` to your desired interval.
         :param strict:
             If set ``True`` then the ``redis_client`` needs to be an instance of ``redis.StrictRedis``.
         :param signal_expire:
             Advanced option to override signal list expiration in milliseconds. Increase it for very slow clients. Default: ``1000``.
         """
         if strict and not isinstance(redis_client, StrictRedis):
             raise ValueError("redis_client must be instance of StrictRedis. "
                              "Use strict=False if you know what you're doing.")
         if auto_renewal and expire is None:
             raise ValueError("Expire may not be None when auto_renewal is set")
 
         self._client = redis_client
 
         if expire:
             expire = int(expire)
             if expire < 0:
                 raise ValueError("A negative expire is not acceptable.")
         else:
             expire = None
         self._expire = expire
 
         self._signal_expire = signal_expire
         if id is None:
             self._id = b64encode(urandom(18)).decode('ascii')
         elif isinstance(id, binary_type):
             try:
                 self._id = id.decode('ascii')
             except UnicodeDecodeError:
                 self._id = b64encode(id).decode('ascii')
         elif isinstance(id, text_type):
             self._id = id
         else:
             raise TypeError("Incorrect type for `id`. Must be bytes/str not %s." % type(id))
         self._name = 'lock:' + name
         self._signal = 'lock-signal:' + name
         self._lock_renewal_interval = (float(expire) * 2 / 3
                                        if auto_renewal
                                        else None)
         self._lock_renewal_thread = None
 
         self.register_scripts(redis_client)
 
     @classmethod
     def register_scripts(cls, redis_client):
         global reset_all_script
         if reset_all_script is None:
             reset_all_script = redis_client.register_script(RESET_ALL_SCRIPT)
             cls.unlock_script = redis_client.register_script(UNLOCK_SCRIPT)
             cls.extend_script = redis_client.register_script(EXTEND_SCRIPT)
             cls.reset_script = redis_client.register_script(RESET_SCRIPT)
             cls.reset_all_script = redis_client.register_script(RESET_ALL_SCRIPT)
 
     @property
     def _held(self):
         return self.id == self.get_owner_id()
 
     def reset(self):
         """
         Forcibly deletes the lock. Use this with care.
         """
         self.reset_script(client=self._client, keys=(self._name, self._signal), args=(self.id, self._signal_expire))
 
     @property
     def id(self):
         return self._id
 
     def get_owner_id(self):
         owner_id = self._client.get(self._name)
         if isinstance(owner_id, binary_type):
             owner_id = owner_id.decode('ascii', 'replace')
         return owner_id
 
     def acquire(self, blocking=True, timeout=None):
         """
         :param blocking:
             Boolean value specifying whether lock should be blocking or not.
         :param timeout:
             An integer value specifying the maximum number of seconds to block.
         """
         logger = loggers["acquire"]
 
         logger.debug("Getting blocking: %s acquire on %r ...", blocking, self._name)
 
         if self._held:
             owner_id = self.get_owner_id()
             raise AlreadyAcquired("Already acquired from this Lock instance. Lock id: {}".format(owner_id))
 
         if not blocking and timeout is not None:
             raise TimeoutNotUsable("Timeout cannot be used if blocking=False")
 
         if timeout:
             timeout = int(timeout)
             if timeout < 0:
                 raise InvalidTimeout("Timeout (%d) cannot be less than or equal to 0" % timeout)
 
             if self._expire and not self._lock_renewal_interval and timeout > self._expire:
                 raise TimeoutTooLarge("Timeout (%d) cannot be greater than expire (%d)" % (timeout, self._expire))
 
         busy = True
         blpop_timeout = timeout or self._expire or 0
         timed_out = False
         while busy:
             busy = not self._client.set(self._name, self._id, nx=True, ex=self._expire)
             if busy:
                 if timed_out:
                     return False
                 elif blocking:
                     timed_out = not self._client.blpop(self._signal, blpop_timeout) and timeout
                 else:
                     logger.warning("Failed to get %r.", self._name)
                     return False
 
-        logger.info("Got lock for %r.", self._name)
+        logger.debug("Got lock for %r.", self._name)
         if self._lock_renewal_interval is not None:
             self._start_lock_renewer()
         return True
 
     def extend(self, expire=None):
         """Extends expiration time of the lock.
 
         :param expire:
             New expiration time. If ``None`` - `expire` provided during
             lock initialization will be taken.
         """
         if expire:
             expire = int(expire)
             if expire < 0:
                 raise ValueError("A negative expire is not acceptable.")
         elif self._expire is not None:
             expire = self._expire
         else:
             raise TypeError(
                 "To extend a lock 'expire' must be provided as an "
                 "argument to extend() method or at initialization time."
             )
 
         error = self.extend_script(client=self._client, keys=(self._name, self._signal), args=(self._id, expire))
         if error == 1:
             raise NotAcquired("Lock %s is not acquired or it already expired." % self._name)
         elif error == 2:
             raise NotExpirable("Lock %s has no assigned expiration time" % self._name)
         elif error:
             raise RuntimeError("Unsupported error code %s from EXTEND script" % error)
 
     @staticmethod
     def _lock_renewer(lockref, interval, stop):
         """
         Renew the lock key in redis every `interval` seconds for as long
         as `self._lock_renewal_thread.should_exit` is False.
         """
         while not stop.wait(timeout=interval):
             loggers["refresh.thread.start"].debug("Refreshing lock")
             lock = lockref()
             if lock is None:
                 loggers["refresh.thread.stop"].debug(
                     "The lock no longer exists, stopping lock refreshing"
                 )
                 break
             lock.extend(expire=lock._expire)
             del lock
         loggers["refresh.thread.exit"].debug("Exit requested, stopping lock refreshing")
 
     def _start_lock_renewer(self):
         """
         Starts the lock refresher thread.
         """
         if self._lock_renewal_thread is not None:
             raise AlreadyStarted("Lock refresh thread already started")
 
         loggers["refresh.start"].debug(
             "Starting thread to refresh lock every %s seconds",
             self._lock_renewal_interval
         )
         self._lock_renewal_stop = threading.Event()
         self._lock_renewal_thread = threading.Thread(
             group=None,
             target=self._lock_renewer,
             kwargs={'lockref': weakref.ref(self),
                     'interval': self._lock_renewal_interval,
                     'stop': self._lock_renewal_stop}
         )
         self._lock_renewal_thread.setDaemon(True)
         self._lock_renewal_thread.start()
 
     def _stop_lock_renewer(self):
         """
         Stop the lock renewer.
 
         This signals the renewal thread and waits for its exit.
         """
         if self._lock_renewal_thread is None or not self._lock_renewal_thread.is_alive():
             return
         loggers["refresh.shutdown"].debug("Signalling the lock refresher to stop")
         self._lock_renewal_stop.set()
         self._lock_renewal_thread.join()
         self._lock_renewal_thread = None
         loggers["refresh.exit"].debug("Lock refresher has stopped")
 
     def __enter__(self):
         acquired = self.acquire(blocking=True)
         assert acquired, "Lock wasn't acquired, but blocking=True"
         return self
 
     def __exit__(self, exc_type=None, exc_value=None, traceback=None):
         self.release()
 
     def release(self):
         """Releases the lock, that was acquired with the same object.
 
         .. note::
 
             If you want to release a lock that you acquired in a different place you have two choices:
 
             * Use ``Lock("name", id=id_from_other_place).release()``
             * Use ``Lock("name").reset()``
         """
         if self._lock_renewal_thread is not None:
             self._stop_lock_renewer()
         loggers["release"].debug("Releasing %r.", self._name)
         error = self.unlock_script(client=self._client, keys=(self._name, self._signal), args=(self._id, self._signal_expire))
         if error == 1:
             raise NotAcquired("Lock %s is not acquired or it already expired." % self._name)
         elif error:
             raise RuntimeError("Unsupported error code %s from EXTEND script." % error)
 
     def locked(self):
         """
         Return true if the lock is acquired.
 
         Checks that lock with same name already exists. This method returns true, even if
         lock have another id.
         """
         return self._client.exists(self._name) == 1
 
 
 reset_all_script = None
 
 
 def reset_all(redis_client):
     """
     Forcibly deletes all locks if its remains (like a crash reason). Use this with care.
 
     :param redis_client:
         An instance of :class:`~StrictRedis`.
     """
     Lock.register_scripts(redis_client)
 
     reset_all_script(client=redis_client)  # noqa

rhodecode/lib/audit_logger.py

@@ -1,303 +1,305 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2017-2020 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 logging
 import datetime
 
 from rhodecode.lib.jsonalchemy import JsonRaw
 from rhodecode.model import meta
 from rhodecode.model.db import User, UserLog, Repository
 
 
 log = logging.getLogger(__name__)
 
 # action as key, and expected action_data as value
 ACTIONS_V1 = {
     'user.login.success': {'user_agent': ''},
     'user.login.failure': {'user_agent': ''},
     'user.logout': {'user_agent': ''},
     'user.register': {},
     'user.password.reset_request': {},
     'user.push': {'user_agent': '', 'commit_ids': []},
     'user.pull': {'user_agent': ''},
 
     'user.create': {'data': {}},
     'user.delete': {'old_data': {}},
     'user.edit': {'old_data': {}},
     'user.edit.permissions': {},
     'user.edit.ip.add': {'ip': {}, 'user': {}},
     'user.edit.ip.delete': {'ip': {}, 'user': {}},
     'user.edit.token.add': {'token': {}, 'user': {}},
     'user.edit.token.delete': {'token': {}, 'user': {}},
     'user.edit.email.add': {'email': ''},
     'user.edit.email.delete': {'email': ''},
     'user.edit.ssh_key.add': {'token': {}, 'user': {}},
     'user.edit.ssh_key.delete': {'token': {}, 'user': {}},
     'user.edit.password_reset.enabled': {},
     'user.edit.password_reset.disabled': {},
 
     'user_group.create': {'data': {}},
     'user_group.delete': {'old_data': {}},
     'user_group.edit': {'old_data': {}},
     'user_group.edit.permissions': {},
     'user_group.edit.member.add': {'user': {}},
     'user_group.edit.member.delete': {'user': {}},
 
     'repo.create': {'data': {}},
     'repo.fork': {'data': {}},
     'repo.edit': {'old_data': {}},
     'repo.edit.permissions': {},
     'repo.edit.permissions.branch': {},
     'repo.archive': {'old_data': {}},
     'repo.delete': {'old_data': {}},
 
     'repo.archive.download': {'user_agent': '', 'archive_name': '',
                               'archive_spec': '', 'archive_cached': ''},
 
     'repo.permissions.branch_rule.create': {},
     'repo.permissions.branch_rule.edit': {},
     'repo.permissions.branch_rule.delete': {},
 
     'repo.pull_request.create': '',
     'repo.pull_request.edit': '',
     'repo.pull_request.delete': '',
     'repo.pull_request.close': '',
     'repo.pull_request.merge': '',
     'repo.pull_request.vote': '',
     'repo.pull_request.comment.create': '',
     'repo.pull_request.comment.edit': '',
     'repo.pull_request.comment.delete': '',
 
     'repo.pull_request.reviewer.add': '',
     'repo.pull_request.reviewer.delete': '',
 
     'repo.pull_request.observer.add': '',
     'repo.pull_request.observer.delete': '',
 
     'repo.commit.strip': {'commit_id': ''},
     'repo.commit.comment.create': {'data': {}},
     'repo.commit.comment.delete': {'data': {}},
     'repo.commit.comment.edit': {'data': {}},
     'repo.commit.vote': '',
 
     'repo.artifact.add': '',
     'repo.artifact.delete': '',
 
     'repo_group.create': {'data': {}},
     'repo_group.edit': {'old_data': {}},
     'repo_group.edit.permissions': {},
     'repo_group.delete': {'old_data': {}},
 }
 
 ACTIONS = ACTIONS_V1
 
 SOURCE_WEB = 'source_web'
 SOURCE_API = 'source_api'
 
 
 class UserWrap(object):
     """
     Fake object used to imitate AuthUser
     """
 
     def __init__(self, user_id=None, username=None, ip_addr=None):
         self.user_id = user_id
         self.username = username
         self.ip_addr = ip_addr
 
 
 class RepoWrap(object):
     """
     Fake object used to imitate RepoObject that audit logger requires
     """
 
     def __init__(self, repo_id=None, repo_name=None):
         self.repo_id = repo_id
         self.repo_name = repo_name
 
 
 def _store_log(action_name, action_data, user_id, username, user_data,
                ip_address, repository_id, repository_name):
     user_log = UserLog()
     user_log.version = UserLog.VERSION_2
 
     user_log.action = action_name
     user_log.action_data = action_data or JsonRaw(u'{}')
 
     user_log.user_ip = ip_address
 
     user_log.user_id = user_id
     user_log.username = username
     user_log.user_data = user_data or JsonRaw(u'{}')
 
     user_log.repository_id = repository_id
     user_log.repository_name = repository_name
 
     user_log.action_date = datetime.datetime.now()
 
     return user_log
 
 
 def store_web(*args, **kwargs):
     action_data = {}
     org_action_data = kwargs.pop('action_data', {})
     action_data.update(org_action_data)
     action_data['source'] = SOURCE_WEB
     kwargs['action_data'] = action_data
 
     return store(*args, **kwargs)
 
 
 def store_api(*args, **kwargs):
     action_data = {}
     org_action_data = kwargs.pop('action_data', {})
     action_data.update(org_action_data)
     action_data['source'] = SOURCE_API
     kwargs['action_data'] = action_data
 
     return store(*args, **kwargs)
 
 
 def store(action, user, action_data=None, user_data=None, ip_addr=None,
           repo=None, sa_session=None, commit=False):
     """
     Audit logger for various actions made by users, typically this
     results in a call such::
 
         from rhodecode.lib import audit_logger
 
         audit_logger.store(
             'repo.edit', user=self._rhodecode_user)
         audit_logger.store(
             'repo.delete', action_data={'data': repo_data},
             user=audit_logger.UserWrap(username='itried-login', ip_addr='8.8.8.8'))
 
         # repo action
         audit_logger.store(
             'repo.delete',
             user=audit_logger.UserWrap(username='itried-login', ip_addr='8.8.8.8'),
             repo=audit_logger.RepoWrap(repo_name='some-repo'))
 
         # repo action, when we know and have the repository object already
         audit_logger.store(
             'repo.delete', action_data={'source': audit_logger.SOURCE_WEB, },
             user=self._rhodecode_user,
             repo=repo_object)
 
         # alternative wrapper to the above
         audit_logger.store_web(
             'repo.delete', action_data={},
             user=self._rhodecode_user,
             repo=repo_object)
 
         # without an user ?
         audit_logger.store(
             'user.login.failure',
             user=audit_logger.UserWrap(
                     username=self.request.params.get('username'),
                     ip_addr=self.request.remote_addr))
 
     """
     from rhodecode.lib.utils2 import safe_unicode
     from rhodecode.lib.auth import AuthUser
 
     action_spec = ACTIONS.get(action, None)
     if action_spec is None:
         raise ValueError('Action `{}` is not supported'.format(action))
 
     if not sa_session:
         sa_session = meta.Session()
 
     try:
         username = getattr(user, 'username', None)
         if not username:
             pass
 
         user_id = getattr(user, 'user_id', None)
         if not user_id:
             # maybe we have username ? Try to figure user_id from username
             if username:
                 user_id = getattr(
                     User.get_by_username(username), 'user_id', None)
 
         ip_addr = ip_addr or getattr(user, 'ip_addr', None)
         if not ip_addr:
             pass
 
         if not user_data:
             # try to get this from the auth user
             if isinstance(user, AuthUser):
                 user_data = {
                     'username': user.username,
                     'email': user.email,
                 }
 
         repository_name = getattr(repo, 'repo_name', None)
         repository_id = getattr(repo, 'repo_id', None)
         if not repository_id:
             # maybe we have repo_name ? Try to figure repo_id from repo_name
             if repository_name:
                 repository_id = getattr(
                     Repository.get_by_repo_name(repository_name), 'repo_id', None)
 
         action_name = safe_unicode(action)
         ip_address = safe_unicode(ip_addr)
 
         with sa_session.no_autoflush:
 
             user_log = _store_log(
                 action_name=action_name,
                 action_data=action_data or {},
                 user_id=user_id,
                 username=username,
                 user_data=user_data or {},
                 ip_address=ip_address,
                 repository_id=repository_id,
                 repository_name=repository_name
             )
 
             sa_session.add(user_log)
             if commit:
                 sa_session.commit()
             entry_id = user_log.entry_id or ''
 
             update_user_last_activity(sa_session, user_id)
 
             if commit:
                 sa_session.commit()
 
         log.info('AUDIT[%s]: Logging action: `%s` by user:id:%s[%s] ip:%s',
-                 entry_id, action_name, user_id, username, ip_address)
+                 entry_id, action_name, user_id, username, ip_address,
+                 extra={"entry_id": entry_id, "action": action_name,
+                        "user_id": user_id, "ip": ip_address})
 
     except Exception:
         log.exception('AUDIT: failed to store audit log')
 
 
 def update_user_last_activity(sa_session, user_id):
     _last_activity = datetime.datetime.now()
     try:
         sa_session.query(User).filter(User.user_id == user_id).update(
             {"last_activity": _last_activity})
         log.debug(
             'updated user `%s` last activity to:%s', user_id, _last_activity)
     except Exception:
         log.exception("Failed last activity update for user_id: %s", user_id)
         sa_session.rollback()
 

rhodecode/lib/auth.py

@@ -1,2515 +1,2516 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2010-2020 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/
 
 """
 authentication and permission libraries
 """
 
 import os
 
 import colander
 import time
 import collections
 import fnmatch
 import hashlib
 import itertools
 import logging
 import random
 import traceback
 from functools import wraps
 
 import ipaddress
 
 from pyramid.httpexceptions import HTTPForbidden, HTTPFound, HTTPNotFound
 from sqlalchemy.orm.exc import ObjectDeletedError
 from sqlalchemy.orm import joinedload
 from zope.cachedescriptors.property import Lazy as LazyProperty
 
 import rhodecode
 from rhodecode.model import meta
 from rhodecode.model.meta import Session
 from rhodecode.model.user import UserModel
 from rhodecode.model.db import (
     false, User, Repository, Permission, UserToPerm, UserGroupToPerm, UserGroupMember,
     UserIpMap, UserApiKeys, RepoGroup, UserGroup, UserNotice)
 from rhodecode.lib import rc_cache
 from rhodecode.lib.utils2 import safe_unicode, aslist, safe_str, md5, safe_int, sha1
 from rhodecode.lib.utils import (
     get_repo_slug, get_repo_group_slug, get_user_group_slug)
 from rhodecode.lib.caching_query import FromCache
 
 if rhodecode.is_unix:
     import bcrypt
 
 log = logging.getLogger(__name__)
 
 csrf_token_key = "csrf_token"
 
 
 class PasswordGenerator(object):
     """
     This is a simple class for generating password from different sets of
     characters
     usage::
         passwd_gen = PasswordGenerator()
         #print 8-letter password containing only big and small letters
             of alphabet
         passwd_gen.gen_password(8, passwd_gen.ALPHABETS_BIG_SMALL)
     """
     ALPHABETS_NUM = r'''1234567890'''
     ALPHABETS_SMALL = r'''qwertyuiopasdfghjklzxcvbnm'''
     ALPHABETS_BIG = r'''QWERTYUIOPASDFGHJKLZXCVBNM'''
     ALPHABETS_SPECIAL = r'''`-=[]\;',./~!@#$%^&*()_+{}|:"<>?'''
     ALPHABETS_FULL = ALPHABETS_BIG + ALPHABETS_SMALL \
         + ALPHABETS_NUM + ALPHABETS_SPECIAL
     ALPHABETS_ALPHANUM = ALPHABETS_BIG + ALPHABETS_SMALL + ALPHABETS_NUM
     ALPHABETS_BIG_SMALL = ALPHABETS_BIG + ALPHABETS_SMALL
     ALPHABETS_ALPHANUM_BIG = ALPHABETS_BIG + ALPHABETS_NUM
     ALPHABETS_ALPHANUM_SMALL = ALPHABETS_SMALL + ALPHABETS_NUM
 
     def __init__(self, passwd=''):
         self.passwd = passwd
 
     def gen_password(self, length, type_=None):
         if type_ is None:
             type_ = self.ALPHABETS_FULL
         self.passwd = ''.join([random.choice(type_) for _ in range(length)])
         return self.passwd
 
 
 class _RhodeCodeCryptoBase(object):
     ENC_PREF = None
 
     def hash_create(self, str_):
         """
         hash the string using
 
         :param str_: password to hash
         """
         raise NotImplementedError
 
     def hash_check_with_upgrade(self, password, hashed):
         """
         Returns tuple in which first element is boolean that states that
         given password matches it's hashed version, and the second is new hash
         of the password, in case this password should be migrated to new
         cipher.
         """
         checked_hash = self.hash_check(password, hashed)
         return checked_hash, None
 
     def hash_check(self, password, hashed):
         """
         Checks matching password with it's hashed value.
 
         :param password: password
         :param hashed: password in hashed form
         """
         raise NotImplementedError
 
     def _assert_bytes(self, value):
         """
         Passing in an `unicode` object can lead to hard to detect issues
         if passwords contain non-ascii characters.  Doing a type check
         during runtime, so that such mistakes are detected early on.
         """
         if not isinstance(value, str):
             raise TypeError(
                 "Bytestring required as input, got %r." % (value, ))
 
 
 class _RhodeCodeCryptoBCrypt(_RhodeCodeCryptoBase):
     ENC_PREF = ('$2a$10', '$2b$10')
 
     def hash_create(self, str_):
         self._assert_bytes(str_)
         return bcrypt.hashpw(str_, bcrypt.gensalt(10))
 
     def hash_check_with_upgrade(self, password, hashed):
         """
         Returns tuple in which first element is boolean that states that
         given password matches it's hashed version, and the second is new hash
         of the password, in case this password should be migrated to new
         cipher.
 
         This implements special upgrade logic which works like that:
          - check if the given password == bcrypted hash, if yes then we
            properly used password and it was already in bcrypt. Proceed
            without any changes
          - if bcrypt hash check is not working try with sha256. If hash compare
            is ok, it means we using correct but old hashed password. indicate
            hash change and proceed
         """
 
         new_hash = None
 
         # regular pw check
         password_match_bcrypt = self.hash_check(password, hashed)
 
         # now we want to know if the password was maybe from sha256
         # basically calling _RhodeCodeCryptoSha256().hash_check()
         if not password_match_bcrypt:
             if _RhodeCodeCryptoSha256().hash_check(password, hashed):
                 new_hash = self.hash_create(password)  # make new bcrypt hash
                 password_match_bcrypt = True
 
         return password_match_bcrypt, new_hash
 
     def hash_check(self, password, hashed):
         """
         Checks matching password with it's hashed value.
 
         :param password: password
         :param hashed: password in hashed form
         """
         self._assert_bytes(password)
         try:
             return bcrypt.hashpw(password, hashed) == hashed
         except ValueError as e:
             # we're having a invalid salt here probably, we should not crash
             # just return with False as it would be a wrong password.
             log.debug('Failed to check password hash using bcrypt %s',
                       safe_str(e))
 
         return False
 
 
 class _RhodeCodeCryptoSha256(_RhodeCodeCryptoBase):
     ENC_PREF = '_'
 
     def hash_create(self, str_):
         self._assert_bytes(str_)
         return hashlib.sha256(str_).hexdigest()
 
     def hash_check(self, password, hashed):
         """
         Checks matching password with it's hashed value.
 
         :param password: password
         :param hashed: password in hashed form
         """
         self._assert_bytes(password)
         return hashlib.sha256(password).hexdigest() == hashed
 
 
 class _RhodeCodeCryptoTest(_RhodeCodeCryptoBase):
     ENC_PREF = '_'
 
     def hash_create(self, str_):
         self._assert_bytes(str_)
         return sha1(str_)
 
     def hash_check(self, password, hashed):
         """
         Checks matching password with it's hashed value.
 
         :param password: password
         :param hashed: password in hashed form
         """
         self._assert_bytes(password)
         return sha1(password) == hashed
 
 
 def crypto_backend():
     """
     Return the matching crypto backend.
 
     Selection is based on if we run tests or not, we pick sha1-test backend to run
     tests faster since BCRYPT is expensive to calculate
     """
     if rhodecode.is_test:
         RhodeCodeCrypto = _RhodeCodeCryptoTest()
     else:
         RhodeCodeCrypto = _RhodeCodeCryptoBCrypt()
 
     return RhodeCodeCrypto
 
 
 def get_crypt_password(password):
     """
     Create the hash of `password` with the active crypto backend.
 
     :param password: The cleartext password.
     :type password: unicode
     """
     password = safe_str(password)
     return crypto_backend().hash_create(password)
 
 
 def check_password(password, hashed):
     """
     Check if the value in `password` matches the hash in `hashed`.
 
     :param password: The cleartext password.
     :type password: unicode
 
     :param hashed: The expected hashed version of the password.
     :type hashed: The hash has to be passed in in text representation.
     """
     password = safe_str(password)
     return crypto_backend().hash_check(password, hashed)
 
 
 def generate_auth_token(data, salt=None):
     """
     Generates API KEY from given string
     """
 
     if salt is None:
         salt = os.urandom(16)
     return hashlib.sha1(safe_str(data) + salt).hexdigest()
 
 
 def get_came_from(request):
     """
     get query_string+path from request sanitized after removing auth_token
     """
     _req = request
 
     path = _req.path
     if 'auth_token' in _req.GET:
         # sanitize the request and remove auth_token for redirection
         _req.GET.pop('auth_token')
     qs = _req.query_string
     if qs:
         path += '?' + qs
 
     return path
 
 
 class CookieStoreWrapper(object):
 
     def __init__(self, cookie_store):
         self.cookie_store = cookie_store
 
     def __repr__(self):
         return 'CookieStore<%s>' % (self.cookie_store)
 
     def get(self, key, other=None):
         if isinstance(self.cookie_store, dict):
             return self.cookie_store.get(key, other)
         elif isinstance(self.cookie_store, AuthUser):
             return self.cookie_store.__dict__.get(key, other)
 
 
 def _cached_perms_data(user_id, scope, user_is_admin,
                        user_inherit_default_permissions, explicit, algo,
                        calculate_super_admin):
 
     permissions = PermissionCalculator(
         user_id, scope, user_is_admin, user_inherit_default_permissions,
         explicit, algo, calculate_super_admin)
     return permissions.calculate()
 
 
 class PermOrigin(object):
     SUPER_ADMIN = 'superadmin'
     ARCHIVED = 'archived'
 
     REPO_USER = 'user:%s'
     REPO_USERGROUP = 'usergroup:%s'
     REPO_OWNER = 'repo.owner'
     REPO_DEFAULT = 'repo.default'
     REPO_DEFAULT_NO_INHERIT = 'repo.default.no.inherit'
     REPO_PRIVATE = 'repo.private'
 
     REPOGROUP_USER = 'user:%s'
     REPOGROUP_USERGROUP = 'usergroup:%s'
     REPOGROUP_OWNER = 'group.owner'
     REPOGROUP_DEFAULT = 'group.default'
     REPOGROUP_DEFAULT_NO_INHERIT = 'group.default.no.inherit'
 
     USERGROUP_USER = 'user:%s'
     USERGROUP_USERGROUP = 'usergroup:%s'
     USERGROUP_OWNER = 'usergroup.owner'
     USERGROUP_DEFAULT = 'usergroup.default'
     USERGROUP_DEFAULT_NO_INHERIT = 'usergroup.default.no.inherit'
 
 
 class PermOriginDict(dict):
     """
     A special dict used for tracking permissions along with their origins.
 
     `__setitem__` has been overridden to expect a tuple(perm, origin)
     `__getitem__` will return only the perm
     `.perm_origin_stack` will return the stack of (perm, origin) set per key
 
     >>> perms = PermOriginDict()
     >>> perms['resource'] = 'read', 'default', 1
     >>> perms['resource']
     'read'
     >>> perms['resource'] = 'write', 'admin', 2
     >>> perms['resource']
     'write'
     >>> perms.perm_origin_stack
     {'resource': [('read', 'default', 1), ('write', 'admin', 2)]}
     """
 
     def __init__(self, *args, **kw):
         dict.__init__(self, *args, **kw)
         self.perm_origin_stack = collections.OrderedDict()
 
     def __setitem__(self, key, perm_origin_obj_id):
         (perm, origin, obj_id) = perm_origin_obj_id
         self.perm_origin_stack.setdefault(key, []).append((perm, origin, obj_id))
         dict.__setitem__(self, key, perm)
 
 
 class BranchPermOriginDict(PermOriginDict):
     """
     Dedicated branch permissions dict, with tracking of patterns and origins.
 
     >>> perms = BranchPermOriginDict()
     >>> perms['resource'] = '*pattern', 'read', 'default'
     >>> perms['resource']
     {'*pattern': 'read'}
     >>> perms['resource'] = '*pattern', 'write', 'admin'
     >>> perms['resource']
     {'*pattern': 'write'}
     >>> perms.perm_origin_stack
     {'resource': {'*pattern': [('read', 'default'), ('write', 'admin')]}}
     """
     def __setitem__(self, key, pattern_perm_origin):
         (pattern, perm, origin) = pattern_perm_origin
 
         self.perm_origin_stack.setdefault(key, {}) \
             .setdefault(pattern, []).append((perm, origin))
 
         if key in self:
             self[key].__setitem__(pattern, perm)
         else:
             patterns = collections.OrderedDict()
             patterns[pattern] = perm
             dict.__setitem__(self, key, patterns)
 
 
 class PermissionCalculator(object):
 
     def __init__(
             self, user_id, scope, user_is_admin,
             user_inherit_default_permissions, explicit, algo,
             calculate_super_admin_as_user=False):
 
         self.user_id = user_id
         self.user_is_admin = user_is_admin
         self.inherit_default_permissions = user_inherit_default_permissions
         self.explicit = explicit
         self.algo = algo
         self.calculate_super_admin_as_user = calculate_super_admin_as_user
 
         scope = scope or {}
         self.scope_repo_id = scope.get('repo_id')
         self.scope_repo_group_id = scope.get('repo_group_id')
         self.scope_user_group_id = scope.get('user_group_id')
 
         self.default_user_id = User.get_default_user(cache=True).user_id
 
         self.permissions_repositories = PermOriginDict()
         self.permissions_repository_groups = PermOriginDict()
         self.permissions_user_groups = PermOriginDict()
         self.permissions_repository_branches = BranchPermOriginDict()
         self.permissions_global = set()
 
         self.default_repo_perms = Permission.get_default_repo_perms(
             self.default_user_id, self.scope_repo_id)
         self.default_repo_groups_perms = Permission.get_default_group_perms(
             self.default_user_id, self.scope_repo_group_id)
         self.default_user_group_perms = \
             Permission.get_default_user_group_perms(
                 self.default_user_id, self.scope_user_group_id)
 
         # default branch perms
         self.default_branch_repo_perms = \
             Permission.get_default_repo_branch_perms(
                 self.default_user_id, self.scope_repo_id)
 
     def calculate(self):
         if self.user_is_admin and not self.calculate_super_admin_as_user:
             return self._calculate_super_admin_permissions()
 
         self._calculate_global_default_permissions()
         self._calculate_global_permissions()
         self._calculate_default_permissions()
         self._calculate_repository_permissions()
         self._calculate_repository_branch_permissions()
         self._calculate_repository_group_permissions()
         self._calculate_user_group_permissions()
         return self._permission_structure()
 
     def _calculate_super_admin_permissions(self):
         """
         super-admin user have all default rights for repositories
         and groups set to admin
         """
         self.permissions_global.add('hg.admin')
         self.permissions_global.add('hg.create.write_on_repogroup.true')
 
         # repositories
         for perm in self.default_repo_perms:
             r_k = perm.UserRepoToPerm.repository.repo_name
             obj_id = perm.UserRepoToPerm.repository.repo_id
             archived = perm.UserRepoToPerm.repository.archived
             p = 'repository.admin'
             self.permissions_repositories[r_k] = p, PermOrigin.SUPER_ADMIN, obj_id
             # special case for archived repositories, which we block still even for
             # super admins
             if archived:
                 p = 'repository.read'
                 self.permissions_repositories[r_k] = p, PermOrigin.ARCHIVED, obj_id
 
         # repository groups
         for perm in self.default_repo_groups_perms:
             rg_k = perm.UserRepoGroupToPerm.group.group_name
             obj_id = perm.UserRepoGroupToPerm.group.group_id
             p = 'group.admin'
             self.permissions_repository_groups[rg_k] = p, PermOrigin.SUPER_ADMIN, obj_id
 
         # user groups
         for perm in self.default_user_group_perms:
             u_k = perm.UserUserGroupToPerm.user_group.users_group_name
             obj_id = perm.UserUserGroupToPerm.user_group.users_group_id
             p = 'usergroup.admin'
             self.permissions_user_groups[u_k] = p, PermOrigin.SUPER_ADMIN, obj_id
 
         # branch permissions
         # since super-admin also can have custom rule permissions
         # we *always* need to calculate those inherited from default, and also explicit
         self._calculate_default_permissions_repository_branches(
             user_inherit_object_permissions=False)
         self._calculate_repository_branch_permissions()
 
         return self._permission_structure()
 
     def _calculate_global_default_permissions(self):
         """
         global permissions taken from the default user
         """
         default_global_perms = UserToPerm.query()\
             .filter(UserToPerm.user_id == self.default_user_id)\
             .options(joinedload(UserToPerm.permission))
 
         for perm in default_global_perms:
             self.permissions_global.add(perm.permission.permission_name)
 
         if self.user_is_admin:
             self.permissions_global.add('hg.admin')
             self.permissions_global.add('hg.create.write_on_repogroup.true')
 
     def _calculate_global_permissions(self):
         """
         Set global system permissions with user permissions or permissions
         taken from the user groups of the current user.
 
         The permissions include repo creating, repo group creating, forking
         etc.
         """
 
         # now we read the defined permissions and overwrite what we have set
         # before those can be configured from groups or users explicitly.
 
         # In case we want to extend this list we should make sure
         # this is in sync with User.DEFAULT_USER_PERMISSIONS definitions
         from rhodecode.model.permission import PermissionModel
 
         _configurable = frozenset([
             PermissionModel.FORKING_DISABLED, PermissionModel.FORKING_ENABLED,
             'hg.create.none', 'hg.create.repository',
             'hg.usergroup.create.false', 'hg.usergroup.create.true',
             'hg.repogroup.create.false', 'hg.repogroup.create.true',
             'hg.create.write_on_repogroup.false', 'hg.create.write_on_repogroup.true',
             'hg.inherit_default_perms.false', 'hg.inherit_default_perms.true'
         ])
 
         # USER GROUPS comes first user group global permissions
         user_perms_from_users_groups = Session().query(UserGroupToPerm)\
             .options(joinedload(UserGroupToPerm.permission))\
             .join((UserGroupMember, UserGroupToPerm.users_group_id ==
                    UserGroupMember.users_group_id))\
             .filter(UserGroupMember.user_id == self.user_id)\
             .order_by(UserGroupToPerm.users_group_id)\
             .all()
 
         # need to group here by groups since user can be in more than
         # one group, so we get all groups
         _explicit_grouped_perms = [
             [x, list(y)] for x, y in
             itertools.groupby(user_perms_from_users_groups,
                               lambda _x: _x.users_group)]
 
         for gr, perms in _explicit_grouped_perms:
             # since user can be in multiple groups iterate over them and
             # select the lowest permissions first (more explicit)
             # TODO(marcink): do this^^
 
             # group doesn't inherit default permissions so we actually set them
             if not gr.inherit_default_permissions:
                 # NEED TO IGNORE all previously set configurable permissions
                 # and replace them with explicitly set from this user
                 # group permissions
                 self.permissions_global = self.permissions_global.difference(
                     _configurable)
                 for perm in perms:
                     self.permissions_global.add(perm.permission.permission_name)
 
         # user explicit global permissions
         user_perms = Session().query(UserToPerm)\
             .options(joinedload(UserToPerm.permission))\
             .filter(UserToPerm.user_id == self.user_id).all()
 
         if not self.inherit_default_permissions:
             # NEED TO IGNORE all configurable permissions and
             # replace them with explicitly set from this user permissions
             self.permissions_global = self.permissions_global.difference(
                 _configurable)
             for perm in user_perms:
                 self.permissions_global.add(perm.permission.permission_name)
 
     def _calculate_default_permissions_repositories(self, user_inherit_object_permissions):
         for perm in self.default_repo_perms:
             r_k = perm.UserRepoToPerm.repository.repo_name
             obj_id = perm.UserRepoToPerm.repository.repo_id
             archived = perm.UserRepoToPerm.repository.archived
             p = perm.Permission.permission_name
             o = PermOrigin.REPO_DEFAULT
             self.permissions_repositories[r_k] = p, o, obj_id
 
             # if we decide this user isn't inheriting permissions from
             # default user we set him to .none so only explicit
             # permissions work
             if not user_inherit_object_permissions:
                 p = 'repository.none'
                 o = PermOrigin.REPO_DEFAULT_NO_INHERIT
                 self.permissions_repositories[r_k] = p, o, obj_id
 
             if perm.Repository.private and not (
                     perm.Repository.user_id == self.user_id):
                 # disable defaults for private repos,
                 p = 'repository.none'
                 o = PermOrigin.REPO_PRIVATE
                 self.permissions_repositories[r_k] = p, o, obj_id
 
             elif perm.Repository.user_id == self.user_id:
                 # set admin if owner
                 p = 'repository.admin'
                 o = PermOrigin.REPO_OWNER
                 self.permissions_repositories[r_k] = p, o, obj_id
 
             if self.user_is_admin:
                 p = 'repository.admin'
                 o = PermOrigin.SUPER_ADMIN
                 self.permissions_repositories[r_k] = p, o, obj_id
 
             # finally in case of archived repositories, we downgrade  higher
             # permissions to read
             if archived:
                 current_perm = self.permissions_repositories[r_k]
                 if current_perm in ['repository.write', 'repository.admin']:
                     p = 'repository.read'
                     o = PermOrigin.ARCHIVED
                     self.permissions_repositories[r_k] = p, o, obj_id
 
     def _calculate_default_permissions_repository_branches(self, user_inherit_object_permissions):
         for perm in self.default_branch_repo_perms:
 
             r_k = perm.UserRepoToPerm.repository.repo_name
             p = perm.Permission.permission_name
             pattern = perm.UserToRepoBranchPermission.branch_pattern
             o = PermOrigin.REPO_USER % perm.UserRepoToPerm.user.username
 
             if not self.explicit:
                 cur_perm = self.permissions_repository_branches.get(r_k)
                 if cur_perm:
                     cur_perm = cur_perm[pattern]
                 cur_perm = cur_perm or 'branch.none'
 
                 p = self._choose_permission(p, cur_perm)
 
             # NOTE(marcink): register all pattern/perm instances in this
             # special dict that aggregates entries
             self.permissions_repository_branches[r_k] = pattern, p, o
 
     def _calculate_default_permissions_repository_groups(self, user_inherit_object_permissions):
         for perm in self.default_repo_groups_perms:
             rg_k = perm.UserRepoGroupToPerm.group.group_name
             obj_id = perm.UserRepoGroupToPerm.group.group_id
             p = perm.Permission.permission_name
             o = PermOrigin.REPOGROUP_DEFAULT
             self.permissions_repository_groups[rg_k] = p, o, obj_id
 
             # if we decide this user isn't inheriting permissions from default
             # user we set him to .none so only explicit permissions work
             if not user_inherit_object_permissions:
                 p = 'group.none'
                 o = PermOrigin.REPOGROUP_DEFAULT_NO_INHERIT
                 self.permissions_repository_groups[rg_k] = p, o, obj_id
 
             if perm.RepoGroup.user_id == self.user_id:
                 # set admin if owner
                 p = 'group.admin'
                 o = PermOrigin.REPOGROUP_OWNER
                 self.permissions_repository_groups[rg_k] = p, o, obj_id
 
             if self.user_is_admin:
                 p = 'group.admin'
                 o = PermOrigin.SUPER_ADMIN
                 self.permissions_repository_groups[rg_k] = p, o, obj_id
 
     def _calculate_default_permissions_user_groups(self, user_inherit_object_permissions):
         for perm in self.default_user_group_perms:
             u_k = perm.UserUserGroupToPerm.user_group.users_group_name
             obj_id = perm.UserUserGroupToPerm.user_group.users_group_id
             p = perm.Permission.permission_name
             o = PermOrigin.USERGROUP_DEFAULT
             self.permissions_user_groups[u_k] = p, o, obj_id
 
             # if we decide this user isn't inheriting permissions from default
             # user we set him to .none so only explicit permissions work
             if not user_inherit_object_permissions:
                 p = 'usergroup.none'
                 o = PermOrigin.USERGROUP_DEFAULT_NO_INHERIT
                 self.permissions_user_groups[u_k] = p, o, obj_id
 
             if perm.UserGroup.user_id == self.user_id:
                 # set admin if owner
                 p = 'usergroup.admin'
                 o = PermOrigin.USERGROUP_OWNER
                 self.permissions_user_groups[u_k] = p, o, obj_id
 
             if self.user_is_admin:
                 p = 'usergroup.admin'
                 o = PermOrigin.SUPER_ADMIN
                 self.permissions_user_groups[u_k] = p, o, obj_id
 
     def _calculate_default_permissions(self):
         """
         Set default user permissions for repositories, repository branches,
         repository groups, user groups taken from the default user.
 
         Calculate inheritance of object permissions based on what we have now
         in GLOBAL permissions. We check if .false is in GLOBAL since this is
         explicitly set. Inherit is the opposite of .false being there.
 
         .. note::
 
            the syntax is little bit odd but what we need to check here is
            the opposite of .false permission being in the list so even for
            inconsistent state when both .true/.false is there
            .false is more important
 
         """
         user_inherit_object_permissions = not ('hg.inherit_default_perms.false'
                                                in self.permissions_global)
 
         # default permissions inherited from `default` user permissions
         self._calculate_default_permissions_repositories(
             user_inherit_object_permissions)
 
         self._calculate_default_permissions_repository_branches(
             user_inherit_object_permissions)
 
         self._calculate_default_permissions_repository_groups(
             user_inherit_object_permissions)
 
         self._calculate_default_permissions_user_groups(
             user_inherit_object_permissions)
 
     def _calculate_repository_permissions(self):
         """
         Repository access permissions for the current user.
 
         Check if the user is part of user groups for this repository and
         fill in the permission from it. `_choose_permission` decides of which
         permission should be selected based on selected method.
         """
 
         # user group for repositories permissions
         user_repo_perms_from_user_group = Permission\
             .get_default_repo_perms_from_user_group(
                 self.user_id, self.scope_repo_id)
 
         multiple_counter = collections.defaultdict(int)
         for perm in user_repo_perms_from_user_group:
             r_k = perm.UserGroupRepoToPerm.repository.repo_name
             obj_id = perm.UserGroupRepoToPerm.repository.repo_id
             multiple_counter[r_k] += 1
             p = perm.Permission.permission_name
             o = PermOrigin.REPO_USERGROUP % perm.UserGroupRepoToPerm\
                 .users_group.users_group_name
 
             if multiple_counter[r_k] > 1:
                 cur_perm = self.permissions_repositories[r_k]
                 p = self._choose_permission(p, cur_perm)
 
             self.permissions_repositories[r_k] = p, o, obj_id
 
             if perm.Repository.user_id == self.user_id:
                 # set admin if owner
                 p = 'repository.admin'
                 o = PermOrigin.REPO_OWNER
                 self.permissions_repositories[r_k] = p, o, obj_id
 
             if self.user_is_admin:
                 p = 'repository.admin'
                 o = PermOrigin.SUPER_ADMIN
                 self.permissions_repositories[r_k] = p, o, obj_id
 
         # user explicit permissions for repositories, overrides any specified
         # by the group permission
         user_repo_perms = Permission.get_default_repo_perms(
             self.user_id, self.scope_repo_id)
         for perm in user_repo_perms:
             r_k = perm.UserRepoToPerm.repository.repo_name
             obj_id = perm.UserRepoToPerm.repository.repo_id
             archived = perm.UserRepoToPerm.repository.archived
             p = perm.Permission.permission_name
             o = PermOrigin.REPO_USER % perm.UserRepoToPerm.user.username
 
             if not self.explicit:
                 cur_perm = self.permissions_repositories.get(
                     r_k, 'repository.none')
                 p = self._choose_permission(p, cur_perm)
 
             self.permissions_repositories[r_k] = p, o, obj_id
 
             if perm.Repository.user_id == self.user_id:
                 # set admin if owner
                 p = 'repository.admin'
                 o = PermOrigin.REPO_OWNER
                 self.permissions_repositories[r_k] = p, o, obj_id
 
             if self.user_is_admin:
                 p = 'repository.admin'
                 o = PermOrigin.SUPER_ADMIN
                 self.permissions_repositories[r_k] = p, o, obj_id
 
             # finally in case of archived repositories, we downgrade  higher
             # permissions to read
             if archived:
                 current_perm = self.permissions_repositories[r_k]
                 if current_perm in ['repository.write', 'repository.admin']:
                     p = 'repository.read'
                     o = PermOrigin.ARCHIVED
                     self.permissions_repositories[r_k] = p, o, obj_id
 
     def _calculate_repository_branch_permissions(self):
         # user group for repositories permissions
         user_repo_branch_perms_from_user_group = Permission\
             .get_default_repo_branch_perms_from_user_group(
                 self.user_id, self.scope_repo_id)
 
         multiple_counter = collections.defaultdict(int)
         for perm in user_repo_branch_perms_from_user_group:
             r_k = perm.UserGroupRepoToPerm.repository.repo_name
             p = perm.Permission.permission_name
             pattern = perm.UserGroupToRepoBranchPermission.branch_pattern
             o = PermOrigin.REPO_USERGROUP % perm.UserGroupRepoToPerm\
                 .users_group.users_group_name
 
             multiple_counter[r_k] += 1
             if multiple_counter[r_k] > 1:
                 cur_perm = self.permissions_repository_branches[r_k][pattern]
                 p = self._choose_permission(p, cur_perm)
 
             self.permissions_repository_branches[r_k] = pattern, p, o
 
         # user explicit branch permissions for repositories, overrides
         # any specified by the group permission
         user_repo_branch_perms = Permission.get_default_repo_branch_perms(
             self.user_id, self.scope_repo_id)
 
         for perm in user_repo_branch_perms:
 
             r_k = perm.UserRepoToPerm.repository.repo_name
             p = perm.Permission.permission_name
             pattern = perm.UserToRepoBranchPermission.branch_pattern
             o = PermOrigin.REPO_USER % perm.UserRepoToPerm.user.username
 
             if not self.explicit:
                 cur_perm = self.permissions_repository_branches.get(r_k)
                 if cur_perm:
                     cur_perm = cur_perm[pattern]
                 cur_perm = cur_perm or 'branch.none'
                 p = self._choose_permission(p, cur_perm)
 
             # NOTE(marcink): register all pattern/perm instances in this
             # special dict that aggregates entries
             self.permissions_repository_branches[r_k] = pattern, p, o
 
     def _calculate_repository_group_permissions(self):
         """
         Repository group permissions for the current user.
 
         Check if the user is part of user groups for repository groups and
         fill in the permissions from it. `_choose_permission` decides of which
         permission should be selected based on selected method.
         """
         # user group for repo groups permissions
         user_repo_group_perms_from_user_group = Permission\
             .get_default_group_perms_from_user_group(
                 self.user_id, self.scope_repo_group_id)
 
         multiple_counter = collections.defaultdict(int)
         for perm in user_repo_group_perms_from_user_group:
             rg_k = perm.UserGroupRepoGroupToPerm.group.group_name
             obj_id = perm.UserGroupRepoGroupToPerm.group.group_id
             multiple_counter[rg_k] += 1
             o = PermOrigin.REPOGROUP_USERGROUP % perm.UserGroupRepoGroupToPerm\
                 .users_group.users_group_name
             p = perm.Permission.permission_name
 
             if multiple_counter[rg_k] > 1:
                 cur_perm = self.permissions_repository_groups[rg_k]
                 p = self._choose_permission(p, cur_perm)
             self.permissions_repository_groups[rg_k] = p, o, obj_id
 
             if perm.RepoGroup.user_id == self.user_id:
                 # set admin if owner, even for member of other user group
                 p = 'group.admin'
                 o = PermOrigin.REPOGROUP_OWNER
                 self.permissions_repository_groups[rg_k] = p, o, obj_id
 
             if self.user_is_admin:
                 p = 'group.admin'
                 o = PermOrigin.SUPER_ADMIN
                 self.permissions_repository_groups[rg_k] = p, o, obj_id
 
         # user explicit permissions for repository groups
         user_repo_groups_perms = Permission.get_default_group_perms(
             self.user_id, self.scope_repo_group_id)
         for perm in user_repo_groups_perms:
             rg_k = perm.UserRepoGroupToPerm.group.group_name
             obj_id = perm.UserRepoGroupToPerm.group.group_id
             o = PermOrigin.REPOGROUP_USER % perm.UserRepoGroupToPerm\
                 .user.username
             p = perm.Permission.permission_name
 
             if not self.explicit:
                 cur_perm = self.permissions_repository_groups.get(rg_k, 'group.none')
                 p = self._choose_permission(p, cur_perm)
 
             self.permissions_repository_groups[rg_k] = p, o, obj_id
 
             if perm.RepoGroup.user_id == self.user_id:
                 # set admin if owner
                 p = 'group.admin'
                 o = PermOrigin.REPOGROUP_OWNER
                 self.permissions_repository_groups[rg_k] = p, o, obj_id
 
             if self.user_is_admin:
                 p = 'group.admin'
                 o = PermOrigin.SUPER_ADMIN
                 self.permissions_repository_groups[rg_k] = p, o, obj_id
 
     def _calculate_user_group_permissions(self):
         """
         User group permissions for the current user.
         """
         # user group for user group permissions
         user_group_from_user_group = Permission\
             .get_default_user_group_perms_from_user_group(
                 self.user_id, self.scope_user_group_id)
 
         multiple_counter = collections.defaultdict(int)
         for perm in user_group_from_user_group:
             ug_k = perm.UserGroupUserGroupToPerm.target_user_group.users_group_name
             obj_id = perm.UserGroupUserGroupToPerm.target_user_group.users_group_id
             multiple_counter[ug_k] += 1
             o = PermOrigin.USERGROUP_USERGROUP % perm.UserGroupUserGroupToPerm\
                 .user_group.users_group_name
             p = perm.Permission.permission_name
 
             if multiple_counter[ug_k] > 1:
                 cur_perm = self.permissions_user_groups[ug_k]
                 p = self._choose_permission(p, cur_perm)
 
             self.permissions_user_groups[ug_k] = p, o, obj_id
 
             if perm.UserGroup.user_id == self.user_id:
                 # set admin if owner, even for member of other user group
                 p = 'usergroup.admin'
                 o = PermOrigin.USERGROUP_OWNER
                 self.permissions_user_groups[ug_k] = p, o, obj_id
 
             if self.user_is_admin:
                 p = 'usergroup.admin'
                 o = PermOrigin.SUPER_ADMIN
                 self.permissions_user_groups[ug_k] = p, o, obj_id
 
         # user explicit permission for user groups
         user_user_groups_perms = Permission.get_default_user_group_perms(
             self.user_id, self.scope_user_group_id)
         for perm in user_user_groups_perms:
             ug_k = perm.UserUserGroupToPerm.user_group.users_group_name
             obj_id = perm.UserUserGroupToPerm.user_group.users_group_id
             o = PermOrigin.USERGROUP_USER % perm.UserUserGroupToPerm\
                 .user.username
             p = perm.Permission.permission_name
 
             if not self.explicit:
                 cur_perm = self.permissions_user_groups.get(ug_k, 'usergroup.none')
                 p = self._choose_permission(p, cur_perm)
 
             self.permissions_user_groups[ug_k] = p, o, obj_id
 
             if perm.UserGroup.user_id == self.user_id:
                 # set admin if owner
                 p = 'usergroup.admin'
                 o = PermOrigin.USERGROUP_OWNER
                 self.permissions_user_groups[ug_k] = p, o, obj_id
 
             if self.user_is_admin:
                 p = 'usergroup.admin'
                 o = PermOrigin.SUPER_ADMIN
                 self.permissions_user_groups[ug_k] = p, o, obj_id
 
     def _choose_permission(self, new_perm, cur_perm):
         new_perm_val = Permission.PERM_WEIGHTS[new_perm]
         cur_perm_val = Permission.PERM_WEIGHTS[cur_perm]
         if self.algo == 'higherwin':
             if new_perm_val > cur_perm_val:
                 return new_perm
             return cur_perm
         elif self.algo == 'lowerwin':
             if new_perm_val < cur_perm_val:
                 return new_perm
             return cur_perm
 
     def _permission_structure(self):
         return {
             'global': self.permissions_global,
             'repositories': self.permissions_repositories,
             'repository_branches': self.permissions_repository_branches,
             'repositories_groups': self.permissions_repository_groups,
             'user_groups': self.permissions_user_groups,
         }
 
 
 def allowed_auth_token_access(view_name, auth_token, whitelist=None):
     """
     Check if given controller_name is in whitelist of auth token access
     """
     if not whitelist:
         from rhodecode import CONFIG
         whitelist = aslist(
             CONFIG.get('api_access_controllers_whitelist'), sep=',')
     # backward compat translation
     compat = {
         # old controller, new VIEW
         'ChangesetController:*': 'RepoCommitsView:*',
         'ChangesetController:changeset_patch': 'RepoCommitsView:repo_commit_patch',
         'ChangesetController:changeset_raw': 'RepoCommitsView:repo_commit_raw',
         'FilesController:raw': 'RepoCommitsView:repo_commit_raw',
         'FilesController:archivefile': 'RepoFilesView:repo_archivefile',
         'GistsController:*': 'GistView:*',
     }
 
     log.debug(
         'Allowed views for AUTH TOKEN access: %s', whitelist)
     auth_token_access_valid = False
 
     for entry in whitelist:
         token_match = True
         if entry in compat:
             # translate from old Controllers to Pyramid Views
             entry = compat[entry]
 
         if '@' in entry:
             # specific AuthToken
             entry, allowed_token = entry.split('@', 1)
             token_match = auth_token == allowed_token
 
         if fnmatch.fnmatch(view_name, entry) and token_match:
             auth_token_access_valid = True
             break
 
     if auth_token_access_valid:
         log.debug('view: `%s` matches entry in whitelist: %s',
                   view_name, whitelist)
 
     else:
         msg = ('view: `%s` does *NOT* match any entry in whitelist: %s'
                % (view_name, whitelist))
         if auth_token:
             # if we use auth token key and don't have access it's a warning
             log.warning(msg)
         else:
             log.debug(msg)
 
     return auth_token_access_valid
 
 
 class AuthUser(object):
     """
     A simple object that handles all attributes of user in RhodeCode
 
     It does lookup based on API key,given user, or user present in session
     Then it fills all required information for such user. It also checks if
     anonymous access is enabled and if so, it returns default user as logged in
     """
     GLOBAL_PERMS = [x[0] for x in Permission.PERMS]
     repo_read_perms = ['repository.read', 'repository.admin', 'repository.write']
     repo_group_read_perms = ['group.read', 'group.write', 'group.admin']
     user_group_read_perms = ['usergroup.read', 'usergroup.write', 'usergroup.admin']
 
     def __init__(self, user_id=None, api_key=None, username=None, ip_addr=None):
 
         self.user_id = user_id
         self._api_key = api_key
 
         self.api_key = None
         self.username = username
         self.ip_addr = ip_addr
         self.name = ''
         self.lastname = ''
         self.first_name = ''
         self.last_name = ''
         self.email = ''
         self.is_authenticated = False
         self.admin = False
         self.inherit_default_permissions = False
         self.password = ''
 
         self.anonymous_user = None  # propagated on propagate_data
         self.propagate_data()
         self._instance = None
         self._permissions_scoped_cache = {}  # used to bind scoped calculation
 
     @LazyProperty
     def permissions(self):
         return self.get_perms(user=self, cache=None)
 
     @LazyProperty
     def permissions_safe(self):
         """
         Filtered permissions excluding not allowed repositories
         """
         perms = self.get_perms(user=self, cache=None)
 
         perms['repositories'] = {
             k: v for k, v in perms['repositories'].items()
             if v != 'repository.none'}
         perms['repositories_groups'] = {
             k: v for k, v in perms['repositories_groups'].items()
             if v != 'group.none'}
         perms['user_groups'] = {
             k: v for k, v in perms['user_groups'].items()
             if v != 'usergroup.none'}
         perms['repository_branches'] = {
             k: v for k, v in perms['repository_branches'].iteritems()
             if v != 'branch.none'}
         return perms
 
     @LazyProperty
     def permissions_full_details(self):
         return self.get_perms(
             user=self, cache=None, calculate_super_admin=True)
 
     def permissions_with_scope(self, scope):
         """
         Call the get_perms function with scoped data. The scope in that function
         narrows the SQL calls to the given ID of objects resulting in fetching
         Just particular permission we want to obtain. If scope is an empty dict
         then it basically narrows the scope to GLOBAL permissions only.
 
         :param scope: dict
         """
         if 'repo_name' in scope:
             obj = Repository.get_by_repo_name(scope['repo_name'])
             if obj:
                 scope['repo_id'] = obj.repo_id
         _scope = collections.OrderedDict()
         _scope['repo_id'] = -1
         _scope['user_group_id'] = -1
         _scope['repo_group_id'] = -1
 
         for k in sorted(scope.keys()):
             _scope[k] = scope[k]
 
         # store in cache to mimic how the @LazyProperty works,
         # the difference here is that we use the unique key calculated
         # from params and values
         return self.get_perms(user=self, cache=None, scope=_scope)
 
     def get_instance(self):
         return User.get(self.user_id)
 
     def propagate_data(self):
         """
         Fills in user data and propagates values to this instance. Maps fetched
         user attributes to this class instance attributes
         """
         log.debug('AuthUser: starting data propagation for new potential user')
         user_model = UserModel()
         anon_user = self.anonymous_user = User.get_default_user(cache=True)
         is_user_loaded = False
 
         # lookup by userid
         if self.user_id is not None and self.user_id != anon_user.user_id:
             log.debug('Trying Auth User lookup by USER ID: `%s`', self.user_id)
             is_user_loaded = user_model.fill_data(self, user_id=self.user_id)
 
         # try go get user by api key
         elif self._api_key and self._api_key != anon_user.api_key:
             log.debug('Trying Auth User lookup by API KEY: `...%s`', self._api_key[-4:])
             is_user_loaded = user_model.fill_data(self, api_key=self._api_key)
 
         # lookup by username
         elif self.username:
             log.debug('Trying Auth User lookup by USER NAME: `%s`', self.username)
             is_user_loaded = user_model.fill_data(self, username=self.username)
         else:
             log.debug('No data in %s that could been used to log in', self)
 
         if not is_user_loaded:
             log.debug(
                 'Failed to load user. Fallback to default user %s', anon_user)
             # if we cannot authenticate user try anonymous
             if anon_user.active:
                 log.debug('default user is active, using it as a session user')
                 user_model.fill_data(self, user_id=anon_user.user_id)
                 # then we set this user is logged in
                 self.is_authenticated = True
             else:
                 log.debug('default user is NOT active')
                 # in case of disabled anonymous user we reset some of the
                 # parameters so such user is "corrupted", skipping the fill_data
                 for attr in ['user_id', 'username', 'admin', 'active']:
                     setattr(self, attr, None)
                 self.is_authenticated = False
 
         if not self.username:
             self.username = 'None'
 
         log.debug('AuthUser: propagated user is now %s', self)
 
     def get_perms(self, user, scope=None, explicit=True, algo='higherwin',
                   calculate_super_admin=False, cache=None):
         """
         Fills user permission attribute with permissions taken from database
         works for permissions given for repositories, and for permissions that
         are granted to groups
 
         :param user: instance of User object from database
         :param explicit: In case there are permissions both for user and a group
             that user is part of, explicit flag will defiine if user will
             explicitly override permissions from group, if it's False it will
             make decision based on the algo
         :param algo: algorithm to decide what permission should be choose if
             it's multiple defined, eg user in two different groups. It also
             decides if explicit flag is turned off how to specify the permission
             for case when user is in a group + have defined separate permission
         :param calculate_super_admin: calculate permissions for super-admin in the
             same way as for regular user without speedups
         :param cache: Use caching for calculation, None = let the cache backend decide
         """
         user_id = user.user_id
         user_is_admin = user.is_admin
 
         # inheritance of global permissions like create repo/fork repo etc
         user_inherit_default_permissions = user.inherit_default_permissions
 
         cache_seconds = safe_int(
             rhodecode.CONFIG.get('rc_cache.cache_perms.expiration_time'))
 
         if cache is None:
             # let the backend cache decide
             cache_on = cache_seconds > 0
         else:
             cache_on = cache
 
         log.debug(
             'Computing PERMISSION tree for user %s scope `%s` '
             'with caching: %s[TTL: %ss]', user, scope, cache_on, cache_seconds or 0)
 
         cache_namespace_uid = 'cache_user_auth.{}'.format(user_id)
         region = rc_cache.get_or_create_region('cache_perms', cache_namespace_uid)
 
         @region.conditional_cache_on_arguments(namespace=cache_namespace_uid,
                                                condition=cache_on)
         def compute_perm_tree(cache_name, cache_ver,
                 user_id, scope, user_is_admin,user_inherit_default_permissions,
                 explicit, algo, calculate_super_admin):
             return _cached_perms_data(
                 user_id, scope, user_is_admin, user_inherit_default_permissions,
                 explicit, algo, calculate_super_admin)
 
         start = time.time()
         result = compute_perm_tree(
             'permissions', 'v1', user_id, scope, user_is_admin,
              user_inherit_default_permissions, explicit, algo,
              calculate_super_admin)
 
         result_repr = []
         for k in result:
             result_repr.append((k, len(result[k])))
         total = time.time() - start
         log.debug('PERMISSION tree for user %s computed in %.4fs: %s',
                   user, total, result_repr)
 
         return result
 
     @property
     def is_default(self):
         return self.username == User.DEFAULT_USER
 
     @property
     def is_admin(self):
         return self.admin
 
     @property
     def is_user_object(self):
         return self.user_id is not None
 
     @property
     def repositories_admin(self):
         """
         Returns list of repositories you're an admin of
         """
         return [
             x[0] for x in self.permissions['repositories'].items()
             if x[1] == 'repository.admin']
 
     @property
     def repository_groups_admin(self):
         """
         Returns list of repository groups you're an admin of
         """
         return [
             x[0] for x in self.permissions['repositories_groups'].items()
             if x[1] == 'group.admin']
 
     @property
     def user_groups_admin(self):
         """
         Returns list of user groups you're an admin of
         """
         return [
             x[0] for x in self.permissions['user_groups'].items()
             if x[1] == 'usergroup.admin']
 
     def repo_acl_ids_from_stack(self, perms=None, prefix_filter=None, cache=False):
         if not perms:
             perms = AuthUser.repo_read_perms
         allowed_ids = []
         for k, stack_data in self.permissions['repositories'].perm_origin_stack.items():
             perm, origin, obj_id = stack_data[-1]  # last item is the current permission
             if prefix_filter and not k.startswith(prefix_filter):
                 continue
             if perm in perms:
                 allowed_ids.append(obj_id)
         return allowed_ids
 
     def repo_acl_ids(self, perms=None, name_filter=None, cache=False):
         """
         Returns list of repository ids that user have access to based on given
         perms. The cache flag should be only used in cases that are used for
         display purposes, NOT IN ANY CASE for permission checks.
         """
         from rhodecode.model.scm import RepoList
         if not perms:
             perms = AuthUser.repo_read_perms
 
         if not isinstance(perms, list):
             raise ValueError('perms parameter must be a list got {} instead'.format(perms))
 
         def _cached_repo_acl(perm_def, _name_filter):
             qry = Repository.query()
             if _name_filter:
                 ilike_expression = u'%{}%'.format(safe_unicode(_name_filter))
                 qry = qry.filter(
                     Repository.repo_name.ilike(ilike_expression))
 
             return [x.repo_id for x in
                     RepoList(qry, perm_set=perm_def, extra_kwargs={'user': self})]
 
         log.debug('Computing REPO ACL IDS user %s', self)
 
         cache_namespace_uid = 'cache_user_repo_acl_ids.{}'.format(self.user_id)
         region = rc_cache.get_or_create_region('cache_perms', cache_namespace_uid)
 
         @region.conditional_cache_on_arguments(namespace=cache_namespace_uid, condition=cache)
         def compute_repo_acl_ids(cache_ver, user_id, perm_def, _name_filter):
             return _cached_repo_acl(perm_def, _name_filter)
 
         start = time.time()
         result = compute_repo_acl_ids('v1', self.user_id, perms, name_filter)
         total = time.time() - start
         log.debug('REPO ACL IDS for user %s computed in %.4fs', self, total)
 
         return result
 
     def repo_group_acl_ids_from_stack(self, perms=None, prefix_filter=None, cache=False):
         if not perms:
             perms = AuthUser.repo_group_read_perms
         allowed_ids = []
         for k, stack_data in self.permissions['repositories_groups'].perm_origin_stack.items():
             perm, origin, obj_id = stack_data[-1]  # last item is the current permission
             if prefix_filter and not k.startswith(prefix_filter):
                 continue
             if perm in perms:
                 allowed_ids.append(obj_id)
         return allowed_ids
 
     def repo_group_acl_ids(self, perms=None, name_filter=None, cache=False):
         """
         Returns list of repository group ids that user have access to based on given
         perms. The cache flag should be only used in cases that are used for
         display purposes, NOT IN ANY CASE for permission checks.
         """
         from rhodecode.model.scm import RepoGroupList
         if not perms:
             perms = AuthUser.repo_group_read_perms
 
         if not isinstance(perms, list):
             raise ValueError('perms parameter must be a list got {} instead'.format(perms))
 
         def _cached_repo_group_acl(perm_def, _name_filter):
             qry = RepoGroup.query()
             if _name_filter:
                 ilike_expression = u'%{}%'.format(safe_unicode(_name_filter))
                 qry = qry.filter(
                     RepoGroup.group_name.ilike(ilike_expression))
 
             return [x.group_id for x in
                     RepoGroupList(qry, perm_set=perm_def, extra_kwargs={'user': self})]
 
         log.debug('Computing REPO GROUP ACL IDS user %s', self)
 
         cache_namespace_uid = 'cache_user_repo_group_acl_ids.{}'.format(self.user_id)
         region = rc_cache.get_or_create_region('cache_perms', cache_namespace_uid)
 
         @region.conditional_cache_on_arguments(namespace=cache_namespace_uid, condition=cache)
         def compute_repo_group_acl_ids(cache_ver, user_id, perm_def, _name_filter):
             return _cached_repo_group_acl(perm_def, _name_filter)
 
         start = time.time()
         result = compute_repo_group_acl_ids('v1', self.user_id, perms, name_filter)
         total = time.time() - start
         log.debug('REPO GROUP ACL IDS for user %s computed in %.4fs', self, total)
 
         return result
 
     def user_group_acl_ids_from_stack(self, perms=None, cache=False):
         if not perms:
             perms = AuthUser.user_group_read_perms
         allowed_ids = []
         for k, stack_data in self.permissions['user_groups'].perm_origin_stack.items():
             perm, origin, obj_id = stack_data[-1]  # last item is the current permission
             if perm in perms:
                 allowed_ids.append(obj_id)
         return allowed_ids
 
     def user_group_acl_ids(self, perms=None, name_filter=None, cache=False):
         """
         Returns list of user group ids that user have access to based on given
         perms. The cache flag should be only used in cases that are used for
         display purposes, NOT IN ANY CASE for permission checks.
         """
         from rhodecode.model.scm import UserGroupList
         if not perms:
             perms = AuthUser.user_group_read_perms
 
         if not isinstance(perms, list):
             raise ValueError('perms parameter must be a list got {} instead'.format(perms))
 
         def _cached_user_group_acl(perm_def, _name_filter):
             qry = UserGroup.query()
             if _name_filter:
                 ilike_expression = u'%{}%'.format(safe_unicode(_name_filter))
                 qry = qry.filter(
                     UserGroup.users_group_name.ilike(ilike_expression))
 
             return [x.users_group_id for x in
                     UserGroupList(qry, perm_set=perm_def, extra_kwargs={'user': self})]
 
         log.debug('Computing USER GROUP ACL IDS user %s', self)
 
         cache_namespace_uid = 'cache_user_user_group_acl_ids.{}'.format(self.user_id)
         region = rc_cache.get_or_create_region('cache_perms', cache_namespace_uid)
 
         @region.conditional_cache_on_arguments(namespace=cache_namespace_uid, condition=cache)
         def compute_user_group_acl_ids(cache_ver, user_id, perm_def, _name_filter):
             return _cached_user_group_acl(perm_def, _name_filter)
 
         start = time.time()
         result = compute_user_group_acl_ids('v1', self.user_id, perms, name_filter)
         total = time.time() - start
         log.debug('USER GROUP ACL IDS for user %s computed in %.4fs', self, total)
 
         return result
 
     @property
     def ip_allowed(self):
         """
         Checks if ip_addr used in constructor is allowed from defined list of
         allowed ip_addresses for user
 
         :returns: boolean, True if ip is in allowed ip range
         """
         # check IP
         inherit = self.inherit_default_permissions
         return AuthUser.check_ip_allowed(self.user_id, self.ip_addr,
                                          inherit_from_default=inherit)
 
     @property
     def personal_repo_group(self):
         return RepoGroup.get_user_personal_repo_group(self.user_id)
 
     @LazyProperty
     def feed_token(self):
         return self.get_instance().feed_token
 
     @LazyProperty
     def artifact_token(self):
         return self.get_instance().artifact_token
 
     @classmethod
     def check_ip_allowed(cls, user_id, ip_addr, inherit_from_default):
         allowed_ips = AuthUser.get_allowed_ips(
             user_id, cache=True, inherit_from_default=inherit_from_default)
         if check_ip_access(source_ip=ip_addr, allowed_ips=allowed_ips):
             log.debug('IP:%s for user %s is in range of %s',
                       ip_addr, user_id, allowed_ips)
             return True
         else:
             log.info('Access for IP:%s forbidden for user %s, '
-                     'not in %s', ip_addr, user_id, allowed_ips)
+                     'not in %s', ip_addr, user_id, allowed_ips,
+                     extra={"ip": ip_addr, "user_id": user_id})
             return False
 
     def get_branch_permissions(self, repo_name, perms=None):
         perms = perms or self.permissions_with_scope({'repo_name': repo_name})
         branch_perms = perms.get('repository_branches', {})
         if not branch_perms:
             return {}
         repo_branch_perms = branch_perms.get(repo_name)
         return repo_branch_perms or {}
 
     def get_rule_and_branch_permission(self, repo_name, branch_name):
         """
         Check if this AuthUser has defined any permissions for branches. If any of
         the rules match in order, we return the matching permissions
         """
 
         rule = default_perm = ''
 
         repo_branch_perms = self.get_branch_permissions(repo_name=repo_name)
         if not repo_branch_perms:
             return rule, default_perm
 
         # now calculate the permissions
         for pattern, branch_perm in repo_branch_perms.items():
             if fnmatch.fnmatch(branch_name, pattern):
                 rule = '`{}`=>{}'.format(pattern, branch_perm)
                 return rule, branch_perm
 
         return rule, default_perm
 
     def get_notice_messages(self):
 
         notice_level = 'notice-error'
         notice_messages = []
         if self.is_default:
             return [], notice_level
 
         notices = UserNotice.query()\
             .filter(UserNotice.user_id == self.user_id)\
             .filter(UserNotice.notice_read == false())\
             .all()
 
         try:
             for entry in notices:
 
                 msg = {
                     'msg_id': entry.user_notice_id,
                     'level': entry.notification_level,
                     'subject': entry.notice_subject,
                     'body': entry.notice_body,
                 }
                 notice_messages.append(msg)
 
             log.debug('Got user %s %s messages', self, len(notice_messages))
 
             levels = [x['level'] for x in notice_messages]
             notice_level = 'notice-error' if 'error' in levels else 'notice-warning'
         except Exception:
             pass
 
         return notice_messages, notice_level
 
     def __repr__(self):
         return self.repr_user(self.user_id, self.username, self.ip_addr, self.is_authenticated)
 
     def set_authenticated(self, authenticated=True):
         if self.user_id != self.anonymous_user.user_id:
             self.is_authenticated = authenticated
 
     def get_cookie_store(self):
         return {
             'username': self.username,
             'password': md5(self.password or ''),
             'user_id': self.user_id,
             'is_authenticated': self.is_authenticated
         }
 
     @classmethod
     def repr_user(cls, user_id=0, username='ANONYMOUS', ip='0.0.0.0', is_authenticated=False):
         tmpl = "<AuthUser('id:{}[{}] ip:{} auth:{}')>"
         return tmpl.format(user_id, username, ip, is_authenticated)
 
     @classmethod
     def from_cookie_store(cls, cookie_store):
         """
         Creates AuthUser from a cookie store
 
         :param cls:
         :param cookie_store:
         """
         user_id = cookie_store.get('user_id')
         username = cookie_store.get('username')
         api_key = cookie_store.get('api_key')
         return AuthUser(user_id, api_key, username)
 
     @classmethod
     def get_allowed_ips(cls, user_id, cache=False, inherit_from_default=False):
         _set = set()
 
         if inherit_from_default:
             def_user_id = User.get_default_user(cache=True).user_id
             default_ips = UserIpMap.query().filter(UserIpMap.user_id == def_user_id)
             if cache:
                 default_ips = default_ips.options(
                     FromCache("sql_cache_short", "get_user_ips_default"))
 
             # populate from default user
             for ip in default_ips:
                 try:
                     _set.add(ip.ip_addr)
                 except ObjectDeletedError:
                     # since we use heavy caching sometimes it happens that
                     # we get deleted objects here, we just skip them
                     pass
 
         # NOTE:(marcink) we don't want to load any rules for empty
         # user_id which is the case of access of non logged users when anonymous
         # access is disabled
         user_ips = []
         if user_id:
             user_ips = UserIpMap.query().filter(UserIpMap.user_id == user_id)
             if cache:
                 user_ips = user_ips.options(
                     FromCache("sql_cache_short", "get_user_ips_%s" % user_id))
 
         for ip in user_ips:
             try:
                 _set.add(ip.ip_addr)
             except ObjectDeletedError:
                 # since we use heavy caching sometimes it happens that we get
                 # deleted objects here, we just skip them
                 pass
         return _set or {ip for ip in ['0.0.0.0/0', '::/0']}
 
 
 def set_available_permissions(settings):
     """
     This function will propagate pyramid settings with all available defined
     permission given in db. We don't want to check each time from db for new
     permissions since adding a new permission also requires application restart
     ie. to decorate new views with the newly created permission
 
     :param settings: current pyramid registry.settings
 
     """
     log.debug('auth: getting information about all available permissions')
     try:
         sa = meta.Session
         all_perms = sa.query(Permission).all()
         settings.setdefault('available_permissions',
                             [x.permission_name for x in all_perms])
         log.debug('auth: set available permissions')
     except Exception:
         log.exception('Failed to fetch permissions from the database.')
         raise
 
 
 def get_csrf_token(session, force_new=False, save_if_missing=True):
     """
     Return the current authentication token, creating one if one doesn't
     already exist and the save_if_missing flag is present.
 
     :param session: pass in the pyramid session, else we use the global ones
     :param force_new: force to re-generate the token and store it in session
     :param save_if_missing: save the newly generated token if it's missing in
         session
     """
     # NOTE(marcink): probably should be replaced with below one from pyramid 1.9
     # from pyramid.csrf import get_csrf_token
 
     if (csrf_token_key not in session and save_if_missing) or force_new:
         token = hashlib.sha1(str(random.getrandbits(128))).hexdigest()
         session[csrf_token_key] = token
         if hasattr(session, 'save'):
             session.save()
     return session.get(csrf_token_key)
 
 
 def get_request(perm_class_instance):
     from pyramid.threadlocal import get_current_request
     pyramid_request = get_current_request()
     return pyramid_request
 
 
 # CHECK DECORATORS
 class CSRFRequired(object):
     """
     Decorator for authenticating a form
 
     This decorator uses an authorization token stored in the client's
     session for prevention of certain Cross-site request forgery (CSRF)
     attacks (See
     http://en.wikipedia.org/wiki/Cross-site_request_forgery for more
     information).
 
     For use with the ``secure_form`` helper functions.
 
     """
     def __init__(self, token=csrf_token_key, header='X-CSRF-Token', except_methods=None):
         self.token = token
         self.header = header
         self.except_methods = except_methods or []
 
     def __call__(self, func):
         return get_cython_compat_decorator(self.__wrapper, func)
 
     def _get_csrf(self, _request):
         return _request.POST.get(self.token, _request.headers.get(self.header))
 
     def check_csrf(self, _request, cur_token):
         supplied_token = self._get_csrf(_request)
         return supplied_token and supplied_token == cur_token
 
     def _get_request(self):
         return get_request(self)
 
     def __wrapper(self, func, *fargs, **fkwargs):
         request = self._get_request()
 
         if request.method in self.except_methods:
             return func(*fargs, **fkwargs)
 
         cur_token = get_csrf_token(request.session, save_if_missing=False)
         if self.check_csrf(request, cur_token):
             if request.POST.get(self.token):
                 del request.POST[self.token]
             return func(*fargs, **fkwargs)
         else:
             reason = 'token-missing'
             supplied_token = self._get_csrf(request)
             if supplied_token and cur_token != supplied_token:
                 reason = 'token-mismatch [%s:%s]' % (
                     cur_token or ''[:6], supplied_token or ''[:6])
 
             csrf_message = \
                 ("Cross-site request forgery detected, request denied. See "
                  "http://en.wikipedia.org/wiki/Cross-site_request_forgery for "
                  "more information.")
         log.warn('Cross-site request forgery detected, request %r DENIED: %s '
                  'REMOTE_ADDR:%s, HEADERS:%s' % (
                      request, reason, request.remote_addr, request.headers))
 
         raise HTTPForbidden(explanation=csrf_message)
 
 
 class LoginRequired(object):
     """
     Must be logged in to execute this function else
     redirect to login page
 
     :param api_access: if enabled this checks only for valid auth token
         and grants access based on valid token
     """
     def __init__(self, auth_token_access=None):
         self.auth_token_access = auth_token_access
         if self.auth_token_access:
             valid_type = set(auth_token_access).intersection(set(UserApiKeys.ROLES))
             if not valid_type:
                 raise ValueError('auth_token_access must be on of {}, got {}'.format(
                     UserApiKeys.ROLES, auth_token_access))
 
     def __call__(self, func):
         return get_cython_compat_decorator(self.__wrapper, func)
 
     def _get_request(self):
         return get_request(self)
 
     def __wrapper(self, func, *fargs, **fkwargs):
         from rhodecode.lib import helpers as h
         cls = fargs[0]
         user = cls._rhodecode_user
         request = self._get_request()
         _ = request.translate
 
         loc = "%s:%s" % (cls.__class__.__name__, func.__name__)
         log.debug('Starting login restriction checks for user: %s', user)
         # check if our IP is allowed
         ip_access_valid = True
         if not user.ip_allowed:
             h.flash(h.literal(_('IP {} not allowed'.format(user.ip_addr))),
                     category='warning')
             ip_access_valid = False
 
         # we used stored token that is extract from GET or URL param (if any)
         _auth_token = request.user_auth_token
 
         # check if we used an AUTH_TOKEN and it's a valid one
         # defined white-list of controllers which API access will be enabled
         whitelist = None
         if self.auth_token_access:
             # since this location is allowed by @LoginRequired decorator it's our
             # only whitelist
             whitelist = [loc]
         auth_token_access_valid = allowed_auth_token_access(
             loc, whitelist=whitelist, auth_token=_auth_token)
 
         # explicit controller is enabled or API is in our whitelist
         if auth_token_access_valid:
             log.debug('Checking AUTH TOKEN access for %s', cls)
             db_user = user.get_instance()
 
             if db_user:
                 if self.auth_token_access:
                     roles = self.auth_token_access
                 else:
                     roles = [UserApiKeys.ROLE_HTTP]
                 log.debug('AUTH TOKEN: checking auth for user %s and roles %s',
                           db_user, roles)
                 token_match = db_user.authenticate_by_token(
                     _auth_token, roles=roles)
             else:
                 log.debug('Unable to fetch db instance for auth user: %s', user)
                 token_match = False
 
             if _auth_token and token_match:
                 auth_token_access_valid = True
                 log.debug('AUTH TOKEN ****%s is VALID', _auth_token[-4:])
             else:
                 auth_token_access_valid = False
                 if not _auth_token:
                     log.debug("AUTH TOKEN *NOT* present in request")
                 else:
                     log.warning("AUTH TOKEN ****%s *NOT* valid", _auth_token[-4:])
 
         log.debug('Checking if %s is authenticated @ %s', user.username, loc)
         reason = 'RHODECODE_AUTH' if user.is_authenticated \
             else 'AUTH_TOKEN_AUTH'
 
         if ip_access_valid and (
                 user.is_authenticated or auth_token_access_valid):
             log.info('user %s authenticating with:%s IS authenticated on func %s',
                      user, reason, loc)
 
             return func(*fargs, **fkwargs)
         else:
             log.warning(
                 'user %s authenticating with:%s NOT authenticated on '
                 'func: %s: IP_ACCESS:%s AUTH_TOKEN_ACCESS:%s',
                 user, reason, loc, ip_access_valid, auth_token_access_valid)
             # we preserve the get PARAM
             came_from = get_came_from(request)
 
             log.debug('redirecting to login page with %s', came_from)
             raise HTTPFound(
                 h.route_path('login', _query={'came_from': came_from}))
 
 
 class NotAnonymous(object):
     """
     Must be logged in to execute this function else
     redirect to login page
     """
 
     def __call__(self, func):
         return get_cython_compat_decorator(self.__wrapper, func)
 
     def _get_request(self):
         return get_request(self)
 
     def __wrapper(self, func, *fargs, **fkwargs):
         import rhodecode.lib.helpers as h
         cls = fargs[0]
         self.user = cls._rhodecode_user
         request = self._get_request()
         _ = request.translate
         log.debug('Checking if user is not anonymous @%s', cls)
 
         anonymous = self.user.username == User.DEFAULT_USER
 
         if anonymous:
             came_from = get_came_from(request)
             h.flash(_('You need to be a registered user to '
                       'perform this action'),
                     category='warning')
             raise HTTPFound(
                 h.route_path('login', _query={'came_from': came_from}))
         else:
             return func(*fargs, **fkwargs)
 
 
 class PermsDecorator(object):
     """
     Base class for controller decorators, we extract the current user from
     the class itself, which has it stored in base controllers
     """
 
     def __init__(self, *required_perms):
         self.required_perms = set(required_perms)
 
     def __call__(self, func):
         return get_cython_compat_decorator(self.__wrapper, func)
 
     def _get_request(self):
         return get_request(self)
 
     def __wrapper(self, func, *fargs, **fkwargs):
         import rhodecode.lib.helpers as h
         cls = fargs[0]
         _user = cls._rhodecode_user
         request = self._get_request()
         _ = request.translate
 
         log.debug('checking %s permissions %s for %s %s',
                   self.__class__.__name__, self.required_perms, cls, _user)
 
         if self.check_permissions(_user):
             log.debug('Permission granted for %s %s', cls, _user)
             return func(*fargs, **fkwargs)
 
         else:
             log.debug('Permission denied for %s %s', cls, _user)
             anonymous = _user.username == User.DEFAULT_USER
 
             if anonymous:
                 came_from = get_came_from(self._get_request())
                 h.flash(_('You need to be signed in to view this page'),
                         category='warning')
                 raise HTTPFound(
                     h.route_path('login', _query={'came_from': came_from}))
 
             else:
                 # redirect with 404 to prevent resource discovery
                 raise HTTPNotFound()
 
     def check_permissions(self, user):
         """Dummy function for overriding"""
         raise NotImplementedError(
             'You have to write this function in child class')
 
 
 class HasPermissionAllDecorator(PermsDecorator):
     """
     Checks for access permission for all given predicates. All of them
     have to be meet in order to fulfill the request
     """
 
     def check_permissions(self, user):
         perms = user.permissions_with_scope({})
         if self.required_perms.issubset(perms['global']):
             return True
         return False
 
 
 class HasPermissionAnyDecorator(PermsDecorator):
     """
     Checks for access permission for any of given predicates. In order to
     fulfill the request any of predicates must be meet
     """
 
     def check_permissions(self, user):
         perms = user.permissions_with_scope({})
         if self.required_perms.intersection(perms['global']):
             return True
         return False
 
 
 class HasRepoPermissionAllDecorator(PermsDecorator):
     """
     Checks for access permission for all given predicates for specific
     repository. All of them have to be meet in order to fulfill the request
     """
     def _get_repo_name(self):
         _request = self._get_request()
         return get_repo_slug(_request)
 
     def check_permissions(self, user):
         perms = user.permissions
         repo_name = self._get_repo_name()
 
         try:
             user_perms = {perms['repositories'][repo_name]}
         except KeyError:
             log.debug('cannot locate repo with name: `%s` in permissions defs',
                       repo_name)
             return False
 
         log.debug('checking `%s` permissions for repo `%s`',
                   user_perms, repo_name)
         if self.required_perms.issubset(user_perms):
             return True
         return False
 
 
 class HasRepoPermissionAnyDecorator(PermsDecorator):
     """
     Checks for access permission for any of given predicates for specific
     repository. In order to fulfill the request any of predicates must be meet
     """
     def _get_repo_name(self):
         _request = self._get_request()
         return get_repo_slug(_request)
 
     def check_permissions(self, user):
         perms = user.permissions
         repo_name = self._get_repo_name()
 
         try:
             user_perms = {perms['repositories'][repo_name]}
         except KeyError:
             log.debug(
                 'cannot locate repo with name: `%s` in permissions defs',
                 repo_name)
             return False
 
         log.debug('checking `%s` permissions for repo `%s`',
                   user_perms, repo_name)
         if self.required_perms.intersection(user_perms):
             return True
         return False
 
 
 class HasRepoGroupPermissionAllDecorator(PermsDecorator):
     """
     Checks for access permission for all given predicates for specific
     repository group. All of them have to be meet in order to
     fulfill the request
     """
     def _get_repo_group_name(self):
         _request = self._get_request()
         return get_repo_group_slug(_request)
 
     def check_permissions(self, user):
         perms = user.permissions
         group_name = self._get_repo_group_name()
         try:
             user_perms = {perms['repositories_groups'][group_name]}
         except KeyError:
             log.debug(
                 'cannot locate repo group with name: `%s` in permissions defs',
                 group_name)
             return False
 
         log.debug('checking `%s` permissions for repo group `%s`',
                   user_perms, group_name)
         if self.required_perms.issubset(user_perms):
             return True
         return False
 
 
 class HasRepoGroupPermissionAnyDecorator(PermsDecorator):
     """
     Checks for access permission for any of given predicates for specific
     repository group. In order to fulfill the request any
     of predicates must be met
     """
     def _get_repo_group_name(self):
         _request = self._get_request()
         return get_repo_group_slug(_request)
 
     def check_permissions(self, user):
         perms = user.permissions
         group_name = self._get_repo_group_name()
 
         try:
             user_perms = {perms['repositories_groups'][group_name]}
         except KeyError:
             log.debug(
                 'cannot locate repo group with name: `%s` in permissions defs',
                 group_name)
             return False
 
         log.debug('checking `%s` permissions for repo group `%s`',
                   user_perms, group_name)
         if self.required_perms.intersection(user_perms):
             return True
         return False
 
 
 class HasUserGroupPermissionAllDecorator(PermsDecorator):
     """
     Checks for access permission for all given predicates for specific
     user group. All of them have to be meet in order to fulfill the request
     """
     def _get_user_group_name(self):
         _request = self._get_request()
         return get_user_group_slug(_request)
 
     def check_permissions(self, user):
         perms = user.permissions
         group_name = self._get_user_group_name()
         try:
             user_perms = {perms['user_groups'][group_name]}
         except KeyError:
             return False
 
         if self.required_perms.issubset(user_perms):
             return True
         return False
 
 
 class HasUserGroupPermissionAnyDecorator(PermsDecorator):
     """
     Checks for access permission for any of given predicates for specific
     user group. In order to fulfill the request any of predicates must be meet
     """
     def _get_user_group_name(self):
         _request = self._get_request()
         return get_user_group_slug(_request)
 
     def check_permissions(self, user):
         perms = user.permissions
         group_name = self._get_user_group_name()
         try:
             user_perms = {perms['user_groups'][group_name]}
         except KeyError:
             return False
 
         if self.required_perms.intersection(user_perms):
             return True
         return False
 
 
 # CHECK FUNCTIONS
 class PermsFunction(object):
     """Base function for other check functions"""
 
     def __init__(self, *perms):
         self.required_perms = set(perms)
         self.repo_name = None
         self.repo_group_name = None
         self.user_group_name = None
 
     def __bool__(self):
         import inspect
         frame = inspect.currentframe()
         stack_trace = traceback.format_stack(frame)
         log.error('Checking bool value on a class instance of perm '
                   'function is not allowed: %s', ''.join(stack_trace))
         # rather than throwing errors, here we always return False so if by
         # accident someone checks truth for just an instance it will always end
         # up in returning False
         return False
     __nonzero__ = __bool__
 
     def __call__(self, check_location='', user=None):
         if not user:
             log.debug('Using user attribute from global request')
             request = self._get_request()
             user = request.user
 
         # init auth user if not already given
         if not isinstance(user, AuthUser):
             log.debug('Wrapping user %s into AuthUser', user)
             user = AuthUser(user.user_id)
 
         cls_name = self.__class__.__name__
         check_scope = self._get_check_scope(cls_name)
         check_location = check_location or 'unspecified location'
 
         log.debug('checking cls:%s %s usr:%s %s @ %s', cls_name,
                   self.required_perms, user, check_scope, check_location)
         if not user:
             log.warning('Empty user given for permission check')
             return False
 
         if self.check_permissions(user):
             log.debug('Permission to repo:`%s` GRANTED for user:`%s` @ %s',
                       check_scope, user, check_location)
             return True
 
         else:
             log.debug('Permission to repo:`%s` DENIED for user:`%s` @ %s',
                       check_scope, user, check_location)
             return False
 
     def _get_request(self):
         return get_request(self)
 
     def _get_check_scope(self, cls_name):
         return {
             'HasPermissionAll':          'GLOBAL',
             'HasPermissionAny':          'GLOBAL',
             'HasRepoPermissionAll':      'repo:%s' % self.repo_name,
             'HasRepoPermissionAny':      'repo:%s' % self.repo_name,
             'HasRepoGroupPermissionAll': 'repo_group:%s' % self.repo_group_name,
             'HasRepoGroupPermissionAny': 'repo_group:%s' % self.repo_group_name,
             'HasUserGroupPermissionAll': 'user_group:%s' % self.user_group_name,
             'HasUserGroupPermissionAny': 'user_group:%s' % self.user_group_name,
         }.get(cls_name, '?:%s' % cls_name)
 
     def check_permissions(self, user):
         """Dummy function for overriding"""
         raise Exception('You have to write this function in child class')
 
 
 class HasPermissionAll(PermsFunction):
     def check_permissions(self, user):
         perms = user.permissions_with_scope({})
         if self.required_perms.issubset(perms.get('global')):
             return True
         return False
 
 
 class HasPermissionAny(PermsFunction):
     def check_permissions(self, user):
         perms = user.permissions_with_scope({})
         if self.required_perms.intersection(perms.get('global')):
             return True
         return False
 
 
 class HasRepoPermissionAll(PermsFunction):
     def __call__(self, repo_name=None, check_location='', user=None):
         self.repo_name = repo_name
         return super(HasRepoPermissionAll, self).__call__(check_location, user)
 
     def _get_repo_name(self):
         if not self.repo_name:
             _request = self._get_request()
             self.repo_name = get_repo_slug(_request)
         return self.repo_name
 
     def check_permissions(self, user):
         self.repo_name = self._get_repo_name()
         perms = user.permissions
         try:
             user_perms = {perms['repositories'][self.repo_name]}
         except KeyError:
             return False
         if self.required_perms.issubset(user_perms):
             return True
         return False
 
 
 class HasRepoPermissionAny(PermsFunction):
     def __call__(self, repo_name=None, check_location='', user=None):
         self.repo_name = repo_name
         return super(HasRepoPermissionAny, self).__call__(check_location, user)
 
     def _get_repo_name(self):
         if not self.repo_name:
             _request = self._get_request()
             self.repo_name = get_repo_slug(_request)
         return self.repo_name
 
     def check_permissions(self, user):
         self.repo_name = self._get_repo_name()
         perms = user.permissions
         try:
             user_perms = {perms['repositories'][self.repo_name]}
         except KeyError:
             return False
         if self.required_perms.intersection(user_perms):
             return True
         return False
 
 
 class HasRepoGroupPermissionAny(PermsFunction):
     def __call__(self, group_name=None, check_location='', user=None):
         self.repo_group_name = group_name
         return super(HasRepoGroupPermissionAny, self).__call__(check_location, user)
 
     def check_permissions(self, user):
         perms = user.permissions
         try:
             user_perms = {perms['repositories_groups'][self.repo_group_name]}
         except KeyError:
             return False
         if self.required_perms.intersection(user_perms):
             return True
         return False
 
 
 class HasRepoGroupPermissionAll(PermsFunction):
     def __call__(self, group_name=None, check_location='', user=None):
         self.repo_group_name = group_name
         return super(HasRepoGroupPermissionAll, self).__call__(check_location, user)
 
     def check_permissions(self, user):
         perms = user.permissions
         try:
             user_perms = {perms['repositories_groups'][self.repo_group_name]}
         except KeyError:
             return False
         if self.required_perms.issubset(user_perms):
             return True
         return False
 
 
 class HasUserGroupPermissionAny(PermsFunction):
     def __call__(self, user_group_name=None, check_location='', user=None):
         self.user_group_name = user_group_name
         return super(HasUserGroupPermissionAny, self).__call__(check_location, user)
 
     def check_permissions(self, user):
         perms = user.permissions
         try:
             user_perms = {perms['user_groups'][self.user_group_name]}
         except KeyError:
             return False
         if self.required_perms.intersection(user_perms):
             return True
         return False
 
 
 class HasUserGroupPermissionAll(PermsFunction):
     def __call__(self, user_group_name=None, check_location='', user=None):
         self.user_group_name = user_group_name
         return super(HasUserGroupPermissionAll, self).__call__(check_location, user)
 
     def check_permissions(self, user):
         perms = user.permissions
         try:
             user_perms = {perms['user_groups'][self.user_group_name]}
         except KeyError:
             return False
         if self.required_perms.issubset(user_perms):
             return True
         return False
 
 
 # SPECIAL VERSION TO HANDLE MIDDLEWARE AUTH
 class HasPermissionAnyMiddleware(object):
     def __init__(self, *perms):
         self.required_perms = set(perms)
 
     def __call__(self, auth_user, repo_name):
         # repo_name MUST be unicode, since we handle keys in permission
         # dict by unicode
         repo_name = safe_unicode(repo_name)
         log.debug(
             'Checking VCS protocol permissions %s for user:%s repo:`%s`',
             self.required_perms, auth_user, repo_name)
 
         if self.check_permissions(auth_user, repo_name):
             log.debug('Permission to repo:`%s` GRANTED for user:%s @ %s',
                       repo_name, auth_user, 'PermissionMiddleware')
             return True
 
         else:
             log.debug('Permission to repo:`%s` DENIED for user:%s @ %s',
                       repo_name, auth_user, 'PermissionMiddleware')
             return False
 
     def check_permissions(self, user, repo_name):
         perms = user.permissions_with_scope({'repo_name': repo_name})
 
         try:
             user_perms = {perms['repositories'][repo_name]}
         except Exception:
             log.exception('Error while accessing user permissions')
             return False
 
         if self.required_perms.intersection(user_perms):
             return True
         return False
 
 
 # SPECIAL VERSION TO HANDLE API AUTH
 class _BaseApiPerm(object):
     def __init__(self, *perms):
         self.required_perms = set(perms)
 
     def __call__(self, check_location=None, user=None, repo_name=None,
                  group_name=None, user_group_name=None):
         cls_name = self.__class__.__name__
         check_scope = 'global:%s' % (self.required_perms,)
         if repo_name:
             check_scope += ', repo_name:%s' % (repo_name,)
 
         if group_name:
             check_scope += ', repo_group_name:%s' % (group_name,)
 
         if user_group_name:
             check_scope += ', user_group_name:%s' % (user_group_name,)
 
         log.debug('checking cls:%s %s %s @ %s',
                   cls_name, self.required_perms, check_scope, check_location)
         if not user:
             log.debug('Empty User passed into arguments')
             return False
 
         # process user
         if not isinstance(user, AuthUser):
             user = AuthUser(user.user_id)
         if not check_location:
             check_location = 'unspecified'
         if self.check_permissions(user.permissions, repo_name, group_name,
                                   user_group_name):
             log.debug('Permission to repo:`%s` GRANTED for user:`%s` @ %s',
                       check_scope, user, check_location)
             return True
 
         else:
             log.debug('Permission to repo:`%s` DENIED for user:`%s` @ %s',
                       check_scope, user, check_location)
             return False
 
     def check_permissions(self, perm_defs, repo_name=None, group_name=None,
                           user_group_name=None):
         """
         implement in child class should return True if permissions are ok,
         False otherwise
 
         :param perm_defs: dict with permission definitions
         :param repo_name: repo name
         """
         raise NotImplementedError()
 
 
 class HasPermissionAllApi(_BaseApiPerm):
     def check_permissions(self, perm_defs, repo_name=None, group_name=None,
                           user_group_name=None):
         if self.required_perms.issubset(perm_defs.get('global')):
             return True
         return False
 
 
 class HasPermissionAnyApi(_BaseApiPerm):
     def check_permissions(self, perm_defs, repo_name=None, group_name=None,
                           user_group_name=None):
         if self.required_perms.intersection(perm_defs.get('global')):
             return True
         return False
 
 
 class HasRepoPermissionAllApi(_BaseApiPerm):
     def check_permissions(self, perm_defs, repo_name=None, group_name=None,
                           user_group_name=None):
         try:
             _user_perms = {perm_defs['repositories'][repo_name]}
         except KeyError:
             log.warning(traceback.format_exc())
             return False
         if self.required_perms.issubset(_user_perms):
             return True
         return False
 
 
 class HasRepoPermissionAnyApi(_BaseApiPerm):
     def check_permissions(self, perm_defs, repo_name=None, group_name=None,
                           user_group_name=None):
         try:
             _user_perms = {perm_defs['repositories'][repo_name]}
         except KeyError:
             log.warning(traceback.format_exc())
             return False
         if self.required_perms.intersection(_user_perms):
             return True
         return False
 
 
 class HasRepoGroupPermissionAnyApi(_BaseApiPerm):
     def check_permissions(self, perm_defs, repo_name=None, group_name=None,
                           user_group_name=None):
         try:
             _user_perms = {perm_defs['repositories_groups'][group_name]}
         except KeyError:
             log.warning(traceback.format_exc())
             return False
         if self.required_perms.intersection(_user_perms):
             return True
         return False
 
 
 class HasRepoGroupPermissionAllApi(_BaseApiPerm):
     def check_permissions(self, perm_defs, repo_name=None, group_name=None,
                           user_group_name=None):
         try:
             _user_perms = {perm_defs['repositories_groups'][group_name]}
         except KeyError:
             log.warning(traceback.format_exc())
             return False
         if self.required_perms.issubset(_user_perms):
             return True
         return False
 
 
 class HasUserGroupPermissionAnyApi(_BaseApiPerm):
     def check_permissions(self, perm_defs, repo_name=None, group_name=None,
                           user_group_name=None):
         try:
             _user_perms = {perm_defs['user_groups'][user_group_name]}
         except KeyError:
             log.warning(traceback.format_exc())
             return False
         if self.required_perms.intersection(_user_perms):
             return True
         return False
 
 
 def check_ip_access(source_ip, allowed_ips=None):
     """
     Checks if source_ip is a subnet of any of allowed_ips.
 
     :param source_ip:
     :param allowed_ips: list of allowed ips together with mask
     """
     log.debug('checking if ip:%s is subnet of %s', source_ip, allowed_ips)
     source_ip_address = ipaddress.ip_address(safe_unicode(source_ip))
     if isinstance(allowed_ips, (tuple, list, set)):
         for ip in allowed_ips:
             ip = safe_unicode(ip)
             try:
                 network_address = ipaddress.ip_network(ip, strict=False)
                 if source_ip_address in network_address:
                     log.debug('IP %s is network %s', source_ip_address, network_address)
                     return True
                 # for any case we cannot determine the IP, don't crash just
                 # skip it and log as error, we want to say forbidden still when
                 # sending bad IP
             except Exception:
                 log.error(traceback.format_exc())
                 continue
     return False
 
 
 def get_cython_compat_decorator(wrapper, func):
     """
     Creates a cython compatible decorator. The previously used
     decorator.decorator() function seems to be incompatible with cython.
 
     :param wrapper: __wrapper method of the decorator class
     :param func: decorated function
     """
     @wraps(func)
     def local_wrapper(*args, **kwds):
         return wrapper(func, *args, **kwds)
     local_wrapper.__wrapped__ = func
     return local_wrapper
 
 

rhodecode/lib/db_manage.py

@@ -1,680 +1,680 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2010-2020 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/
 
 """
 Database creation, and setup module for RhodeCode Enterprise. Used for creation
 of database as well as for migration operations
 """
 
 import os
 import sys
 import time
 import uuid
 import logging
 import getpass
 from os.path import dirname as dn, join as jn
 
 from sqlalchemy.engine import create_engine
 
 from rhodecode import __dbversion__
 from rhodecode.model import init_model
 from rhodecode.model.user import UserModel
 from rhodecode.model.db import (
     User, Permission, RhodeCodeUi, RhodeCodeSetting, UserToPerm,
     DbMigrateVersion, RepoGroup, UserRepoGroupToPerm, CacheKey, Repository)
 from rhodecode.model.meta import Session, Base
 from rhodecode.model.permission import PermissionModel
 from rhodecode.model.repo import RepoModel
 from rhodecode.model.repo_group import RepoGroupModel
 from rhodecode.model.settings import SettingsModel
 
 
 log = logging.getLogger(__name__)
 
 
 def notify(msg):
     """
     Notification for migrations messages
     """
     ml = len(msg) + (4 * 2)
     print(('\n%s\n*** %s ***\n%s' % ('*' * ml, msg, '*' * ml)).upper())
 
 
 class DbManage(object):
 
     def __init__(self, log_sql, dbconf, root, tests=False,
                  SESSION=None, cli_args=None):
         self.dbname = dbconf.split('/')[-1]
         self.tests = tests
         self.root = root
         self.dburi = dbconf
         self.log_sql = log_sql
         self.cli_args = cli_args or {}
         self.init_db(SESSION=SESSION)
         self.ask_ok = self.get_ask_ok_func(self.cli_args.get('force_ask'))
 
     def db_exists(self):
         if not self.sa:
             self.init_db()
         try:
             self.sa.query(RhodeCodeUi)\
                 .filter(RhodeCodeUi.ui_key == '/')\
                 .scalar()
             return True
         except Exception:
             return False
         finally:
             self.sa.rollback()
 
     def get_ask_ok_func(self, param):
         if param not in [None]:
             # return a function lambda that has a default set to param
             return lambda *args, **kwargs: param
         else:
             from rhodecode.lib.utils import ask_ok
             return ask_ok
 
     def init_db(self, SESSION=None):
         if SESSION:
             self.sa = SESSION
         else:
             # init new sessions
             engine = create_engine(self.dburi, echo=self.log_sql)
             init_model(engine)
             self.sa = Session()
 
     def create_tables(self, override=False):
         """
         Create a auth database
         """
 
         log.info("Existing database with the same name is going to be destroyed.")
         log.info("Setup command will run DROP ALL command on that database.")
         if self.tests:
             destroy = True
         else:
             destroy = self.ask_ok('Are you sure that you want to destroy the old database? [y/n]')
         if not destroy:
-            log.info('Nothing done.')
+            log.info('db tables bootstrap: Nothing done.')
             sys.exit(0)
         if destroy:
             Base.metadata.drop_all()
 
         checkfirst = not override
         Base.metadata.create_all(checkfirst=checkfirst)
         log.info('Created tables for %s', self.dbname)
 
     def set_db_version(self):
         ver = DbMigrateVersion()
         ver.version = __dbversion__
         ver.repository_id = 'rhodecode_db_migrations'
         ver.repository_path = 'versions'
         self.sa.add(ver)
         log.info('db version set to: %s', __dbversion__)
 
     def run_post_migration_tasks(self):
         """
         Run various tasks before actually doing migrations
         """
         # delete cache keys on each upgrade
         total = CacheKey.query().count()
         log.info("Deleting (%s) cache keys now...", total)
         CacheKey.delete_all_cache()
 
     def upgrade(self, version=None):
         """
         Upgrades given database schema to given revision following
         all needed steps, to perform the upgrade
 
         """
 
         from rhodecode.lib.dbmigrate.migrate.versioning import api
         from rhodecode.lib.dbmigrate.migrate.exceptions import \
             DatabaseNotControlledError
 
         if 'sqlite' in self.dburi:
             print(
                '********************** WARNING **********************\n'
                'Make sure your version of sqlite is at least 3.7.X.  \n'
                'Earlier versions are known to fail on some migrations\n'
                '*****************************************************\n')
 
         upgrade = self.ask_ok(
             'You are about to perform a database upgrade. Make '
             'sure you have backed up your database. '
             'Continue ? [y/n]')
         if not upgrade:
             log.info('No upgrade performed')
             sys.exit(0)
 
         repository_path = jn(dn(dn(dn(os.path.realpath(__file__)))),
                              'rhodecode/lib/dbmigrate')
         db_uri = self.dburi
 
         if version:
             DbMigrateVersion.set_version(version)
 
         try:
             curr_version = api.db_version(db_uri, repository_path)
             msg = ('Found current database db_uri under version '
                    'control with version {}'.format(curr_version))
 
         except (RuntimeError, DatabaseNotControlledError):
             curr_version = 1
             msg = ('Current database is not under version control. Setting '
                    'as version %s' % curr_version)
             api.version_control(db_uri, repository_path, curr_version)
 
         notify(msg)
 
 
         if curr_version == __dbversion__:
             log.info('This database is already at the newest version')
             sys.exit(0)
 
         upgrade_steps = range(curr_version + 1, __dbversion__ + 1)
         notify('attempting to upgrade database from '
                'version %s to version %s' % (curr_version, __dbversion__))
 
         # CALL THE PROPER ORDER OF STEPS TO PERFORM FULL UPGRADE
         _step = None
         for step in upgrade_steps:
             notify('performing upgrade step %s' % step)
             time.sleep(0.5)
 
             api.upgrade(db_uri, repository_path, step)
             self.sa.rollback()
             notify('schema upgrade for step %s completed' % (step,))
 
             _step = step
 
         self.run_post_migration_tasks()
         notify('upgrade to version %s successful' % _step)
 
     def fix_repo_paths(self):
         """
         Fixes an old RhodeCode version path into new one without a '*'
         """
 
         paths = self.sa.query(RhodeCodeUi)\
                 .filter(RhodeCodeUi.ui_key == '/')\
                 .scalar()
 
         paths.ui_value = paths.ui_value.replace('*', '')
 
         try:
             self.sa.add(paths)
             self.sa.commit()
         except Exception:
             self.sa.rollback()
             raise
 
     def fix_default_user(self):
         """
         Fixes an old default user with some 'nicer' default values,
         used mostly for anonymous access
         """
         def_user = self.sa.query(User)\
                 .filter(User.username == User.DEFAULT_USER)\
                 .one()
 
         def_user.name = 'Anonymous'
         def_user.lastname = 'User'
         def_user.email = User.DEFAULT_USER_EMAIL
 
         try:
             self.sa.add(def_user)
             self.sa.commit()
         except Exception:
             self.sa.rollback()
             raise
 
     def fix_settings(self):
         """
         Fixes rhodecode settings and adds ga_code key for google analytics
         """
 
         hgsettings3 = RhodeCodeSetting('ga_code', '')
 
         try:
             self.sa.add(hgsettings3)
             self.sa.commit()
         except Exception:
             self.sa.rollback()
             raise
 
     def create_admin_and_prompt(self):
 
         # defaults
         defaults = self.cli_args
         username = defaults.get('username')
         password = defaults.get('password')
         email = defaults.get('email')
 
         if username is None:
             username = raw_input('Specify admin username:')
         if password is None:
             password = self._get_admin_password()
             if not password:
                 # second try
                 password = self._get_admin_password()
                 if not password:
                     sys.exit()
         if email is None:
             email = raw_input('Specify admin email:')
         api_key = self.cli_args.get('api_key')
         self.create_user(username, password, email, True,
                          strict_creation_check=False,
                          api_key=api_key)
 
     def _get_admin_password(self):
         password = getpass.getpass('Specify admin password '
                                    '(min 6 chars):')
         confirm = getpass.getpass('Confirm password:')
 
         if password != confirm:
             log.error('passwords mismatch')
             return False
         if len(password) < 6:
             log.error('password is too short - use at least 6 characters')
             return False
 
         return password
 
     def create_test_admin_and_users(self):
         log.info('creating admin and regular test users')
         from rhodecode.tests import TEST_USER_ADMIN_LOGIN, \
             TEST_USER_ADMIN_PASS, TEST_USER_ADMIN_EMAIL, \
             TEST_USER_REGULAR_LOGIN, TEST_USER_REGULAR_PASS, \
             TEST_USER_REGULAR_EMAIL, TEST_USER_REGULAR2_LOGIN, \
             TEST_USER_REGULAR2_PASS, TEST_USER_REGULAR2_EMAIL
 
         self.create_user(TEST_USER_ADMIN_LOGIN, TEST_USER_ADMIN_PASS,
                          TEST_USER_ADMIN_EMAIL, True, api_key=True)
 
         self.create_user(TEST_USER_REGULAR_LOGIN, TEST_USER_REGULAR_PASS,
                          TEST_USER_REGULAR_EMAIL, False, api_key=True)
 
         self.create_user(TEST_USER_REGULAR2_LOGIN, TEST_USER_REGULAR2_PASS,
                          TEST_USER_REGULAR2_EMAIL, False, api_key=True)
 
     def create_ui_settings(self, repo_store_path):
         """
         Creates ui settings, fills out hooks
         and disables dotencode
         """
         settings_model = SettingsModel(sa=self.sa)
         from rhodecode.lib.vcs.backends.hg import largefiles_store
         from rhodecode.lib.vcs.backends.git import lfs_store
 
         # Build HOOKS
         hooks = [
             (RhodeCodeUi.HOOK_REPO_SIZE, 'python:vcsserver.hooks.repo_size'),
 
             # HG
             (RhodeCodeUi.HOOK_PRE_PULL, 'python:vcsserver.hooks.pre_pull'),
             (RhodeCodeUi.HOOK_PULL, 'python:vcsserver.hooks.log_pull_action'),
             (RhodeCodeUi.HOOK_PRE_PUSH, 'python:vcsserver.hooks.pre_push'),
             (RhodeCodeUi.HOOK_PRETX_PUSH, 'python:vcsserver.hooks.pre_push'),
             (RhodeCodeUi.HOOK_PUSH, 'python:vcsserver.hooks.log_push_action'),
             (RhodeCodeUi.HOOK_PUSH_KEY, 'python:vcsserver.hooks.key_push'),
 
         ]
 
         for key, value in hooks:
             hook_obj = settings_model.get_ui_by_key(key)
             hooks2 = hook_obj if hook_obj else RhodeCodeUi()
             hooks2.ui_section = 'hooks'
             hooks2.ui_key = key
             hooks2.ui_value = value
             self.sa.add(hooks2)
 
         # enable largefiles
         largefiles = RhodeCodeUi()
         largefiles.ui_section = 'extensions'
         largefiles.ui_key = 'largefiles'
         largefiles.ui_value = ''
         self.sa.add(largefiles)
 
         # set default largefiles cache dir, defaults to
         # /repo_store_location/.cache/largefiles
         largefiles = RhodeCodeUi()
         largefiles.ui_section = 'largefiles'
         largefiles.ui_key = 'usercache'
         largefiles.ui_value = largefiles_store(repo_store_path)
 
         self.sa.add(largefiles)
 
         # set default lfs cache dir, defaults to
         # /repo_store_location/.cache/lfs_store
         lfsstore = RhodeCodeUi()
         lfsstore.ui_section = 'vcs_git_lfs'
         lfsstore.ui_key = 'store_location'
         lfsstore.ui_value = lfs_store(repo_store_path)
 
         self.sa.add(lfsstore)
 
         # enable hgsubversion disabled by default
         hgsubversion = RhodeCodeUi()
         hgsubversion.ui_section = 'extensions'
         hgsubversion.ui_key = 'hgsubversion'
         hgsubversion.ui_value = ''
         hgsubversion.ui_active = False
         self.sa.add(hgsubversion)
 
         # enable hgevolve disabled by default
         hgevolve = RhodeCodeUi()
         hgevolve.ui_section = 'extensions'
         hgevolve.ui_key = 'evolve'
         hgevolve.ui_value = ''
         hgevolve.ui_active = False
         self.sa.add(hgevolve)
 
         hgevolve = RhodeCodeUi()
         hgevolve.ui_section = 'experimental'
         hgevolve.ui_key = 'evolution'
         hgevolve.ui_value = ''
         hgevolve.ui_active = False
         self.sa.add(hgevolve)
 
         hgevolve = RhodeCodeUi()
         hgevolve.ui_section = 'experimental'
         hgevolve.ui_key = 'evolution.exchange'
         hgevolve.ui_value = ''
         hgevolve.ui_active = False
         self.sa.add(hgevolve)
 
         hgevolve = RhodeCodeUi()
         hgevolve.ui_section = 'extensions'
         hgevolve.ui_key = 'topic'
         hgevolve.ui_value = ''
         hgevolve.ui_active = False
         self.sa.add(hgevolve)
 
         # enable hggit disabled by default
         hggit = RhodeCodeUi()
         hggit.ui_section = 'extensions'
         hggit.ui_key = 'hggit'
         hggit.ui_value = ''
         hggit.ui_active = False
         self.sa.add(hggit)
 
         # set svn branch defaults
         branches = ["/branches/*", "/trunk"]
         tags = ["/tags/*"]
 
         for branch in branches:
             settings_model.create_ui_section_value(
                 RhodeCodeUi.SVN_BRANCH_ID, branch)
 
         for tag in tags:
             settings_model.create_ui_section_value(RhodeCodeUi.SVN_TAG_ID, tag)
 
     def create_auth_plugin_options(self, skip_existing=False):
         """
         Create default auth plugin settings, and make it active
 
         :param skip_existing:
         """
         defaults = [
             ('auth_plugins',
              'egg:rhodecode-enterprise-ce#token,egg:rhodecode-enterprise-ce#rhodecode',
              'list'),
 
             ('auth_authtoken_enabled',
              'True',
              'bool'),
 
             ('auth_rhodecode_enabled',
              'True',
              'bool'),
         ]
         for k, v, t in defaults:
             if (skip_existing and
                     SettingsModel().get_setting_by_name(k) is not None):
                 log.debug('Skipping option %s', k)
                 continue
             setting = RhodeCodeSetting(k, v, t)
             self.sa.add(setting)
 
     def create_default_options(self, skip_existing=False):
         """Creates default settings"""
 
         for k, v, t in [
             ('default_repo_enable_locking',  False, 'bool'),
             ('default_repo_enable_downloads', False, 'bool'),
             ('default_repo_enable_statistics', False, 'bool'),
             ('default_repo_private', False, 'bool'),
             ('default_repo_type', 'hg', 'unicode')]:
 
             if (skip_existing and
                     SettingsModel().get_setting_by_name(k) is not None):
                 log.debug('Skipping option %s', k)
                 continue
             setting = RhodeCodeSetting(k, v, t)
             self.sa.add(setting)
 
     def fixup_groups(self):
         def_usr = User.get_default_user()
         for g in RepoGroup.query().all():
             g.group_name = g.get_new_name(g.name)
             self.sa.add(g)
             # get default perm
             default = UserRepoGroupToPerm.query()\
                 .filter(UserRepoGroupToPerm.group == g)\
                 .filter(UserRepoGroupToPerm.user == def_usr)\
                 .scalar()
 
             if default is None:
                 log.debug('missing default permission for group %s adding', g)
                 perm_obj = RepoGroupModel()._create_default_perms(g)
                 self.sa.add(perm_obj)
 
     def reset_permissions(self, username):
         """
         Resets permissions to default state, useful when old systems had
         bad permissions, we must clean them up
 
         :param username:
         """
         default_user = User.get_by_username(username)
         if not default_user:
             return
 
         u2p = UserToPerm.query()\
             .filter(UserToPerm.user == default_user).all()
         fixed = False
         if len(u2p) != len(Permission.DEFAULT_USER_PERMISSIONS):
             for p in u2p:
                 Session().delete(p)
             fixed = True
             self.populate_default_permissions()
         return fixed
 
     def config_prompt(self, test_repo_path='', retries=3):
         defaults = self.cli_args
         _path = defaults.get('repos_location')
         if retries == 3:
             log.info('Setting up repositories config')
 
         if _path is not None:
             path = _path
         elif not self.tests and not test_repo_path:
             path = raw_input(
                  'Enter a valid absolute path to store repositories. '
                  'All repositories in that path will be added automatically:'
             )
         else:
             path = test_repo_path
         path_ok = True
 
         # check proper dir
         if not os.path.isdir(path):
             path_ok = False
             log.error('Given path %s is not a valid directory', path)
 
         elif not os.path.isabs(path):
             path_ok = False
             log.error('Given path %s is not an absolute path', path)
 
         # check if path is at least readable.
         if not os.access(path, os.R_OK):
             path_ok = False
             log.error('Given path %s is not readable', path)
 
         # check write access, warn user about non writeable paths
         elif not os.access(path, os.W_OK) and path_ok:
             log.warning('No write permission to given path %s', path)
 
             q = ('Given path %s is not writeable, do you want to '
                  'continue with read only mode ? [y/n]' % (path,))
             if not self.ask_ok(q):
                 log.error('Canceled by user')
                 sys.exit(-1)
 
         if retries == 0:
             sys.exit('max retries reached')
         if not path_ok:
             retries -= 1
             return self.config_prompt(test_repo_path, retries)
 
         real_path = os.path.normpath(os.path.realpath(path))
 
         if real_path != os.path.normpath(path):
             q = ('Path looks like a symlink, RhodeCode Enterprise will store '
                  'given path as %s ? [y/n]') % (real_path,)
             if not self.ask_ok(q):
                 log.error('Canceled by user')
                 sys.exit(-1)
 
         return real_path
 
     def create_settings(self, path):
 
         self.create_ui_settings(path)
 
         ui_config = [
             ('web', 'push_ssl', 'False'),
             ('web', 'allow_archive', 'gz zip bz2'),
             ('web', 'allow_push', '*'),
             ('web', 'baseurl', '/'),
             ('paths', '/', path),
             ('phases', 'publish', 'True')
         ]
         for section, key, value in ui_config:
             ui_conf = RhodeCodeUi()
             setattr(ui_conf, 'ui_section', section)
             setattr(ui_conf, 'ui_key', key)
             setattr(ui_conf, 'ui_value', value)
             self.sa.add(ui_conf)
 
         # rhodecode app settings
         settings = [
             ('realm', 'RhodeCode', 'unicode'),
             ('title', '', 'unicode'),
             ('pre_code', '', 'unicode'),
             ('post_code', '', 'unicode'),
 
             # Visual
             ('show_public_icon', True, 'bool'),
             ('show_private_icon', True, 'bool'),
             ('stylify_metatags', True, 'bool'),
             ('dashboard_items', 100, 'int'),
             ('admin_grid_items', 25, 'int'),
 
             ('markup_renderer', 'markdown', 'unicode'),
 
             ('repository_fields', True, 'bool'),
             ('show_version', True, 'bool'),
             ('show_revision_number', True, 'bool'),
             ('show_sha_length', 12, 'int'),
 
             ('use_gravatar', False, 'bool'),
             ('gravatar_url', User.DEFAULT_GRAVATAR_URL, 'unicode'),
 
             ('clone_uri_tmpl', Repository.DEFAULT_CLONE_URI, 'unicode'),
             ('clone_uri_id_tmpl', Repository.DEFAULT_CLONE_URI_ID, 'unicode'),
             ('clone_uri_ssh_tmpl', Repository.DEFAULT_CLONE_URI_SSH, 'unicode'),
             ('support_url', '', 'unicode'),
             ('update_url', RhodeCodeSetting.DEFAULT_UPDATE_URL, 'unicode'),
 
             # VCS Settings
             ('pr_merge_enabled', True, 'bool'),
             ('use_outdated_comments', True, 'bool'),
             ('diff_cache', True, 'bool'),
         ]
 
         for key, val, type_ in settings:
             sett = RhodeCodeSetting(key, val, type_)
             self.sa.add(sett)
 
         self.create_auth_plugin_options()
         self.create_default_options()
 
         log.info('created ui config')
 
     def create_user(self, username, password, email='', admin=False,
                     strict_creation_check=True, api_key=None):
         log.info('creating user `%s`', username)
         user = UserModel().create_or_update(
             username, password, email, firstname=u'RhodeCode', lastname=u'Admin',
             active=True, admin=admin, extern_type="rhodecode",
             strict_creation_check=strict_creation_check)
 
         if api_key:
             log.info('setting a new default auth token for user `%s`', username)
             UserModel().add_auth_token(
                 user=user, lifetime_minutes=-1,
                 role=UserModel.auth_token_role.ROLE_ALL,
                 description=u'BUILTIN TOKEN')
 
     def create_default_user(self):
         log.info('creating default user')
         # create default user for handling default permissions.
         user = UserModel().create_or_update(username=User.DEFAULT_USER,
                                             password=str(uuid.uuid1())[:20],
                                             email=User.DEFAULT_USER_EMAIL,
                                             firstname=u'Anonymous',
                                             lastname=u'User',
                                             strict_creation_check=False)
         # based on configuration options activate/de-activate this user which
         # controlls anonymous access
         if self.cli_args.get('public_access') is False:
             log.info('Public access disabled')
             user.active = False
             Session().add(user)
             Session().commit()
 
     def create_permissions(self):
         """
         Creates all permissions defined in the system
         """
         # module.(access|create|change|delete)_[name]
         # module.(none|read|write|admin)
         log.info('creating permissions')
         PermissionModel(self.sa).create_permissions()
 
     def populate_default_permissions(self):
         """
         Populate default permissions. It will create only the default
         permissions that are missing, and not alter already defined ones
         """
         log.info('creating default user permissions')
         PermissionModel(self.sa).create_default_user_permissions(user=User.DEFAULT_USER)

rhodecode/lib/middleware/request_wrapper.py

@@ -1,90 +1,93 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2016-2020 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_access_path, get_user_agent
 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')
         response = None
         try:
             response = self.handler(request)
         finally:
             count = request.request_count()
             _ver_ = rhodecode.__version__
             _path = safe_str(get_access_path(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"
 
             total = time.time() - start
             log.info(
                 '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_
+                _path, total, get_user_agent(request. environ), _ver_,
+                extra={"time": total, "ver": _ver_, "ip": ip,
+                       "path": _path, "view_name": match_route}
             )
 
             statsd = request.registry.statsd
             if statsd:
-                match_route = request.matched_route.name if request.matched_route else "NOT_FOUND"
                 resp_code = getattr(response, 'status_code', 'UNDEFINED')
                 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',
     )

rhodecode/lib/rc_cache/utils.py

@@ -1,422 +1,422 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2015-2020 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 os
 import time
 import logging
 import functools
 import threading
 
 from dogpile.cache import CacheRegion
 from dogpile.cache.util import compat
 
 import rhodecode
 from rhodecode.lib.utils import safe_str, sha1
 from rhodecode.lib.utils2 import safe_unicode, str2bool
 from rhodecode.model.db import Session, CacheKey, IntegrityError
 
 from rhodecode.lib.rc_cache import cache_key_meta
 from rhodecode.lib.rc_cache import region_meta
 
 log = logging.getLogger(__name__)
 
 
 def isCython(func):
     """
     Private helper that checks if a function is a cython function.
     """
     return func.__class__.__name__ == 'cython_function_or_method'
 
 
 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 rhodecode.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
 
 
 class ActiveRegionCache(object):
     def __init__(self, context, cache_data):
         self.context = context
         self.cache_data = cache_data
 
     def should_invalidate(self):
         return False
 
 
 class FreshRegionCache(object):
     def __init__(self, context, cache_data):
         self.context = context
         self.cache_data = cache_data
 
     def should_invalidate(self):
         return True
 
 
 class InvalidationContext(object):
     """
     usage::
 
         from rhodecode.lib import rc_cache
 
         cache_namespace_uid = CacheKey.SOME_NAMESPACE.format(1)
         region = rc_cache.get_or_create_region('cache_perms', cache_namespace_uid)
 
         @region.conditional_cache_on_arguments(namespace=cache_namespace_uid, condition=True)
         def heavy_compute(cache_name, param1, param2):
             print('COMPUTE {}, {}, {}'.format(cache_name, param1, param2))
 
         # invalidation namespace is shared namespace key for all process caches
         # we use it to send a global signal
         invalidation_namespace = 'repo_cache:1'
 
         inv_context_manager = rc_cache.InvalidationContext(
             uid=cache_namespace_uid, invalidation_namespace=invalidation_namespace)
         with inv_context_manager as invalidation_context:
             args = ('one', 'two')
             # re-compute and store cache if we get invalidate signal
             if invalidation_context.should_invalidate():
                 result = heavy_compute.refresh(*args)
             else:
                 result = heavy_compute(*args)
 
             compute_time = inv_context_manager.compute_time
             log.debug('result computed in %.4fs', compute_time)
 
         # To send global invalidation signal, simply run
         CacheKey.set_invalidate(invalidation_namespace)
 
     """
 
     def __repr__(self):
         return '<InvalidationContext:{}[{}]>'.format(
             safe_str(self.cache_key), safe_str(self.uid))
 
     def __init__(self, uid, invalidation_namespace='',
                  raise_exception=False, thread_scoped=None):
         self.uid = uid
         self.invalidation_namespace = invalidation_namespace
         self.raise_exception = raise_exception
         self.proc_id = safe_unicode(rhodecode.CONFIG.get('instance_id') or 'DEFAULT')
         self.thread_id = 'global'
 
         if thread_scoped is None:
             # if we set "default" we can override this via .ini settings
             thread_scoped = str2bool(rhodecode.CONFIG.get('cache_thread_scoped'))
 
         # Append the thread id to the cache key if this invalidation context
         # should be scoped to the current thread.
         if thread_scoped is True:
             self.thread_id = threading.current_thread().ident
 
         self.cache_key = compute_key_from_params(uid)
         self.cache_key = 'proc:{}|thread:{}|params:{}'.format(
             self.proc_id, self.thread_id, self.cache_key)
         self.compute_time = 0
 
     def get_or_create_cache_obj(self, cache_type, invalidation_namespace=''):
         invalidation_namespace = invalidation_namespace or self.invalidation_namespace
         # fetch all cache keys for this namespace and convert them to a map to find if we
         # have specific cache_key object registered. We do this because we want to have
         # all consistent cache_state_uid for newly registered objects
         cache_obj_map = CacheKey.get_namespace_map(invalidation_namespace)
         cache_obj = cache_obj_map.get(self.cache_key)
         log.debug('Fetched cache obj %s using %s cache key.', cache_obj, self.cache_key)
         if not cache_obj:
             new_cache_args = invalidation_namespace
             first_cache_obj = next(cache_obj_map.itervalues()) if cache_obj_map else None
             cache_state_uid = None
             if first_cache_obj:
                 cache_state_uid = first_cache_obj.cache_state_uid
             cache_obj = CacheKey(self.cache_key, cache_args=new_cache_args,
                                  cache_state_uid=cache_state_uid)
             cache_key_meta.cache_keys_by_pid.append(self.cache_key)
 
         return cache_obj
 
     def __enter__(self):
         """
         Test if current object is valid, and return CacheRegion function
         that does invalidation and calculation
         """
         log.debug('Entering cache invalidation check context: %s', self.invalidation_namespace)
         # register or get a new key based on uid
         self.cache_obj = self.get_or_create_cache_obj(cache_type=self.uid)
         cache_data = self.cache_obj.get_dict()
         self._start_time = time.time()
         if self.cache_obj.cache_active:
             # means our cache obj is existing and marked as it's
             # cache is not outdated, we return ActiveRegionCache
             self.skip_cache_active_change = True
 
             return ActiveRegionCache(context=self, cache_data=cache_data)
 
         # the key is either not existing or set to False, we return
         # the real invalidator which re-computes value. We additionally set
         # the flag to actually update the Database objects
         self.skip_cache_active_change = False
         return FreshRegionCache(context=self, cache_data=cache_data)
 
     def __exit__(self, exc_type, exc_val, exc_tb):
         # save compute time
         self.compute_time = time.time() - self._start_time
 
         if self.skip_cache_active_change:
             return
 
         try:
             self.cache_obj.cache_active = True
             Session().add(self.cache_obj)
             Session().commit()
         except IntegrityError:
             # if we catch integrity error, it means we inserted this object
             # assumption is that's really an edge race-condition case and
             # it's safe is to skip it
             Session().rollback()
         except Exception:
             log.exception('Failed to commit on cache key update')
             Session().rollback()
             if self.raise_exception:
                 raise