logging: use lazy parameter evaluation in log calls.

rhodecode/api/__init__.py

@@ -204,7 +204,7
                 message='Request from IP:%s not allowed' % (
                     request.rpc_ip_addr,))
         else:
-            log.info('Access for IP:%s allowed' % (request.rpc_ip_addr,))
+            log.info('Access for IP:%s allowed', request.rpc_ip_addr)
 
         # register our auth-user
         request.rpc_user = auth_u
@@ -352,8 +352,7
         request.rpc_params = json_body['args'] \
             if isinstance(json_body['args'], dict) else {}
 
-        log.debug(
-            'method: %s, params: %s' % (request.rpc_method, request.rpc_params))
+        log.debug('method: %s, params: %s', request.rpc_method, request.rpc_params)
     except KeyError as e:
         raise JSONRPCError('Incorrect JSON data. Missing %s' % e)
 

rhodecode/apps/gist/views.py

@@ -405,8 +405,8
         revision = self.request.GET.get('revision')
 
         if revision != last_rev.raw_id:
-            log.error('Last revision %s is different then submitted %s'
-                      % (revision, last_rev))
+            log.error('Last revision %s is different then submitted %s',
+                      revision, last_rev)
             # our gist has newer version than we
             success = False
 

rhodecode/apps/login/views.py

@@ -93,16 +93,16
     allowed_schemes = ['http', 'https']
     default_came_from = h.route_path('home')
     if parsed.scheme and parsed.scheme not in allowed_schemes:
-        log.error('Suspicious URL scheme detected %s for url %s' %
-                  (parsed.scheme, parsed))
+        log.error('Suspicious URL scheme detected %s for url %s',
+                  parsed.scheme, parsed)
         came_from = default_came_from
     elif parsed.netloc and request.host != parsed.netloc:
         log.error('Suspicious NETLOC detected %s for url %s server url '
-                  'is: %s' % (parsed.netloc, parsed, request.host))
+                  'is: %s', parsed.netloc, parsed, request.host)
         came_from = default_came_from
     elif any(bad_str in parsed.path for bad_str in ('\r', '\n')):
-        log.error('Header injection detected `%s` for url %s server url ' %
-                  (parsed.path, parsed))
+        log.error('Header injection detected `%s` for url %s server url ',
+                  parsed.path, parsed)
         came_from = default_came_from
 
     return came_from or default_came_from

rhodecode/apps/repository/views/repo_compare.py

@@ -256,8 +256,8
             # case we want a simple diff without incoming commits,
             # previewing what will be merged.
             # Make the diff on target repo (which is known to have target_ref)
-            log.debug('Using ancestor %s as source_ref instead of %s'
-                      % (c.ancestor, source_ref))
+            log.debug('Using ancestor %s as source_ref instead of %s',
+                      c.ancestor, source_ref)
             source_repo = target_repo
             source_commit = target_repo.get_commit(commit_id=c.ancestor)
 

rhodecode/apps/repository/views/repo_strip.py

@@ -98,8 +98,8
                 ScmModel().strip(
                     repo=self.db_repo,
                     commit_id=commit['rev'], branch=commit['branch'])
-                log.info('Stripped commit %s from repo `%s` by %s' % (
-                    commit['rev'], self.db_repo_name, user))
+                log.info('Stripped commit %s from repo `%s` by %s',
+                         commit['rev'], self.db_repo_name, user)
                 data[commit['rev']] = True
 
                 audit_logger.store_web(
@@ -108,6 +108,6
 
             except Exception as e:
                 data[commit['rev']] = False
-                log.debug('Stripped commit %s from repo `%s` failed by %s, exeption %s' % (
-                    commit['rev'], self.db_repo_name, user, e.message))
+                log.debug('Stripped commit %s from repo `%s` failed by %s, exeption %s',
+                          commit['rev'], self.db_repo_name, user, e.message)
         return data

rhodecode/authentication/plugins/auth_crowd.py

@@ -241,16 +241,16
             log.debug('Empty username or password skipping...')
             return None
 
-        log.debug("Crowd settings: \n%s" % (formatted_json(settings)))
+        log.debug("Crowd settings: \n%s", formatted_json(settings))
         server = CrowdServer(**settings)
         server.set_credentials(settings["app_name"], settings["app_password"])
         crowd_user = server.user_auth(username, password)
-        log.debug("Crowd returned: \n%s" % (formatted_json(crowd_user)))
+        log.debug("Crowd returned: \n%s", formatted_json(crowd_user))
         if not crowd_user["status"]:
             return None
 
         res = server.user_groups(crowd_user["name"])
-        log.debug("Crowd groups: \n%s" % (formatted_json(res)))
+        log.debug("Crowd groups: \n%s", formatted_json(res))
         crowd_user["groups"] = [x["name"] for x in res["groups"]]
 
         # old attrs fetched from RhodeCode database
@@ -280,6 +280,6
         for group in settings["admin_groups"]:
             if group in user_attrs["groups"]:
                 user_attrs["admin"] = True
-        log.debug("Final crowd user object: \n%s" % (formatted_json(user_attrs)))
-        log.info('user `%s` authenticated correctly' % user_attrs['username'])
+        log.debug("Final crowd user object: \n%s", formatted_json(user_attrs))
+        log.info('user `%s` authenticated correctly', user_attrs['username'])
         return user_attrs

rhodecode/authentication/plugins/auth_headers.py

@@ -125,24 +125,24
         username = None
         environ = environ or {}
         if not environ:
-            log.debug('got empty environ: %s' % 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))
+            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))
+            log.debug('extracted %s:%s', header, username)
 
         if username and str2bool(settings.get('clean_username')):
-            log.debug('Received username `%s` from headers' % username)
+            log.debug('Received username `%s` from headers', username)
             username = self._clean_username(username)
-            log.debug('New cleanup user is:%s' % username)
+            log.debug('New cleanup user is:%s', username)
         return username
 
     def get_user(self, username=None, **kwargs):
@@ -221,5 +221,5
             'extern_type': extern_type,
         }
 
-        log.info('user `%s` authenticated correctly' % user_attrs['username'])
+        log.info('user `%s` authenticated correctly', user_attrs['username'])
         return user_attrs

rhodecode/authentication/plugins/auth_jasig_cas.py

@@ -134,10 +134,10
         try:
             response = urllib2.urlopen(request)
         except urllib2.HTTPError as e:
-            log.debug("HTTPError when requesting Jasig CAS (status code: %d)" % e.code)
+            log.debug("HTTPError when requesting Jasig CAS (status code: %d)", e.code)
             return None
         except urllib2.URLError as e:
-            log.debug("URLError when requesting Jasig CAS url: %s " % url)
+            log.debug("URLError when requesting Jasig CAS url: %s ", url)
             return None
 
         # old attrs fetched from RhodeCode database
@@ -163,5 +163,5
             'extern_type': extern_type,
         }
 
-        log.info('user `%s` authenticated correctly' % user_attrs['username'])
+        log.info('user `%s` authenticated correctly', user_attrs['username'])
         return user_attrs

rhodecode/authentication/plugins/auth_pam.py

@@ -115,10 +115,10
         auth_result = _pam.authenticate(username, password, settings["service"])
 
         if not auth_result:
-            log.error("PAM was unable to authenticate user: %s" % (username, ))
+            log.error("PAM was unable to authenticate user: %s", username)
             return None
 
-        log.debug('Got PAM response %s' % (auth_result, ))
+        log.debug('Got PAM response %s', auth_result)
 
         # old attrs fetched from RhodeCode database
         default_email = "%s@%s" % (username, socket.gethostname())
@@ -157,5 +157,5
             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'])
         return user_attrs

rhodecode/authentication/plugins/auth_rhodecode.py

@@ -87,12 +87,12
 
     def auth(self, userobj, username, password, settings, **kwargs):
         if not userobj:
-            log.debug('userobj was:%s skipping' % (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))
+                "userobj:%s extern_type mismatch got:`%s` expected:`%s`",
+                userobj, userobj.extern_type, self.name)
             return None
 
         user_attrs = {
@@ -109,7 +109,7
             "extern_type": userobj.extern_type,
         }
 
-        log.debug("User attributes:%s" % (user_attrs, ))
+        log.debug("User attributes:%s", user_attrs)
         if userobj.active:
             from rhodecode.lib import auth
             crypto_backend = auth.crypto_backend()

rhodecode/authentication/plugins/auth_token.py

@@ -103,7 +103,7
 
     def auth(self, userobj, username, password, settings, **kwargs):
         if not userobj:
-            log.debug('userobj was:%s skipping' % (userobj, ))
+            log.debug('userobj was:%s skipping', userobj)
             return None
 
         user_attrs = {

rhodecode/events/repo.py

@@ -133,7 +133,7
     missing_commits = set(commit_ids) - set(c['raw_id'] for c in commits)
     if missing_commits:
         log.error('Inconsistent repository state. '
-                  'Missing commits: %s' % ', '.join(missing_commits))
+                  'Missing commits: %s', ', '.join(missing_commits))
 
     return commits
 

rhodecode/integrations/__init__.py

@@ -66,8 +66,8
             exc_info = sys.exc_info()
             store_exception(id(exc_info), exc_info)
             log.exception(
-                'failure occurred when sending event %s to integration %s' % (
-                    event, integration))
+                'failure occurred when sending event %s to integration %s',
+                event, integration)
 
 
 def includeme(config):

rhodecode/integrations/registry.py

@@ -31,8 +31,7
         key = IntegrationType.key
         if key in self:
             log.debug(
-                'Overriding existing integration type %s (%s) with %s' % (
-                    self[key], key, IntegrationType))
+                'Overriding existing integration type %s (%s) with %s',
+                self[key], key, IntegrationType)
 
         self[key] = IntegrationType
-

rhodecode/integrations/types/hipchat.py

@@ -119,11 +119,11
 
     def send_event(self, event):
         if event.__class__ not in self.valid_events:
-            log.debug('event not valid: %r' % event)
+            log.debug('event not valid: %r', event)
             return
 
         if event.name not in self.settings['events']:
-            log.debug('event ignored: %r' % event)
+            log.debug('event ignored: %r', event)
             return
 
         data = event.as_dict()
@@ -131,7 +131,7
         text = '<b>%s<b> caused a <b>%s</b> event' % (
             data['actor']['username'], event.name)
 
-        log.debug('handling hipchat event for %s' % event.name)
+        log.debug('handling hipchat event for %s', event.name)
 
         if isinstance(event, events.PullRequestCommentEvent):
             text = self.format_pull_request_comment_event(event, data)
@@ -144,7 +144,7
         elif isinstance(event, events.RepoCreateEvent):
             text = self.format_repo_create_event(data)
         else:
-            log.error('unhandled event type: %r' % event)
+            log.error('unhandled event type: %r', event)
 
         run_task(post_text_to_hipchat, self.settings, text)
 
@@ -242,7 +242,7
 
 @async_task(ignore_result=True, base=RequestContextTask)
 def post_text_to_hipchat(settings, text):
-    log.debug('sending %s to hipchat %s' % (text, settings['server_url']))
+    log.debug('sending %s to hipchat %s', text, settings['server_url'])
     json_message = {
         "message": text,
         "color": settings.get('color', 'yellow'),

rhodecode/integrations/types/slack.py

@@ -110,11 +110,11
 
     def send_event(self, event):
         if event.__class__ not in self.valid_events:
-            log.debug('event not valid: %r' % event)
+            log.debug('event not valid: %r', event)
             return
 
         if event.name not in self.settings['events']:
-            log.debug('event ignored: %r' % event)
+            log.debug('event ignored: %r', event)
             return
 
         data = event.as_dict()
@@ -127,7 +127,7
         fields = None
         overrides = None
 
-        log.debug('handling slack event for %s' % event.name)
+        log.debug('handling slack event for %s', event.name)
 
         if isinstance(event, events.PullRequestCommentEvent):
             (title, text, fields, overrides) \
@@ -141,7 +141,7
         elif isinstance(event, events.RepoCreateEvent):
             title, text = self.format_repo_create_event(data)
         else:
-            log.error('unhandled event type: %r' % event)
+            log.error('unhandled event type: %r', event)
 
         run_task(post_text_to_slack, self.settings, title, text, fields, overrides)
 
@@ -314,8 +314,7
 
 @async_task(ignore_result=True, base=RequestContextTask)
 def post_text_to_slack(settings, title, text, fields=None, overrides=None):
-    log.debug('sending %s (%s) to slack %s' % (
-        title, text, settings['service']))
+    log.debug('sending %s (%s) to slack %s', title, text, settings['service'])
 
     fields = fields or []
     overrides = overrides or {}

rhodecode/integrations/types/webhook.py

@@ -171,11 +171,11
             'handling event %s with Webhook integration %s', event.name, self)
 
         if event.__class__ not in self.valid_events:
-            log.debug('event not valid: %r' % event)
+            log.debug('event not valid: %r', event)
             return
 
         if event.name not in self.settings['events']:
-            log.debug('event ignored: %r' % event)
+            log.debug('event ignored: %r', event)
             return
 
         data = event.as_dict()

rhodecode/lib/auth.py

@@ -979,7 +979,7
     }
 
     log.debug(
-        'Allowed views for AUTH TOKEN access: %s' % (whitelist,))
+        'Allowed views for AUTH TOKEN access: %s', whitelist)
     auth_token_access_valid = False
 
     for entry in whitelist:
@@ -998,8 +998,9
             break
 
     if auth_token_access_valid:
-        log.debug('view: `%s` matches entry in whitelist: %s'
-                  % (view_name, whitelist))
+        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))
@@ -1190,7 +1191,7
 
         log.debug(
             'Computing PERMISSION tree for user %s scope `%s` '
-            'with caching: %s[TTL: %ss]' % (user, scope, cache_on, cache_seconds or 0))
+            '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)
@@ -1214,8 +1215,8
         for k in result:
             result_repr.append((k, len(result[k])))
         total = time.time() - start
-        log.debug('PERMISSION tree for user %s computed in %.3fs: %s' % (
-            user, total, result_repr))
+        log.debug('PERMISSION tree for user %s computed in %.3fs: %s',
+                  user, total, result_repr)
 
         return result
 
@@ -1352,12 +1353,12
         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))
+            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)
             return False
 
     def get_branch_permissions(self, repo_name, perms=None):
@@ -1593,7 +1594,7
         _ = request.translate
 
         loc = "%s:%s" % (cls.__class__.__name__, func.__name__)
-        log.debug('Starting login restriction checks for user: %s' % (user,))
+        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:
@@ -1610,7 +1611,7
 
         # explicit controller is enabled or API is in our whitelist
         if self.auth_token_access or auth_token_access_valid:
-            log.debug('Checking AUTH TOKEN access for %s' % (cls,))
+            log.debug('Checking AUTH TOKEN access for %s', cls)
             db_user = user.get_instance()
 
             if db_user:
@@ -1626,36 +1627,33
 
             if _auth_token and token_match:
                 auth_token_access_valid = True
-                log.debug('AUTH TOKEN ****%s is VALID' % (_auth_token[-4:],))
+                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))
+                    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))
+            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))
+                '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,))
+            log.debug('redirecting to login page with %s', came_from)
             raise HTTPFound(
                 h.route_path('login', _query={'came_from': came_from}))
 
@@ -1678,7 +1676,7
         self.user = cls._rhodecode_user
         request = self._get_request()
         _ = request.translate
-        log.debug('Checking if user is not anonymous @%s' % cls)
+        log.debug('Checking if user is not anonymous @%s', cls)
 
         anonymous = self.user.username == User.DEFAULT_USER
 
@@ -1939,7 +1937,7
         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))
+                  '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
@@ -2182,9 +2180,8
         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))
+        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
@@ -2305,7 +2302,7
     :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))
+    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:
@@ -2313,8 +2310,7
             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))
+                    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

rhodecode/lib/base.py

@@ -216,7 +216,7
         try:
             return get_exception(safe_int(http_code))
         except Exception:
-            log.exception('Failed to fetch response for code %s' % http_code)
+            log.exception('Failed to fetch response for code %s', http_code)
             return HTTPForbidden
 
     def get_rc_realm(self):

rhodecode/lib/codeblocks.py

@@ -442,7 +442,7
         return self._lexer_cache[filename]
 
     def render_patch(self, patch):
-        log.debug('rendering diff for %r' % patch['filename'])
+        log.debug('rendering diff for %r', patch['filename'])
 
         source_filename = patch['original_filename']
         target_filename = patch['filename']

rhodecode/lib/db_manage.py

@@ -107,7 +107,7
 
         checkfirst = not override
         Base.metadata.create_all(checkfirst=checkfirst)
-        log.info('Created tables for %s' % self.dbname)
+        log.info('Created tables for %s', self.dbname)
 
     def set_db_version(self):
         ver = DbMigrateVersion()
@@ -115,7 +115,7
         ver.repository_id = 'rhodecode_db_migrations'
         ver.repository_path = 'versions'
         self.sa.add(ver)
-        log.info('db version set to: %s' % __dbversion__)
+        log.info('db version set to: %s', __dbversion__)
 
     def run_pre_migration_tasks(self):
         """
@@ -402,7 +402,7
                         ('auth_rhodecode_enabled', 'True', 'bool')]:
             if (skip_existing and
                     SettingsModel().get_setting_by_name(k) is not None):
-                log.debug('Skipping option %s' % k)
+                log.debug('Skipping option %s', k)
                 continue
             setting = RhodeCodeSetting(k, v, t)
             self.sa.add(setting)
@@ -419,7 +419,7
 
             if (skip_existing and
                     SettingsModel().get_setting_by_name(k) is not None):
-                log.debug('Skipping option %s' % k)
+                log.debug('Skipping option %s', k)
                 continue