logging: expose extra metadata to various important logs for loki

rhodecode/authentication/base.py

@@ -776,7 +776,8 b' 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 b' 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

rhodecode/authentication/plugins/auth_headers.py

@@ -222,7 +222,8 b' 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
 
 

rhodecode/authentication/plugins/auth_ldap.py

@@ -534,7 +534,8 b' 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
 

rhodecode/authentication/plugins/auth_pam.py

@@ -162,7 +162,8 b' 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
 
 

rhodecode/authentication/plugins/auth_rhodecode.py

@@ -167,11 +167,13 b' 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)

rhodecode/lib/_vendor/redis_lock/__init__.py

@@ -252,7 +252,7 b' 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

rhodecode/lib/audit_logger.py

@@ -284,7 +284,9 b' 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')

rhodecode/lib/auth.py

@@ -1490,7 +1490,8 b' 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):

rhodecode/lib/db_manage.py

@@ -112,7 +112,7 b' 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()

rhodecode/lib/middleware/request_wrapper.py

@@ -54,17 +54,20 b' 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(

rhodecode/lib/rc_cache/utils.py

@@ -121,11 +121,11 b' 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 b' 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):