logging: use lazy parameter evaluation in log calls.

This commit is contained in:
Marcin Kuzminski 2018-09-13 17:41:35 +02:00
parent b8b33988bd
commit 9033601562
57 changed files with 173 additions and 188 deletions

View file

@ -204,7 +204,7 @@ def request_view(request):
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 @@ def setup_request(request):
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)

View file

@ -405,8 +405,8 @@ class GistView(BaseAppView):
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

View file

@ -93,16 +93,16 @@ def get_came_from(request):
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

View file

@ -256,8 +256,8 @@ class RepoCompareView(RepoAppView):
# 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)

View file

@ -98,8 +98,8 @@ class StripView(RepoAppView):
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 @@ class StripView(RepoAppView):
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

View file

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

View file

@ -125,24 +125,24 @@ class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
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 @@ 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'])
return user_attrs

View file

@ -134,10 +134,10 @@ class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
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 @@ 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'])
return user_attrs

View file

@ -115,10 +115,10 @@ class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
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 @@ 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'])
return user_attrs

View file

@ -87,12 +87,12 @@ class RhodeCodeAuthPlugin(RhodeCodeAuthPluginBase):
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 @@ class RhodeCodeAuthPlugin(RhodeCodeAuthPluginBase):
"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()

View file

@ -103,7 +103,7 @@ class RhodeCodeAuthPlugin(RhodeCodeAuthPluginBase):
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 = {

View file

@ -133,7 +133,7 @@ def _commits_as_dict(event, commit_ids, repos):
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

View file

@ -66,8 +66,8 @@ def integrations_event_handler(event):
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):

View file

@ -31,8 +31,7 @@ class IntegrationTypeRegistry(collections.OrderedDict):
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

View file

@ -119,11 +119,11 @@ class HipchatIntegrationType(IntegrationTypeBase, CommitParsingDataHandler):
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 @@ class HipchatIntegrationType(IntegrationTypeBase, CommitParsingDataHandler):
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 @@ class HipchatIntegrationType(IntegrationTypeBase, CommitParsingDataHandler):
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 @@ class HipchatIntegrationType(IntegrationTypeBase, CommitParsingDataHandler):
@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'),

View file

@ -110,11 +110,11 @@ class SlackIntegrationType(IntegrationTypeBase, CommitParsingDataHandler):
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 @@ class SlackIntegrationType(IntegrationTypeBase, CommitParsingDataHandler):
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 @@ class SlackIntegrationType(IntegrationTypeBase, CommitParsingDataHandler):
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 @@ def html_to_slack_links(message):
@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 {}

View file

@ -171,11 +171,11 @@ class WebhookIntegrationType(IntegrationTypeBase):
'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()

View file

@ -979,7 +979,7 @@ def allowed_auth_token_access(view_name, auth_token, whitelist=None):
}
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 @@ def allowed_auth_token_access(view_name, auth_token, whitelist=None):
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 @@ class AuthUser(object):
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 @@ class AuthUser(object):
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 @@ class AuthUser(object):
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 @@ class LoginRequired(object):
_ = 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 @@ class LoginRequired(object):
# 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 @@ class LoginRequired(object):
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.warning("AUTH TOKEN ****%s *NOT* valid", _auth_token[-4:])
log.debug('Checking if %s is authenticated @ %s' % (user.username, loc))
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 @@ class NotAnonymous(object):
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 @@ class PermsFunction(object):
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 @@ class _BaseApiPerm(object):
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 @@ def check_ip_access(source_ip, allowed_ips=None):
: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 @@ def check_ip_access(source_ip, allowed_ips=None):
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

View file

@ -216,7 +216,7 @@ class BasicAuth(AuthBasicAuthenticator):
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):

View file

@ -442,7 +442,7 @@ class DiffSet(object):
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']

View file

@ -107,7 +107,7 @@ class DbManage(object):
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 @@ class DbManage(object):
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 @@ class DbManage(object):
('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 @@ class DbManage(object):
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)
@ -436,7 +436,7 @@ class DbManage(object):
.scalar()
if default is None:
log.debug('missing default permission for group %s adding' % g)
log.debug('missing default permission for group %s adding', g)
perm_obj = RepoGroupModel()._create_default_perms(g)
self.sa.add(perm_obj)
@ -484,20 +484,20 @@ class DbManage(object):
# check proper dir
if not os.path.isdir(path):
path_ok = False
log.error('Given path %s is not a valid directory' % (path,))
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,))
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,))
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,))
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,))
@ -573,7 +573,7 @@ class DbManage(object):
def create_user(self, username, password, email='', admin=False,
strict_creation_check=True, api_key=None):
log.info('creating user `%s`' % username)
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",

View file

@ -25,13 +25,13 @@ def usage():
def delete_file(filepath):
"""Deletes a file and prints a message."""
log.info('Deleting file: %s' % filepath)
log.info('Deleting file: %s', filepath)
os.remove(filepath)
def move_file(src, tgt):
"""Moves a file and prints a message."""
log.info('Moving file %s to %s' % (src, tgt))
log.info('Moving file %s to %s', src, tgt)
if os.path.exists(tgt):
raise Exception(
'Cannot move file %s because target %s already exists' % \
@ -41,13 +41,13 @@ def move_file(src, tgt):
def delete_directory(dirpath):
"""Delete a directory and print a message."""
log.info('Deleting directory: %s' % dirpath)
log.info('Deleting directory: %s', dirpath)
os.rmdir(dirpath)
def migrate_repository(repos):
"""Does the actual migration to the new repository format."""
log.info('Migrating repository at: %s to new format' % repos)
log.info('Migrating repository at: %s to new format', repos)
versions = '%s/versions' % repos
dirs = os.listdir(versions)
# Only use int's in list.
@ -55,7 +55,7 @@ def migrate_repository(repos):
numdirs.sort() # Sort list.
for dirname in numdirs:
origdir = '%s/%s' % (versions, dirname)
log.info('Working on directory: %s' % origdir)
log.info('Working on directory: %s', origdir)
files = os.listdir(origdir)
files.sort()
for filename in files:

View file

@ -35,7 +35,7 @@ class Pathed(KeyedInstance):
"""Try to initialize this object's parent, if it has one"""
parent_path = self.__class__._parent_path(path)
self.parent = self.__class__.parent(parent_path)
log.debug("Getting parent %r:%r" % (self.__class__.parent, parent_path))
log.debug("Getting parent %r:%r", self.__class__.parent, parent_path)
self.parent._init_child(path, self)
def _init_child(self, child, path):

View file

@ -73,14 +73,14 @@ class Repository(pathed.Pathed):
_versions = 'versions'
def __init__(self, path):
log.debug('Loading repository %s...' % path)
log.debug('Loading repository %s...', path)
self.verify(path)
super(Repository, self).__init__(path)
self.config = cfgparse.Config(os.path.join(self.path, self._config))
self.versions = version.Collection(os.path.join(self.path,
self._versions))
log.debug('Repository %s loaded successfully' % path)
log.debug('Config: %r' % self.config.to_dict())
log.debug('Repository %s loaded successfully', path)
log.debug('Config: %r', self.config.to_dict())
@classmethod
def verify(cls, path):

View file

@ -24,10 +24,10 @@ class BaseScript(pathed.Pathed):
""" # TODO: sphinxfy this and implement it correctly
def __init__(self, path):
log.debug('Loading script %s...' % path)
log.debug('Loading script %s...', path)
self.verify(path)
super(BaseScript, self).__init__(path)
log.debug('Script %s loaded successfully' % path)
log.debug('Script %s loaded successfully', path)
@classmethod
def verify(cls, path):

View file

@ -311,7 +311,7 @@ class User(Base, BaseModel):
self.last_login = datetime.datetime.now()
Session.add(self)
Session.commit()
log.debug('updated user %s lastlogin' % self.username)
log.debug('updated user %s lastlogin', self.username)
@classmethod
def create(cls, form_data):
@ -656,7 +656,7 @@ class Repository(Base, BaseModel):
try:
alias = get_scm(repo_full_path)[0]
log.debug('Creating instance of %s repository' % alias)
log.debug('Creating instance of %s repository', alias)
backend = get_backend(alias)
except VCSError:
log.error(traceback.format_exc())
@ -731,7 +731,7 @@ class Group(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error('group nested more than %s' %
log.error('group nested more than %s',
parents_recursion_limit)
break
@ -1006,7 +1006,7 @@ class CacheInvalidation(Base, BaseModel):
:param key:
"""
log.debug('marking %s for invalidation' % key)
log.debug('marking %s for invalidation', key)
inv_obj = Session.query(cls)\
.filter(cls.cache_key == key).scalar()
if inv_obj:

View file

@ -379,7 +379,7 @@ class User(Base, BaseModel):
"""Update user lastlogin"""
self.last_login = datetime.datetime.now()
Session.add(self)
log.debug('updated user %s lastlogin' % self.username)
log.debug('updated user %s lastlogin', self.username)
def __json__(self):
return dict(
@ -676,7 +676,7 @@ class Repository(Base, BaseModel):
repo_full_path = self.repo_full_path
try:
alias = get_scm(repo_full_path)[0]
log.debug('Creating instance of %s repository' % alias)
log.debug('Creating instance of %s repository', alias)
backend = get_backend(alias)
except VCSError:
log.error(traceback.format_exc())
@ -760,8 +760,7 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error('group nested more than %s' %
parents_recursion_limit)
log.error('group nested more than %s', parents_recursion_limit)
break
groups.insert(0, gr)
@ -1095,8 +1094,7 @@ class CacheInvalidation(Base, BaseModel):
key, _prefix, _org_key = cls._get_key(key)
inv_objs = Session.query(cls).filter(cls.cache_args == _org_key).all()
log.debug('marking %s key[s] %s for invalidation' % (len(inv_objs),
_org_key))
log.debug('marking %s key[s] %s for invalidation', len(inv_objs), _org_key)
try:
for inv_obj in inv_objs:
if inv_obj:

View file

@ -614,15 +614,13 @@ class Repository(Base, BaseModel):
if (cs_cache != self.changeset_cache or not self.changeset_cache):
_default = datetime.datetime.fromtimestamp(0)
last_change = cs_cache.get('date') or _default
log.debug('updated repo %s with new cs cache %s'
% (self.repo_name, cs_cache))
log.debug('updated repo %s with new cs cache %s', self.repo_name, cs_cache)
self.updated_on = last_change
self.changeset_cache = cs_cache
Session().add(self)
Session().commit()
else:
log.debug('Skipping repo:%s already with latest changes'
% self.repo_name)
log.debug('Skipping repo:%s already with latest changes', self.repo_name)
class RepoGroup(Base, BaseModel):
__tablename__ = 'groups'

View file

@ -2415,8 +2415,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -2481,8 +2481,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -2108,8 +2108,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -2100,8 +2100,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -2100,8 +2100,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -2104,8 +2104,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -2104,8 +2104,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -2154,8 +2154,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -2155,8 +2155,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -2352,8 +2352,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -74,7 +74,7 @@ class User(Base):
self.last_login = datetime.datetime.now()
session.add(self)
session.commit()
log.debug('updated user %s lastlogin' % self.username)
log.debug('updated user %s lastlogin', self.username)
except (DatabaseError,):
session.rollback()

View file

@ -102,7 +102,7 @@ def fixups(models, _SESSION):
perms = models.UserToPerm.query().filter(models.UserToPerm.user == user).all()
defined_perms_groups = map(
_get_group, (x.permission.permission_name for x in perms))
log.debug('GOT ALREADY DEFINED:%s' % perms)
log.debug('GOT ALREADY DEFINED:%s', perms)
DEFAULT_PERMS = models.Permission.DEFAULT_USER_PERMISSIONS
# for every default permission that needs to be created, we check if
@ -110,8 +110,7 @@ def fixups(models, _SESSION):
for perm_name in DEFAULT_PERMS:
gr = _get_group(perm_name)
if gr not in defined_perms_groups:
log.debug('GR:%s not found, creating permission %s'
% (gr, perm_name))
log.debug('GR:%s not found, creating permission %s', gr, perm_name)
new_perm = _make_perm(perm_name)
_SESSION().add(new_perm)
_SESSION().commit()
@ -127,7 +126,7 @@ def fixups(models, _SESSION):
('default_repo_type', 'hg')]:
if skip_existing and get_by_name(models.RhodeCodeSetting, k) is not None:
log.debug('Skipping option %s' % k)
log.debug('Skipping option %s', k)
continue
setting = models.RhodeCodeSetting(k, v)
_SESSION().add(setting)

View file

@ -99,7 +99,7 @@ def fixups(models, _SESSION):
perms = models.UserToPerm.query().filter(models.UserToPerm.user == user).all()
defined_perms_groups = map(_get_group,
(x.permission.permission_name for x in perms))
log.debug('GOT ALREADY DEFINED:%s' % perms)
log.debug('GOT ALREADY DEFINED:%s', perms)
DEFAULT_PERMS = models.Permission.DEFAULT_USER_PERMISSIONS
# for every default permission that needs to be created, we check if
@ -107,8 +107,7 @@ def fixups(models, _SESSION):
for perm_name in DEFAULT_PERMS:
gr = _get_group(perm_name)
if gr not in defined_perms_groups:
log.debug('GR:%s not found, creating permission %s'
% (gr, perm_name))
log.debug('GR:%s not found, creating permission %s', gr, perm_name)
new_perm = _make_perm(perm_name)
_SESSION().add(new_perm)
_SESSION().commit()

View file

@ -446,7 +446,7 @@ class DiffProcessor(object):
for chunk in self._diff.chunks():
head = chunk.header
log.debug('parsing diff %r' % head)
log.debug('parsing diff %r', head)
raw_diff = chunk.raw
limited_diff = False

View file

@ -1712,14 +1712,14 @@ def process_patterns(text_string, repo_name, link_format='html',
newtext = text_string
for uid, entry in active_entries.items():
log.debug('found issue tracker entry with uid %s' % (uid,))
log.debug('found issue tracker entry with uid %s', uid)
if not (entry['pat'] and entry['url']):
log.debug('skipping due to missing data')
continue
log.debug('issue tracker entry: uid: `%s` PAT:%s URL:%s PREFIX:%s'
% (uid, entry['pat'], entry['url'], entry['pref']))
log.debug('issue tracker entry: uid: `%s` PAT:%s URL:%s PREFIX:%s',
uid, entry['pat'], entry['url'], entry['pref'])
try:
pattern = re.compile(r'%s' % entry['pat'])
@ -1741,7 +1741,7 @@ def process_patterns(text_string, repo_name, link_format='html',
link_format=link_format)
newtext = pattern.sub(url_func, newtext)
log.debug('processed prefix:uid `%s`' % (uid,))
log.debug('processed prefix:uid `%s`', uid)
return newtext, issues_data

View file

@ -122,7 +122,7 @@ class Search(BaseSearch):
search_user, repo_name)
try:
query = qp.parse(safe_unicode(query))
log.debug('query: %s (%s)' % (query, repr(query)))
log.debug('query: %s (%s)', query, repr(query))
reverse, sortedby = False, None
if search_type == 'message':
@ -217,8 +217,8 @@ class Search(BaseSearch):
'path': self.file_schema
}.get(cur_type, self.file_schema)
log.debug('IDX: %s' % index_name)
log.debug('SCHEMA: %s' % schema_defn)
log.debug('IDX: %s', index_name)
log.debug('SCHEMA: %s', schema_defn)
return search_type, index_name, schema_defn
def _init_searcher(self, index_name):

View file

@ -67,7 +67,7 @@ class LRUDictDebug(LRUDict):
fmt = '\n'
for cnt, elem in enumerate(self.keys()):
fmt += '%s - %s\n' % (cnt+1, safe_str(elem))
log.debug('current LRU keys (%s):%s' % (elems_cnt, fmt))
log.debug('current LRU keys (%s):%s', elems_cnt, fmt)
def __getitem__(self, key):
self._report_keys()

View file

@ -44,10 +44,11 @@ class RequestWrapperTween(object):
finally:
end = time.time()
total = end - start
log.info('IP: %s Request to %s time: %.3fs [%s]' % (
log.info(
'IP: %s Request to %s time: %.3fs [%s]',
get_ip_addr(request.environ),
safe_str(get_access_path(request.environ)), total,
get_user_agent(request. environ),)
get_user_agent(request. environ)
)
return response

View file

@ -237,7 +237,7 @@ class InvalidationContext(object):
result = heavy_compute(*args)
compute_time = inv_context_manager.compute_time
log.debug('result computed in %.3fs' ,compute_time)
log.debug('result computed in %.3fs', compute_time)
# To send global invalidation signal, simply run
CacheKey.set_invalidate(invalidation_namespace)

View file

@ -111,7 +111,7 @@ class SmtpMailer(object):
smtp_serv.login(self.user, self.passwd)
smtp_serv.sendmail(msg.sender, msg.send_to, raw_msg.as_string())
log.info('email sent to: %s' % recipients)
log.info('email sent to: %s', recipients)
try:
smtp_serv.quit()

View file

@ -49,13 +49,13 @@ def user_log_filter(user_log, search_term):
:param user_log:
:param search_term:
"""
log.debug('Initial search term: %r' % search_term)
log.debug('Initial search term: %r', search_term)
qry = None
if search_term:
qp = QueryParser('repository', schema=JOURNAL_SCHEMA)
qp.add_plugin(DateParserPlugin())
qry = qp.parse(safe_unicode(search_term))
log.debug('Filtering using parsed query %r' % qry)
log.debug('Filtering using parsed query %r', qry)
def wildcard_handler(col, wc_term):
if wc_term.startswith('*') and not wc_term.endswith('*'):
@ -80,7 +80,7 @@ def user_log_filter(user_log, search_term):
field = getattr(UserLog, 'username')
else:
field = getattr(UserLog, field)
log.debug('filter field: %s val=>%s' % (field, val))
log.debug('filter field: %s val=>%s', field, val)
# sql filtering
if isinstance(term, query.Wildcard):

View file

@ -291,8 +291,7 @@ def is_valid_repo_group(repo_group_name, base_path, skip_path_check=False):
# check if it's not a repo
if is_valid_repo(repo_group_name, base_path):
log.debug('Repo called %s exist, it is not a valid '
'repo group' % repo_group_name)
log.debug('Repo called %s exist, it is not a valid repo group', repo_group_name)
return False
try:
@ -300,8 +299,7 @@ def is_valid_repo_group(repo_group_name, base_path, skip_path_check=False):
# since we might match branches/hooks/info/objects or possible
# other things inside bare git repo
scm_ = get_scm(os.path.dirname(full_path))
log.debug('path: %s is a vcs object:%s, not valid '
'repo group' % (full_path, scm_))
log.debug('path: %s is a vcs object:%s, not valid repo group', full_path, scm_)
return False
except VCSError:
pass
@ -774,5 +772,5 @@ def generate_platform_uuid():
uuid_list = [platform.platform()]
return hashlib.sha256(':'.join(uuid_list)).hexdigest()
except Exception as e:
log.error('Failed to generate host uuid: %s' % e)
log.error('Failed to generate host uuid: %s', e)
return 'UNDEFINED'

View file

@ -2539,8 +2539,8 @@ class RepoGroup(Base, BaseModel):
break
if cnt == parents_recursion_limit:
# this will prevent accidental infinit loops
log.error(('more than %s parents found for group %s, stopping '
'recursive parent fetching' % (parents_recursion_limit, self)))
log.error('more than %s parents found for group %s, stopping '
'recursive parent fetching', parents_recursion_limit, self)
break
groups.insert(0, gr)

View file

@ -241,9 +241,8 @@ class SettingsModel(BaseModel):
region.invalidate()
result = _get_all_settings('rhodecode_settings', key)
log.debug(
'Fetching app settings for key: %s took: %.3fs', key,
inv_context_manager.compute_time)
log.debug('Fetching app settings for key: %s took: %.3fs', key,
inv_context_manager.compute_time)
return result

View file

@ -300,11 +300,11 @@ class UserModel(BaseModel):
if updating_user_id:
log.debug('Checking for existing account in RhodeCode '
'database with user_id `%s` ' % (updating_user_id,))
'database with user_id `%s` ', updating_user_id)
user = User.get(updating_user_id)
else:
log.debug('Checking for existing account in RhodeCode '
'database with username `%s` ' % (username,))
'database with username `%s` ', username)
user = User.get_by_username(username, case_insensitive=True)
if user is None:

View file

@ -626,7 +626,7 @@ class UserGroupModel(BaseModel):
self.remove_user_from_group(gr, user)
else:
log.debug('Skipping removal from group %s since it is '
'not set to be automatically synchronized' % gr)
'not set to be automatically synchronized', gr)
# now we calculate in which groups user should be == groups params
owner = User.get_first_super_admin().username
@ -647,7 +647,7 @@ class UserGroupModel(BaseModel):
UserGroupModel().add_user_to_group(existing_group, user)
else:
log.debug('Skipping addition to group %s since it is '
'not set to be automatically synchronized' % gr)
'not set to be automatically synchronized', gr)
def change_groups(self, user, groups):
"""

View file

@ -99,8 +99,8 @@ class RhodeCodeAuthPlugin(RhodeCodeExternalAuthPlugin):
'extern_type': extern_type,
}
log.debug('EXTERNAL user: \n%s' % formatted_json(user_attrs))
log.info('user `%s` authenticated correctly' % user_attrs['username'])
log.debug('EXTERNAL user: \n%s', formatted_json(user_attrs))
log.info('user `%s` authenticated correctly', user_attrs['username'])
return user_attrs

View file

@ -61,7 +61,7 @@ class Command(object):
"""
command = cmd + ' ' + ' '.join(args)
log.debug('Executing %s' % command)
log.debug('Executing %s', command)
if DEBUG:
print(command)
p = Popen(command, shell=True, stdout=PIPE, stderr=PIPE, cwd=self.cwd)

View file

@ -57,7 +57,7 @@ class Command(object):
command = cmd + ' ' + ' '.join(args)
if DEBUG:
log.debug('*** CMD %s ***' % (command,))
log.debug('*** CMD %s ***', command)
env = dict(os.environ)
# Delete coverage variables, as they make the test fail for Mercurial
@ -69,8 +69,8 @@ class Command(object):
cwd=self.cwd, env=env)
stdout, stderr = self.process.communicate()
if DEBUG:
log.debug('STDOUT:%s' % (stdout,))
log.debug('STDERR:%s' % (stderr,))
log.debug('STDOUT:%s', stdout)
log.debug('STDERR:%s', stderr)
return stdout, stderr
def assert_returncode_success(self):