engineering/unrhodecode
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

logging: expose extra metadata to various important logs for loki

Browse source
This commit is contained in:
RhodeCode Admin 2022-10-27 22:49:17 +02:00
parent d04fb901d3
commit faa449987b
11 changed files with 32 additions and 15 deletions
Download patch file Download diff file Expand all files Collapse all files

8
rhodecode/authentication/base.py
View file

@ -776,7 +776,8 @@ def authenticate(username, password, environ=None, auth_type=None,
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, environ=None, auth_type=None,
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

3
rhodecode/authentication/plugins/auth_headers.py
View file

@ -222,7 +222,8 @@ class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
'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

3
rhodecode/authentication/plugins/auth_ldap.py
View file

@ -534,7 +534,8 @@ class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
}
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

3
rhodecode/authentication/plugins/auth_pam.py
View file

@ -162,7 +162,8 @@ class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
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

6
rhodecode/authentication/plugins/auth_rhodecode.py
View file

@ -167,11 +167,13 @@ class RhodeCodeAuthPlugin(RhodeCodeAuthPluginBase):
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)

2
rhodecode/lib/_vendor/redis_lock/__init__.py
View file

@ -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

4
rhodecode/lib/audit_logger.py
View file

@ -284,7 +284,9 @@ def store(action, user, action_data=None, user_data=None, ip_addr=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')

3
rhodecode/lib/auth.py
View file

@ -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):

2
rhodecode/lib/db_manage.py
View file

@ -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()

7
rhodecode/lib/middleware/request_wrapper.py
View file

@ -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(

6
rhodecode/lib/rc_cache/utils.py
View file

@ -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):