diff --git a/rhodecode/authentication/base.py b/rhodecode/authentication/base.py --- a/rhodecode/authentication/base.py +++ b/rhodecode/authentication/base.py @@ -776,7 +776,8 @@ def authenticate(username, password, env 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) @@ -785,7 +786,12 @@ def authenticate(username, password, env 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 diff --git a/rhodecode/authentication/plugins/auth_headers.py b/rhodecode/authentication/plugins/auth_headers.py --- a/rhodecode/authentication/plugins/auth_headers.py +++ b/rhodecode/authentication/plugins/auth_headers.py @@ -222,7 +222,8 @@ class RhodeCodeAuthPlugin(RhodeCodeExter '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 diff --git a/rhodecode/authentication/plugins/auth_ldap.py b/rhodecode/authentication/plugins/auth_ldap.py --- a/rhodecode/authentication/plugins/auth_ldap.py +++ b/rhodecode/authentication/plugins/auth_ldap.py @@ -534,7 +534,8 @@ class RhodeCodeAuthPlugin(RhodeCodeExter } 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 diff --git a/rhodecode/authentication/plugins/auth_pam.py b/rhodecode/authentication/plugins/auth_pam.py --- a/rhodecode/authentication/plugins/auth_pam.py +++ b/rhodecode/authentication/plugins/auth_pam.py @@ -162,7 +162,8 @@ class RhodeCodeAuthPlugin(RhodeCodeExter 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 diff --git a/rhodecode/authentication/plugins/auth_rhodecode.py b/rhodecode/authentication/plugins/auth_rhodecode.py --- a/rhodecode/authentication/plugins/auth_rhodecode.py +++ b/rhodecode/authentication/plugins/auth_rhodecode.py @@ -167,11 +167,13 @@ class RhodeCodeAuthPlugin(RhodeCodeAuthP 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) diff --git a/rhodecode/lib/_vendor/redis_lock/__init__.py b/rhodecode/lib/_vendor/redis_lock/__init__.py --- a/rhodecode/lib/_vendor/redis_lock/__init__.py +++ b/rhodecode/lib/_vendor/redis_lock/__init__.py @@ -252,7 +252,7 @@ class Lock(object): 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 diff --git a/rhodecode/lib/audit_logger.py b/rhodecode/lib/audit_logger.py --- a/rhodecode/lib/audit_logger.py +++ b/rhodecode/lib/audit_logger.py @@ -284,7 +284,9 @@ def store(action, user, action_data=None 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') diff --git a/rhodecode/lib/auth.py b/rhodecode/lib/auth.py --- a/rhodecode/lib/auth.py +++ b/rhodecode/lib/auth.py @@ -1490,7 +1490,8 @@ class AuthUser(object): 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): diff --git a/rhodecode/lib/db_manage.py b/rhodecode/lib/db_manage.py --- a/rhodecode/lib/db_manage.py +++ b/rhodecode/lib/db_manage.py @@ -112,7 +112,7 @@ class DbManage(object): 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() diff --git a/rhodecode/lib/middleware/request_wrapper.py b/rhodecode/lib/middleware/request_wrapper.py --- a/rhodecode/lib/middleware/request_wrapper.py +++ b/rhodecode/lib/middleware/request_wrapper.py @@ -54,17 +54,20 @@ class RequestWrapperTween(object): _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( diff --git a/rhodecode/lib/rc_cache/utils.py b/rhodecode/lib/rc_cache/utils.py --- a/rhodecode/lib/rc_cache/utils.py +++ b/rhodecode/lib/rc_cache/utils.py @@ -121,11 +121,11 @@ class RhodeCodeCacheRegion(CacheRegion): 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) @@ -133,7 +133,7 @@ class RhodeCodeCacheRegion(CacheRegion): 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):